Pourquoi deux appels consécutifs à la même méthode donnent-ils des temps d'exécution différents?

https://stackoverflow.com/questions/804620

03-07-2019
|

Question

Voici un exemple de code:

public class TestIO{
public static void main(String[] str){
    TestIO t = new TestIO();
    t.fOne();
    t.fTwo();
    t.fOne();
    t.fTwo();
}


public void fOne(){
    long t1, t2;
    t1 = System.nanoTime();
    int i = 10;
    int j = 10;
    int k = j*i;
    System.out.println(k);
    t2 = System.nanoTime();
    System.out.println("Time taken by 'fOne' ... " + (t2-t1));
}

public void fTwo(){
    long t1, t2;
    t1 = System.nanoTime();
    int i = 10;
    int j = 10;
    int k = j*i;
    System.out.println(k);
    t2 = System.nanoTime();
    System.out.println("Time taken by 'fTwo' ... " + (t2-t1));
}

}

Ceci donne la sortie suivante: 100 Temps pris par 'fOne' ... 390273 100 Temps pris par 'deux' ... 118451 100 Temps pris par 'fOne' ... 53359 100 Temps pris par 'deux' ... 115936 Appuyez sur n'importe quelle touche pour continuer . . .

Pourquoi faut-il plus de temps (beaucoup plus) pour exécuter la même méthode pour la première fois que les appels consécutifs?

J'ai essayé de donner -XX: CompileThreshold = 1000000 à la ligne de commande, mais il n'y avait pas de différence.

La solution

Il y a plusieurs raisons. Le compilateur JIT (Just In Time) n'a peut-être pas été exécuté. La machine virtuelle Java peut effectuer des optimisations différentes selon les invocations. Vous mesurez le temps écoulé, alors peut-être que quelque chose d'autre que Java est en cours d'exécution sur votre machine. Les caches de processeur et de RAM sont probablement "chauds". lors des invocations suivantes.

Vous devez vraiment effectuer plusieurs invocations (par milliers) pour obtenir un temps d'exécution précis par méthode.

Autres conseils

Les problèmes mentionnés par Andreas et l'imprévisibilité de JIT sont bien vraisemblables, mais le chargeur de classe reste un autre problème:

Le premier appel à fOne diffère radicalement de ces derniers, car c’est ce qui rend le premier appel à System.out.println , ce qui signifie que Le chargeur de classes utilisera, depuis le cache du disque ou du système de fichiers (généralement mis en cache), toutes les classes nécessaires pour imprimer le texte. Donnez le paramètre -verbose: class à la machine virtuelle Java pour voir le nombre de classes réellement chargées au cours de ce petit programme.

J'ai remarqué un comportement similaire lors de l'exécution de tests unitaires - le premier test pour appeler un grand framework prend beaucoup plus de temps (dans le cas de Guice, environ 250 ms sur un C2Q6600), même si le code de test serait identique, car le premier L'invocation se produit lorsque des centaines de classes sont chargées par le chargeur de classes.

Étant donné que votre exemple de programme est très court, la surcharge provient probablement des très premières optimisations JIT et de l'activité de chargement de classe. Le ramasse-miettes ne démarrera probablement pas avant la fin du programme.

Mise à jour:

Maintenant, j'ai trouvé un moyen fiable de savoir ce qui prend réellement le temps . Personne ne l'avait encore découvert, bien que cela soit étroitement lié au chargement de classe: il s'agissait d'un lien dynamique entre les méthodes natives !

.
J'ai modifié le code comme suit, afin que les journaux indiquent le début et la fin des tests (en recherchant le moment où ces classes de marqueurs vides sont chargées).

TestIO t = new TestIO(); new TestMarker1(); t.fOne(); t.fTwo(); t.fOne(); t.fTwo(); new TestMarker2();

Commande permettant d'exécuter le programme, avec le droit Paramètres JVM qui montrent ce qui se passe réellement:

java -verbose:class -verbose:jni -verbose:gc -XX:+PrintCompilation TestIO

Et la sortie:

* snip 493 lines * [Loaded java.security.Principal from shared objects file] [Loaded java.security.cert.Certificate from shared objects file] [Dynamic-linking native method java.lang.ClassLoader.defineClass1 ... JNI] [Loaded TestIO from file:/D:/DEVEL/Test/classes/] 3 java.lang.String::indexOf (166 bytes) [Loaded TestMarker1 from file:/D:/DEVEL/Test/classes/] [Dynamic-linking native method java.io.FileOutputStream.writeBytes ... JNI] 100 Time taken by 'fOne' ... 155354 100 Time taken by 'fTwo' ... 23684 100 Time taken by 'fOne' ... 22672 100 Time taken by 'fTwo' ... 23954 [Loaded TestMarker2 from file:/D:/DEVEL/Test/classes/] [Loaded java.util.AbstractList$Itr from shared objects file] [Loaded java.util.IdentityHashMap$KeySet from shared objects file] * snip 7 lines *

