Journal Optimisation, microbenchmark et compilation Just In Time : quand 1 + 1 ne font pas 2

Posté par  (site web personnel, Mastodon) .
Étiquettes :
50
3
nov.
2017

Sommaire

Imaginons que j'aie une méthode à optimiser. Par exemple – sans intérêt réel – cette fonction qui génère une chaîne de 100 caractères aléatoires :

private static final Random RANDOM = new Random();
private static final char[] CHARS = "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123465798".toCharArray();
private static final int ALPHABET_SIZE = CHARS.length;

private static String functionToMeasure() {
    final StringBuilder sb = new StringBuilder(100);
    for (int i = 0; i < 100; i++) {
        sb.append(CHARS[RANDOM.nextInt(ALPHABET_SIZE)]);
    }
    return sb.toString();
}

En admettant que je sais (par algorithmique, par mesures, etc.) que c'est cette fonctionnalité que je dois améliorer. Ou que cette fonction a plusieurs implémentations possibles (ici avec StringBuffer, StringBuilder ou des concaténation de chaines de caractères) que je dois comparer.

La question que je me pose est :

Question : Comment assurer une mesure et une comparaison fiables ?

Eh bien mine de rien, il y a moyen de bien se planter juste avec une question d'apparence aussi simple !

Un micro-benchmark

Je fais un micro-benchmark pour vérifier comment cette fonction se comporte. Le code ne mesure que le temps d'exécution de la méthode, et on fait quelque chose du résultat pour être sûr qu'une optimisation ne va pas se contenter de ne pas exécuter la méthode, ce qui fausserait tout.

import java.util.Random;

public class Test {

    private static final Random RANDOM = new Random();
    private static final char[] CHARS = "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123465798".toCharArray();
    private static final int ALPHABET_SIZE = CHARS.length;

    private static final int LOOPS = 1;
    private static final long[] TIMES = new long[LOOPS];

    public static void main(String... args) {
        String string;
        for (int i = 0; i < LOOPS; i++) {

            final long start = System.nanoTime();
            string = functionToMeasure();
            TIMES[i] = System.nanoTime() - start;

            System.out.println(string);
        }
        long totalTime = 0;
        for (long time : TIMES) {
            totalTime += time;
        }
        System.out.println(LOOPS + " loops in " + totalTime + " ns "
                +  "--> " + (totalTime / LOOPS) + " ns/string, "
                + "throughput " + (LOOPS * 1_000_000_000L) / totalTime + " strings/s");
    }

    private static String functionToMeasure() {
        final StringBuilder sb = new StringBuilder(100);
        for (int i = 0; i < 100; i++) {
            sb.append(CHARS[RANDOM.nextInt(ALPHABET_SIZE)]);
        }
        return sb.toString();
    }
}

On commence par se demander combien de temps il faut pour exécuter une fois cette méthode :

1 loops in 97898 ns --> 97898 ns/string, throughput 10214 strings/s

Ça me paraît bien lent : seulement 10 000 générations par seconde en moyenne. Je m'attendais mieux de la part de Java.

Question : Je suis sûr qu'on peut améliorer ça en ne modifiant qu'une seule ligne de code. Comment ?

Quand 1 + 1 ≠ 2 !

La réponse est très simple : il suffit de modifier le nombre de fois où on lance le test et donc de modifier la valeur à la ligne 9 !

Question : Attends, tu ne te fouterais pas un peu de notre gueule là ? Si on lance le test 10 fois, on devrait avoir 10 fois le même résultat !

Et c'est vrai… si on lance 10 fois le même test dans 10 JVM différentes avec le même code, on a des petites variations mais le résultat est toujours le même, à peu de choses près.

Mais si on demande à une même JVM d'exécuter plusieurs fois la même méthode, ce qui se produira en réalité, les résultats ne sont plus les mêmes. Jugez plutôt :

      1 loops in 95804 ns -->      95804 ns/string, throughput 10437 strings/s
     10 loops in 806218 ns -->     80621 ns/string, throughput 12403 strings/s
    100 loops in 1639395 ns -->    16393 ns/string, throughput 60998 strings/s
   1000 loops in 5508983 ns -->     5508 ns/string, throughput 181521 strings/s
  10000 loops in 17692767 ns -->    1769 ns/string, throughput 565202 strings/s
 100000 loops in 131703629 ns -->   1317 ns/string, throughput 759280 strings/s
