57 votes

Un programme Java fonctionne plus lentement lorsque le code qui n'est jamais exécuté est commenté.

J'ai observé un comportement étrange dans l'un de mes programmes Java. J'ai essayé de dépouiller le code autant que possible tout en étant capable de reproduire le comportement. Code complet ci-dessous.

public class StrangeBehaviour {

    static boolean recursionFlag = true;

    public static void main(String[] args) {
        long startTime = System.nanoTime();
        for (int i = 0; i < 10000; i ++) {
            functionA(6, 0);
        }
        long endTime = System.nanoTime();
        System.out.format("%.2f seconds elapsed.\n", (endTime - startTime) / 1000.0 / 1000 / 1000);
    }

    static boolean functionA(int recursionDepth, int recursionSwitch) {
        if (recursionDepth == 0) { return true; }
        return functionB(recursionDepth, recursionSwitch);
    }

    static boolean functionB(int recursionDepth, int recursionSwitch) {
        for (int i = 0; i < 16; i++) {
            if (StrangeBehaviour.recursionFlag) {
                if (recursionSwitch == 0) {
                    if (functionA(recursionDepth - 1, 1 - recursionSwitch)) return true;
                } else {
                    if (!functionA(recursionDepth - 1, 1 - recursionSwitch)) return false;
                }
            } else {
                // This block is never entered into.
                // Yet commenting out one of the lines below makes the program run slower!
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
                System.out.println("...");
            }
        }
        return false;
    }
}

J'ai deux fonctions, functionA() y functionB() qui s'appellent mutuellement de manière récursive. Les deux fonctions prennent un recursionDepth qui contrôle la fin de la récursion. functionA() appelle functionB() une fois au maximum avec recursionDepth inchangé. functionB() appelle functionA() 16 fois avec recursionDepth - 1 . La récursion se termine lorsque functionA() est appelé avec un recursionDepth de 0 .

functionB() a un bloc de code avec un certain nombre de System.out.println() appels. Ce bloc n'est jamais pénétré, car l'entrée est contrôlée par un système d'alarme. boolean recursionFlag qui a pour valeur true et n'a jamais été modifié pendant l'exécution du programme. Cependant, le fait de commenter ne serait-ce qu'un seul des println() entraîne un ralentissement de l'exécution du programme. Sur ma machine, le temps d'exécution est <0,2s avec tous les println() présents, et >2s lorsque l'un des appels est commenté.

Quelle pourrait être la cause de ce comportement ? Ma seule hypothèse est qu'il y a une optimisation naïve du compilateur qui est déclenchée par un paramètre lié à la longueur du bloc de code (ou au nombre d'appels de fonction, etc.). Je vous serais reconnaissant de bien vouloir m'éclairer sur ce point !

Modification : j'utilise le JDK 1.8.

41voto

k5_ Points 3546

Le code commenté affecte la façon dont l'inlining est géré. Si la fonction B devient plus longue/grande (plus d'instructions de bytecode), elle ne sera pas inline dans la fonction A.

Ainsi, @J3D1 a pu utiliser VMOptions pour désactiver manuellement l'inlining pour la fonctionB() : -XX:CompileCommand=dontinline,com.jd.benchmarking.StrangeBeh‌​aviour::functionB Cela semble éliminer le retard avec la fonction courte.

avec les options vm vous pouvez afficher l'inlining -XX:+UnlockDiagnosticVMOptions -XX:+PrintInlining

La plus grande version, sans fonction en ligneB

@ 8   StrangeBehaviour::functionB (326 bytes)   callee is too large
@ 21   StrangeBehaviour::functionA (12 bytes)
  @ 8   StrangeBehaviour::functionB (326 bytes)   callee is too large
@ 35   StrangeBehaviour::functionA (12 bytes)
  @ 8   StrangeBehaviour::functionB (326 bytes)   callee is too large

La version la plus courte essaiera de mettre en ligne la fonction B, ce qui entraînera quelques tentatives supplémentaires.