Et la raison de cette différence de temps est la suivante: [Méthode native de liaison dynamique java.io.FileOutputStream.writeBytes ... JNI]

Nous pouvons également constater que le compilateur JIT n’affecte pas ce point de repère. Seules trois méthodes sont compilées (telles que java.lang.String :: indexOf dans l'extrait de code ci-dessus) et elles se produisent toutes avant l'appel de la méthode fOne .

Le code testé est assez trivial. l'action la plus chère prise est

System.out.println(k);

vous mesurez donc à quelle vitesse la sortie de débogage est écrite. Cela varie énormément et peut même dépendre de la position de la fenêtre de débogage à l’écran, s’il faut faire défiler sa taille, etc.

JIT / Hotspot optimise de manière incrémentielle les chemins de code fréquemment utilisés.

Le processeur optimise les chemins de code attendus. Les chemins utilisés plus souvent s'exécutent plus rapidement.

La taille de votre échantillon est trop petite. Ces micro-repères effectuent généralement une phase d’échauffement. Vous pouvez voir à quel point cela devrait être fait, comme Java est vraiment vite à ne rien faire .

En plus du JIT, d'autres facteurs pourraient être:

Blocage du flux de sortie du processus lorsque vous appelez System.out.println

Votre processus est planifié par un autre processus

Le ramasse-miettes effectuant des travaux sur un thread d'arrière-plan

Si vous souhaitez obtenir de bons points de repère, vous devez

Exécutez le code que vous comparez un grand nombre de fois, plusieurs milliers au moins, et calculez le temps moyen.

Ignorer les heures des premiers appels (à cause de JIT, etc.)

Désactivez le GC si vous le pouvez. cela peut ne pas être une option si votre code génère beaucoup d'objets.

Supprimez la journalisation (appels println) du code à analyser.

Il existe des bibliothèques d'analyse comparative sur plusieurs plates-formes qui vous aideront à faire ce travail. ils peuvent également calculer les écarts-types et d’autres statistiques.

Le coupable le plus probable est le JIT (juste-à-temps) moteur de hotspot. Fondamentalement, lorsque le premier code temporel est exécuté, le code machine est "mémorisé". par la JVM, puis réutilisé lors de futures exécutions.

Je pense que c'est parce que la deuxième fois que le code généré était déjà optimisé, après la première utilisation.

Comme cela a été suggéré, JIT pourrait être le coupable, tout comme le temps d’attente des entrées / sorties et des ressources si d’autres processus de la machine utilisaient des ressources à ce moment-là.

La morale de cette histoire est que le micromarquage est un problème difficile, en particulier pour Java. Je ne sais pas pourquoi vous faites cela, mais si vous essayez de choisir entre deux approches pour un problème, ne les mesurez pas de cette façon. Utilisez le modèle de conception de stratégie et exécutez l'ensemble de votre programme avec les deux approches différentes et mesurez l'ensemble du système. Cela alourdit légèrement le temps de traitement à long terme et vous donne une idée beaucoup plus réaliste de la goulotte d'étranglement des performances de l'ensemble de votre application (indice: c'est probablement moins que vous ne le pensez.)

La réponse la plus probable est l'initialisation. JIT n'est certainement pas la bonne réponse car il faut beaucoup plus de cycles avant de commencer à optimiser. Mais à la toute première fois, il peut y avoir:

recherche de classes (est mis en cache afin qu'aucune seconde recherche ne soit nécessaire)

chargement des classes (une fois chargé reste en mémoire)

obtention du code supplémentaire de la bibliothèque native (le code natif est mis en cache)

enfin, il charge le code à exécuter dans le cache L1 de la CPU. C’est le cas le plus propice à l’accélération, à votre sens, et en même temps une raison pour laquelle le critère de référence (étant un micro-critère) ne dit pas grand chose. Si votre code est suffisamment petit, la deuxième invocation d'une boucle peut être exécutée complètement à l'intérieur du processeur, ce qui est rapide. Dans le monde réel, cela ne se produit pas car les programmes sont plus volumineux et la réutilisation du cache L1 est loin d’être aussi importante.

Licencié sous: CC-BY-SA avec attribution

Non affilié à StackOverflow