1000000 loops in 1155445070 ns -->  1155 ns/string, throughput 865467 strings/s

Édifiant non ? On a pas loin d'un facteur 100 ! Mais pourquoi ?

Zyeutons ce qui se passe en détails…

Je modifie le système de tests pour enregistrer les temps d'exécution de chaque exécution :

import java.util.Random;

public class Test {

    private static final Random RANDOM = new Random();
    private static final char[] CHARS = "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123465798".toCharArray();
    private static final int ALPHABET_SIZE = CHARS.length;
    private static final int LOOPS = 5000;
    private static final long[] TIMES = new long[LOOPS];

    public static void main(String... args) {
        String string;
        for (int i = 0; i < LOOPS; i++) {
            final long start = System.nanoTime();
            string = functionToMeasure();
            TIMES[i] = System.nanoTime() - start;
            System.out.println(string);
        }
        long totalTime = 0;
        System.out.println("Time list:");
        for (int i = 0; i < LOOPS; i++) {
            long time = TIMES[i];
            System.out.println(time);
            totalTime += time;
        }
        System.out.println(LOOPS + " loops in " + totalTime + " ns "
                +  "--> " + (totalTime / LOOPS) + " ns/string, "
                + "throughput " + (LOOPS * 1_000_000_000L) / totalTime + " strings/s");
    }

    private static String functionToMeasure() {
        final StringBuilder sb = new StringBuilder(100);
        for (int i = 0; i < 100; i++) {
            sb.append(CHARS[RANDOM.nextInt(ALPHABET_SIZE)]);
        }
        return sb.toString();
    }
}

Si on trace les temps de réponse (échelle logarithmique !) en fonction du numéro de l'échantillon, on obtient ce genre de graphe :

Temps de réponse