@ 8   StrangeBehaviour::functionB (318 bytes)   inline (hot)
 @ 21   StrangeBehaviour::functionA (12 bytes)   inline (hot)
   @ 8   StrangeBehaviour::functionB (318 bytes)   inline (hot)
     @ 35   StrangeBehaviour::functionA (12 bytes)   recursive inlining is too deep
 @ 35   StrangeBehaviour::functionA (12 bytes)   inline (hot)
   @ 8   StrangeBehaviour::functionB (318 bytes)   inline (hot)
     @ 21   StrangeBehaviour::functionA (12 bytes)   recursive inlining is too deep
     @ 35   StrangeBehaviour::functionA (12 bytes)   recursive inlining is too deep
@ 21   StrangeBehaviour::functionA (12 bytes)   inline (hot)
 @ 8   StrangeBehaviour::functionB (318 bytes)   inline (hot)
   @ 35   StrangeBehaviour::functionA (12 bytes)   inline (hot)
     @ 8   StrangeBehaviour::functionB (318 bytes)   recursive inlining is too deep
@ 35   StrangeBehaviour::functionA (12 bytes)   inline (hot)
 @ 8   StrangeBehaviour::functionB (318 bytes)   inline (hot)
   @ 21   StrangeBehaviour::functionA (12 bytes)   inline (hot)
    @ 8   StrangeBehaviour::functionB (318 bytes)   recursive inlining is too deep
   @ 35   StrangeBehaviour::functionA (12 bytes)   inline (hot)
     @ 8   StrangeBehaviour::functionB (318 bytes)   recursive inlining is too deep

C'est surtout une supposition, mais le bytecode plus gros/inlined posera des problèmes avec la prédiction des branches et la mise en cache.

21voto

Erwin Bolwidt Points 5566

La réponse complète est une combinaison de k5_ et des réponses de Tony.

Le code que l'OP a posté omet une boucle d'échauffement pour déclencher la compilation HotSpot avant de faire le benchmark ; d'où l'accélération de 10 fois (sur mon ordinateur) lorsque les instructions d'impression sont incluses, combine à la fois le temps passé dans HotSpot pour compiler le bytecode en instructions CPU, ainsi que l'exécution réelle des instructions CPU.

Si j'ajoute une boucle d'échauffement séparée avant la boucle de chronométrage, la vitesse n'est que de 2,5 fois supérieure avec l'instruction print.