On y voit 4 plages de fonctionnement qui correspondent à 4 niveaux d'optimisation différents :

  1. Les toutes premières exécutions, très lentes (environ 90 000 ns).
  2. La première centaine d'exécutions tombe rapidement aux alentours de 10 000 - 20 000 ns, soit déjà un bon facteur 5, mais c'est assez instable.
  3. Ensuite, jusqu'à la 2000ème^ exécution, on oscille entre 2000 et 3000 ns, soit un facteur de près de 10.
  4. Cette méthode est vraiment très utilisée, elle est encore optimisée et tombe vers 1000 ns (en réalité, 80 % des échantillons sont à 1047 ns exactement, d'où ce « plat » sur le graphique et un débit théorique de 973 709 générations/seconde).

Tout ça correspond aux différentes passes d'optimisation de la JVM : on passe graduellement d'une méthode utilisée une fois donc entièrement interprétée, à une méthode identifiée comme critique pour le fonctionnement de l'application donc compilée et optimisée à fond par la JVM.

Une preuve supplémentaire en graphiques

Une petite illustration pour montrer à quel point les valeurs numériques ça ne veut rien dire.

J'ai sur mon PC perso 4 JVM différentes :

  • OpenJDK 1.8
  • OpenJDK 9
  • Oracle JDK 1.8
  • IBM J9 1.8

Déjà ce qu'on remarque, c'est que si on lance le même test avec la même JVM, les seuils de déclenchement des optimisations sont différents d'une exécution à l'autre avec OpenJDK 1.8. Je soupçonne que c'est parce que mon processeur est un Core i5 dont la fréquence varie pas mal, alors que mon processeur au boulot est un Core i3 plus sollicité et donc reste coincé à 3.9 GHz.

Rien qu'en changeant de JVM, sans recompiler quoi que ce soit, on obtient quelque chose comme ça :

Temps d'exécution en ns (log) pour chaque échantillon

Graphe assez peu lisible, je vous l'accorde. On remarque néanmoins que :

  • Les JVM 1.8 Oracle et OpenJDK, c'est exactement les mêmes – les seuils de déclenchement des optimisations sont aléatoires.
  • La JVM IBM ne se comporte pas comme les autres, en particulier il lui manque le dernier seuil d'optimisation – ou alors il faut plus de 5000 exécutions de la méthode pour le déclencher.
  • Curieusement, il manque aussi cette dernière optimisation sur la JVM OpenJDK 9 (elle n'a probablement pas eu le temps de se déclencher).

S'il fallait un exemple de l'inutilité crasse de donner des chiffres pour des chiffres, celui-ci est parlant.

Là où ça devient drôle, c'est quand on visualise les données. Ici, 3 implémentations possibles pour concaténer les caractères aléatoires de la chaine :

StringBuilder : 5000 loops in 17861869 ns --> 3572 ns/string, throughput 279925 strings/s
StringBuffer :  5000 loops in 17371225 ns --> 3474 ns/string, throughput 287832 strings/s
Concaténation : 5000 loops in 58851808 ns --> 11770 ns/string, throughput 84959 strings/s

OK, on a raison de dire que concaténer des chaines de caractères dans des boucles c'est mal. Mais les deux autres implémentations ont l'air équivalentes, non ?

Implémentations

Ha ben non. StringBuffer est plus lente, c'est juste que sur cet exemple, StringBuilder n'a pas déclenché la dernière optimisation (laquelle ramène effectivement les deux méthodes au même niveau de performances).

Et au passage on remarque que la JVM peut dé-optimiser un bout de code !

Tant que c'est possible, visualisez vos données, surtout quand vous faites des tests sur des choses aussi instables que du code interprété !

Pour aller plus loin

Ce journal, placé sous licence Creative Commons Paternité 4.0 (CC BY), est une légère modification de l'original disponible ici et de ce commentaire, que je repartage ici parce que j'imagine que ça peut intéresser.

  • # Super intéressant

    Posté par  . Évalué à 9.

    Merci. Ce commentaire est juste là pour t'encourager :)

  • # microbenchmark

    Posté par  (site web personnel) . Évalué à 6. Dernière modification le 03 novembre 2017 à 16:49.

    Je conseil très fortement la même chose pour du code C. Utiliser une moyenne n'a pas beaucoup de sens. J'ai remarqué que il faut 3 exécutions de la boucle pour atteindre un palier bas, pour remplir la mémoire cache. Et évidement, un code ne se comporte pas pareil avec des données en cache ou non. Donc, optimiser un code en dehors
    de son cas d'usage réel peux être un mauvais plan.

    N'utilisez plus un seul chiffre, mais des courbes !

    "La première sécurité est la liberté"

    • [^] # Re: microbenchmark

      Posté par  (site web personnel, Mastodon) . Évalué à 1. Dernière modification le 03 novembre 2017 à 16:55.

      Tu as une idée de l'ampleur du phénomène sur du code compilé en natif ?

      Assez naïvement, j'aurais tendance à imaginer que ça ne change pas dans des proportions importantes, mais en vrai je ne sais pas du tout comment se comportent les cache processeurs etc. au niveau des impacts sur les performances. Et vu que la dernière fois que j'ai touché à un langage compilé en natif, c'était à l'IUT, du C sur 68HC11…

      La connaissance libre : https://zestedesavoir.com

      • [^] # Re: microbenchmark

        Posté par  (site web personnel) . Évalué à 5.

        Sur un microbenchmark de memcpy, il y avait un facteur x10 entre cold/hot start.

        Sur un code de calcul, de mémoire, il y avait une augmentation de 30% des perfs au 3ième tour.

        "La première sécurité est la liberté"

    • [^] # Re: microbenchmark

      Posté par  . Évalué à 3.

      Tu as aussi la prédiction du CPU qui peut, peut-être, jouer.

      « Rappelez-vous toujours que si la Gestapo avait les moyens de vous faire parler, les politiciens ont, eux, les moyens de vous faire taire. » Coluche

  • # fonction à durée aléatoire

    Posté par  . Évalué à 4. Dernière modification le 03 novembre 2017 à 17:57.

    Je n'ai pas regardé le fonctionnement de cette fonction Random() en java. Mais il y a de forte chance qu'elle fasse appelle à de l'entropie, au système ou bien d'autres trucs à durée aléatoire.

    Pour un benchmark comme celui-là, j'essayerai sans en la remplaçant par une fonction dont l'on est sur du temps d'exécution.

    • [^] # Re: fonction à durée aléatoire

      Posté par  . Évalué à 6.

      Je n'ai pas regardé le fonctionnement de cette fonction Random() en java. Mais il y a de forte chance qu'elle fasse appelle à de l'entropie, au système ou bien d'autres trucs à durée aléatoire.

      Non, Random c'est une bête congruence linéaire. Si tu veux un générateur pour la crypto -> SecureRandom

  • # Et maintenant ?

    Posté par  . Évalué à -1.

    Tout ça correspond aux différentes passes d'optimisation de la JVM : on passe graduellement d'une méthode utilisée une fois donc entièrement interprétée, à une méthode identifiée comme critique pour le fonctionnement de l'application donc compilée et optimisée à fond par la JVM.

    Et maintenant tu vas passer aux choses sérieuses et faire une vraie analyse ou des vrais tests ? ;-)

    Si tu veux essayer de comprendre un peu ce qu'il se passe en vrai JITWatch est un excellent outil.

    tl;dr:

    1. Tu récupères linux-hsdis-amd64.so quelque part. Historiquement via le projet Kenai mais le site est down maintenant. Si tu le trouves pas, tu te frappes une compilation d'OpenJDK en debug. Tu le places dans $JDK/jre/lib/amd64/server/hsdis-amd64.so. hsdis te permet de sortir sortir le code assembleur généré par HotSpot
    2. Tu tournes ton appli -XX:+UnlockDiagnosticVMOptions -XX:+TraceClassLoading -XX:+LogCompilation -XX:+PrintAssembly -XX:-UseCompressedOops -XX:LogFile=mylogfile.log
    3. Tu lances JitWatch

    Ça te permettra de comprendre les différentes phases de compilation d'une même méthode, explorer la compile chain (ie. ce qui a été compilé, pas compilé, inliné, appels virtuels etc.), voir l'assembleur généré à chaque étape, voir les intrinsics utilisés etc.

    En général le combo JITWatch / JMH bien utilisé te permettent de comprendre beaucoup de choses. Côté JMH, souvent la clé pour se genre de truc c'est de jouer avec les options de la JVM pour prendre différentes mesures. Ici tu pourrais tester un -Xint pour empêcher toute compilation, puis -XX:TieredStopAtLevel=X si tu penses que ce tu observes est lié aux 5 niveaux de compilation d'HotSpot. Les logs de compilations sont aussi super utiles, de même que la sortie assembleur.

    Avec ces deux outils tu peux mettre en place un joli cycle d'itérations ou tu appliques bêtement la méthode scientifique. Attention un bench sert à valider un modèle de performance et pas à le découvrir. Voilà, tu viens de découvrir comment occuper tes 5 prochaines années ! Si j'ai 5 minutes a tuer je regarderais ton test.

    Note: Je ne rentre pas sur le terrain de la pertinence de ton test, savoir expliquer ce que l'on observe est déjà bien rigolo :-)

    • [^] # Re: Et maintenant ?

      Posté par  (site web personnel, Mastodon) . Évalué à 8.

      Et maintenant tu vas passer aux choses sérieuses et faire une vraie analyse ou des vrais tests ? ;-)

      Absolument pas. Ce n'est pas le but : le test présenté est totalement bidon et ne correspondait pas à un cas d'usage réel (lequel était de comparer plusieurs implémentations existantes tierces, sans chercher à les optimiser).

      Le but de ce billet était tout simplement de sensibiliser – et de montrer par l'exemple – que des tests qui semblent simples et logiques peuvent déboucher sur du grand n'importe quoi en terme de résultats. Parce que si la mode de la microoptimisation à la PHP (« Utilise des guillemets simples ça va plus vite » et autres idioties) est passée, je croise encore souvent ce genre de « métriques ».

      La connaissance libre : https://zestedesavoir.com

  • # Dé-optimiser : mais pourquoi faire ?

    Posté par  . Évalué à 2.

    Et au passage on remarque que la JVM peut dé-optimiser un bout de code !

    Tu parles du graphe jaune (la concaténation de chaînes de caractères), qui remonte à > 10.000, je suppose ?
    Pourquoi la JVM a-t-elle décidé de dé-optimiser ce bout de code ?

    • [^] # Re: Dé-optimiser : mais pourquoi faire ?

      Posté par  (site web personnel, Mastodon) . Évalué à 3.

      Aucune idée. Peut-être qu'elle a croisé une valeur qui a fait que l'assembleur généré n'était plus utilisable.

      Si ça se trouve ce n'est même pas une désoptimisation, juste le CPU qui a décidé de réduire sa fréquence.

      Mais je trouve l'exemple intéressant, dans la mesure où il montre que de façon surprenante les comportements sont instables dans le temps, à la baisse comme à la hausse.

      La connaissance libre : https://zestedesavoir.com

      • [^] # Re: Dé-optimiser : mais pourquoi faire ?

        Posté par  . Évalué à 1.

        Tu as fait ces benchmarks à fréquence variable ?
        Mais… Qui me dit que toute ton explication ne tombe pas à l'eau et que c'est pas juste le CPU qui s'adapte à la charge ? ^

        • [^] # Re: Dé-optimiser : mais pourquoi faire ?

          Posté par  (site web personnel, Mastodon) . Évalué à 1.

          Deux choses :

          1. Le fait que c'est fait sur des CPU qui sont à fréquence normalement fixe en charge, donc si ça baisse, c'est du throttle (et ça impliquerait des choses graves sur le refroidissement de mon ordi), mais surtout
          2. On est dans des plages de variations très au-delà de ce qu'est capable de faire un CPU.

          La connaissance libre : https://zestedesavoir.com

  • # Reproductibilité

    Posté par  (site web personnel) . Évalué à 8.

    Ce qui compte pour mesurer la performance d'un programme pour s'orienter dans le développement c'est d'appliquer la méthode scientifique. Le but est donc de construire un énoncé falsifiable et dans le contexte de l'optimisation de ta méthode functionToMeasure on aimerait bien construire un énoncé du type “l'implémentation A est toujours plus performante que l'implémentation B” mais ce type d'énoncé n'au aucune chance de marcher.

    Dans la liste des défauts de mon énoncé il y a bien-sûr le fait qu'il faut expliquer ce que veut dire “performant” ce qui n'est pas forcément facile et en plus imaginer une expérience qui mesure cette performance dont on a précisé la teneur, et le but est d'arriver à une expérience dont le résultat est reproductible, autrement on ne peut rien conclure du tout. Mais ensuite la durée d'exécution (“performance en temps”) se comporte super mal! À preuve:

    1. Le même programme lancé sur la même machine opérant sur la même donnée après un cold boot peut livrer des temps d'exécution très différents, sans problème du simple au double. Il y a des milliers de raisons possibles à cela, dont l'alignement mémoire qui a une influence directe sur la stratégie d'utilisation des caches.

    2. Un programme plus long qu'un autre (par exemple bordé de NOPs ou qui fait des contrôles d'indice sur un tableau) peut parfois être rapide!

    3. Les ordinateurs sont très complexes et il y a des tas de facteurs qui influent sur la vitesse d'exécution des programmes, même la taille d'une variable d'environnement non utilisée par le programme!

    Voir par exemple Producing Wrong Data Without Doing Anything Obviously Wrong!. Un autre exemple rigolo de biais est la question la plus votée de SO.

    Ainsi, même si on réalise que les mesures individuelles n'ont aucun sens et qu'il faut toujours mesurer des distributions, on ne fait que s'avancer vers un problème très compliqué et si on veut mesurer sérieusement la vitesse d'exécution d'un programme on doit donc construire un protocole expérimental qui se débarrasse de tous les biais… et quand on le fait pour GCC on découvre que l'incidence de l'utilisation de -O3 par rapport à -O2 est indistiguable d'un bruit statistique.

    Des problèmes particulièrement difficiles en pratique sont en outre la production de données dont la distribution ressemble à celles de l'application réelle, et pour les applications réseau la reproduction d'une charge ressemblant à celle de l'application réelle.

  • # c'est un JIT compiler

    Posté par  . Évalué à -1. Dernière modification le 13 novembre 2017 à 15:24.

    Quand on connaît le fonctionnement d'un JIT on pourrait dire "merci captain obvious".
    Mais j'ai quand même pertinenté l'effort d'illustration et d'explication.

Suivre le flux des commentaires

Note : les commentaires appartiennent à celles et ceux qui les ont postés. Nous n’en sommes pas responsables.