Cela indique que la compilation HotSpot/JIT prend plus de temps lorsque la méthode est inlined (comme Tony l'a expliqué) et que l'exécution du code prend plus de temps, probablement à cause d'une moins bonne performance de cache ou de prédiction de branche/pipelining, comme k5_ l'a montré.

public static void main(String[] args) {
    // Added the following warmup loop before the timing loop
    for (int i = 0; i < 50000; i++) {
        functionA(6, 0);
    }

    long startTime = System.nanoTime();
    for (int i = 0; i < 50000; i++) {
        functionA(6, 0);
    }
    long endTime = System.nanoTime();
    System.out.format("%.2f seconds elapsed.\n", (endTime - startTime) / 1000.0 / 1000 / 1000);
}

18voto

Tony Points 3371

Je suis avec @k5_, il semble qu'il existe un seuil pour déterminer s'il faut mettre une fonction en ligne. Et si le compilateur JIT décide de l'inliner, cela entraînera beaucoup de travail et de temps pour le faire en tant que -XX:+PrintCompilation montre :

  task-id
    158   32       3       so_test.StrangeBehaviour::functionB (326 bytes)   made not entrant
    159   35       3       java.lang.String::<init> (82 bytes)
    160   36  s    1       java.util.Vector::size (5 bytes)
    1878   37 %     3       so_test.StrangeBehaviour::main @ 6 (65 bytes)
    1898   38       3       so_test.StrangeBehaviour::main (65 bytes)
    2665   39       3       java.util.regex.Pattern::has (15 bytes)
    2667   40       3       sun.misc.FDBigInteger::mult (64 bytes)
    2668   41       3       sun.misc.FDBigInteger::<init> (30 bytes)
    2668   42       3       sun.misc.FDBigInteger::trimLeadingZeros (57 bytes)
    2.51 seconds elapsed.

L'info supérieure est sans commentaire, la suivante est avec un commentaire qui réduit la taille de la méthode de 326 octets à 318 octets. Et vous pouvez remarquer que le identifiant de la tâche dans la colonne 1 de la sortie est beaucoup plus grande dans ce dernier, ce qui entraîne plus de temps.

  task-id
    126   35       4       so_test.StrangeBehaviour::functionA (12 bytes)
    130   33       3       so_test.StrangeBehaviour::functionA (12 bytes)   made not entrant
    131   36  s    1       java.util.Vector::size (5 bytes)
    14078   37 %     3       so_test.StrangeBehaviour::main @ 6 (65 bytes)
    14296   38       3       so_test.StrangeBehaviour::main (65 bytes)
    14296   39 %     4       so_test.StrangeBehaviour::functionB @ 2 (318 bytes)
    14300   40       4       so_test.StrangeBehaviour::functionB (318 bytes)
    14304   34       3       so_test.StrangeBehaviour::functionB (318 bytes)   made not entrant
    14628   41       3       java.util.regex.Pattern::has (15 bytes)
    14631   42       3       sun.misc.FDBigInteger::mult (64 bytes)
    14632   43       3       sun.misc.FDBigInteger::<init> (30 bytes)
    14632   44       3       sun.misc.FDBigInteger::trimLeadingZeros (57 bytes)
    14.50 seconds elapsed.

Et si vous changez le code en suivant (ajouter deux lignes et imprimer une ligne), vous pouvez voir que la taille du code est passée à 326 octets, et qu'il fonctionne plus rapidement maintenant :

        if (StrangeBehaviour.recursionFlag) {
            int a = 1;
            int b = 1;
            if (recursionSwitch == 0) {
                if (functionA(recursionDepth - 1, 1 - recursionSwitch)) return true;
            } else {
                if (!functionA(recursionDepth - 1, 1 - recursionSwitch)) return false;
            }
        } else {
            // This block is never entered into.
            // Yet commenting out one of the lines below makes the program run slower!
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
          //System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
            System.out.println("...");
        }

Nouvelle heure et informations sur le compilateur JIT :

    140   34       3       so_test.StrangeBehaviour::functionB (326 bytes)   made not entrant
    145   36       3       java.lang.String::<init> (82 bytes)
    148   37  s    1       java.util.Vector::size (5 bytes)
    162   38       4       so_test.StrangeBehaviour::functionA (12 bytes)
    163   33       3       so_test.StrangeBehaviour::functionA (12 bytes)   made not entrant
    1916   39 %     3       so_test.StrangeBehaviour::main @ 6 (65 bytes)
    1936   40       3       so_test.StrangeBehaviour::main (65 bytes)
    2686   41       3       java.util.regex.Pattern::has (15 bytes)
    2689   42       3       sun.misc.FDBigInteger::mult (64 bytes)
    2690   43       3       sun.misc.FDBigInteger::<init> (30 bytes)
    2690   44       3       sun.misc.FDBigInteger::trimLeadingZeros (57 bytes)
    2.55 seconds elapsed.

En conclusion :

  • Lorsque la taille de la méthode dépasse certaines limites, le JIT ne met pas cette fonction en ligne ;
  • Et si nous commentons une ligne, qui se réduit à une taille inférieure au seuil, le JIT décide de la mettre en ligne ;
  • L'intégration de cette fonction entraîne un grand nombre de tâches JIT, ce qui ralentit le programme.

mise à jour :

Conformément à mon dernier essai La réponse à cette question n'est pas si simple :

Comme le montre mon exemple de code, une optimisation en ligne normale sera

  • accélère le programme
  • et ne coûte pas beaucoup de travail au compilateur (dans mon test, il coûte même moins de travail lorsque l'inline se produit).

Mais dans ce problème, le code provoque beaucoup de travail JIT et ralentit le programme, ce qui semble être un bug du JIT. Et on ne sait toujours pas pourquoi il fait travailler autant le JIT.

Prograide.com

Prograide est une communauté de développeurs qui cherche à élargir la connaissance de la programmation au-delà de l'anglais.
Pour cela nous avons les plus grands doutes résolus en français et vous pouvez aussi poser vos propres questions ou résoudre celles des autres.

Powered by:

X