Licence CC BY

Optimisation, microbenchmark et compilation Just In Time

Quand 1 + 1 ne font pas 2

Dernière mise à jour :
Auteur :
Catégorie :
Temps de lecture estimé : 11 minutes

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 :

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
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 :

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.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
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
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.

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 !

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
2
3
4
5
6
7
      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 :

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
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.


Ce petit exemple nous a montré que déterminer à priori les performances d’un bout de code d’un langage interprété par une JVM n’est pas du tout quelque chose de trivial. En effet :

  • Il y a une compilation à la volée qui optimise le code le plus utilisé.
  • Cette optimisation se fait en plusieurs étapes au fur et à mesure de l’utilisation de la méthode.
  • Un micro-benchmark peut donc être parfaitement non représentatif de l’application finale.
  • Rien de tout ceci n’est facilement visible avec des outils de traçage type YourKit.
  • Attention à la représentativité des tests mais aussi aux métriques récoltées !

De même, si le but du test est de comparer plusieurs solutions, attention à ce que l’environnement soit comparable : si on lance des tests séquentiellement dans une même JVM, les derniers test seront avantagés par une optimisation préalable possible de certaines parties du code, et désavantagés par une pression mémoire plus importante, les deux ne se compensant probablement pas. Il vaut probablement mieux lancer une JVM séparée par élément à tester.

Une question intéressante serait de savoir comment se comportent d’autres machines virtuelles de langages face à ce genre de problématiques : une autre JVM (ici celle d’Oracle sous Windows, on pourrait se demander si la version Linux, OpenJDK, IBM J9 ou Android se comportent pareil), les langages .NET, Python… Si vous avez le courage de lancer ces tests, indiquez-le en commentaire !

16 commentaires

Pour poser une question car je ne connais pas bien la JVM, il n’est pas possible de configurer la JVM pour qu’elle fasse les optimisations ou non sans avoir à se baser sur le nombre de fois où une méthode est appelée ?

Édité par Saroupille

+0 -0

C’est encore plus frappant quand il y a un JIT parce que le code qui est vraiment exécuté change lui-même, mais le problème de "les tests ne donnent pas un résultat numériquement fiable" est déjà présent dans à peu près tous les langages. Il y a toujours des paramètres qui changent selon les conditions d’utilisation et qui peuvent changer le temps d’exécution réel d’une fonction.

C’est pour ça que la remarque à mon avis intéressante est un peu sous-développée ici : quand on teste une fonction, ce n’est pas le chiffre absolu qui est intéressant (hé, il dépend même de ton processeur !), mais la différence entre deux codes (lequel est le plus rapide, dans des conditions d’utilisation semblables ?). Il se trouve que ça peut aussi dépendre des conditions exactes d’utilisation – mais en tout cas, se baser sur les chiffres absolus est de toute façon toujours une mauvaise idée.

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. Donc en montant de version la JVM, il y a un risque de perte de performances.

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 :

1
2
3
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é !

Édité par SpaceFox

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

On est d’accord, mais tu sembles insister alors j’ai une autre question : qui fait ça ? Dans quelle situation as-tu vu quelqu’un indiquer les performances d’une fonction avec un chiffre brut sans contexte et sans comparaison avec autre chose ?

Déjà oui, c’était même une grande mode à la grande époque des microoptimisations en PHP.

Tu pars d’une interprétation d’une petite partie de mes propos : je ne parle pas de « indiquer les performances d’une fonction avec un chiffre brut et sans comparaison avec autre chose ». Non seulement ce n’était déjà pas le propos du billet (les chiffres ne sont là que pour montrer qu’ils sont instables la manière dont ils le sont, avec un focus sur les optimisations par palier de la JVM – fonctionnement qu’à peu près personne ne connait) ; et tout le message sous lequel tu réponds ne parle que de comparaisons !

Mon propos est le suivant : une comparaison mal foutue, dans laquelle on a pas compris précisément ce qui est fait, n’a aucune valeur, parce que les métriques ne mesurent rien de probant. Or, des métriques complètement moisies, ça on en trouve à la pelle dans des tas de benchmark sur à peu près tous les sujets possibles. Et pas forcément par ignorance : ce que je montre aussi, c’est que sortir un chiffre utilisable peut devenir compliqué même sur un cas d’apparence aussi idiot que « mesurer le temps d’exécution d’une fonction ».

Beau travail, intéressant. :)

Cela me fait penser à un site, géré par un ingénieur système / noyau de Netflix à propos de la mesure des performances : http://www.brendangregg.com/usemethod.html

Il y a quelques conseils, outils, type de graphes pour visualiser les données, etc. C’est très intéressant, même s’il travaille plutôt au niveau noyau / système d’exploitation que langage ou une application standard.

Amateur de Logiciel Libre et de la distribution GNU/Linux Fedora. #JeSuisArius

+0 -0

Pris de curiosité, j’ai refais exactement le même test en C#, en utilisant le framework .NET 4.7. Voici déjà le code source, rien de bien différent de son équivalent Java, à l’exception d’une fonction NanoTime récupérée sur StackOverflow car n’existant pas nativement en C#.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
using System;
using System.Diagnostics;
using System.Text;

namespace ConsoleApp
{
    public class Program
    {
        public static Random Random = new Random();
        public static string Chars = "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123465798";
        public static int AlphabetSize = Chars.Length;

        public static int Loops = 1;
        public static long[] Times = new long[Loops];

        public static void Main()
        {
            string s;

            for (int i = 0; i < Loops; ++i)
            {
                long start = NanoTime();
                s = FunctionToMeasure();
                Times[i] = NanoTime() - start;
            }

            long totalTime = 0;
            foreach (long time in Times)
            {
                totalTime += time;
            }

            Console.WriteLine($"{Loops} loops in {totalTime} ns --> {totalTime / Loops} ns/string, throughput {(Loops * 1_000_000_000L) / totalTime} strings/s.");
        }

        private static string FunctionToMeasure()
        {
            var sb = new StringBuilder(100);
            for (int i = 0; i < 100; ++i)
            {
                sb.Append(Chars[Random.Next(AlphabetSize)]);
            }
            return sb.ToString();
        }

        private static long NanoTime()
        {
            long nano = 10000L * Stopwatch.GetTimestamp();
            nano /= TimeSpan.TicksPerMillisecond;
            nano *= 100L;
            return nano;
        }
    }
}

Voici les résultats chez moi. On observe très vite un certains plafond.

1
2
3
4
5
6
7
8
1 loops in 54700 ns             -->     54700 ns/string, throughput 18281 strings/s.
10 loops in 59900 ns            -->     5990 ns/string, throughput 166944 strings/s.
100 loops in 136300 ns          -->     1363 ns/string, throughput 733675 strings/s.
1000 loops in 732300 ns         -->     732 ns/string, throughput 1365560 strings/s.
10000 loops in 6854600 ns       -->     685 ns/string, throughput 1458874 strings/s.
100000 loops in 66080100 ns     -->     660 ns/string, throughput 1513314 strings/s.
1000000 loops in 670075900 ns   -->     670 ns/string, throughput 1492368 strings/s.
10000000 loops in 6634057600 ns -->     663 ns/string, throughput 1507373 strings/s.

Quand à savoir si j’ai des chiffres plus bas que toi SpaceFox, je n’ai aucune idée s’il s’agit de différences dans l’environnement d’exécution ou bien de la machine virtuelle C# plus optimisée que la JVM, ou une autre raison encore.

Je vais essayer de faire le test Java sur mon ordinateur et comparer avec mes métriques C#.

Hello, et merci pour l’article intéressant.

J’avais lu cet article, qui traitait grosso modo du même sujet.

Ce que j’en avais retenu, et que je fais d’ailleurs systématiquement, c’est, pour tout micro-benchmark, d’utiliser JMH, qui permet notamment de s’affranchir de certaines difficultés que tu as pu décrire dans ton article.

Comme je ne le voyais pas apparaître ici, je me permets de le mentionner.

J’espère pouvoir revenir plus en détails sur son utilisation dans un prochain commentaire, je manque de temps là tout de suite.

Happiness is a warm puppy

+3 -0

Au fait, pour ce que tu cherchais à mesurer (ou au moins que t’avais pris en exemple), j’avais assisté à cette conf l’année dernière.

(Pour l’anecdote : le speaker est plutôt un mec sérieux dans le monde de la JVM, notamment pour l’OpenJDK, et il est vraiment très sympathique)

Ca reprend un peu plus dans le détail ce dont tu parles : la JVM n’interprète pas systématiquement le bytecode, mais passe par le JIT quand elle considère qu’elle en a besoin (paramétrable mais attention…).

Il parle aussi de --XX:+PrintCompilation qui serait bien utile dans l’exemple que tu proposes pour piger ce que va faire le JIT, voire --XX:+PrintAssembly pour vraiment se faire mal.

C’est là-dessus que je voulais revenir, parce que je trouve que c’est une présentation très intéressante à plusieurs titres.

Premièrement : pour le cas que tu évoques : un benchmark naïf ne permet absolument pas de se faire une idée des performances d’un code qui s’exécute sur la JVM. (à partir de 13 minutes dans la vidéo, c’est exactement ce dont il parle). Et du coup il évoque JMH.

Ensuite : pour se rendre compte à travers un exemple pourtant trivial (que d’ailleurs tu as à juste titre repris, c’est l’un des premiers trucs qu’on apprend en Java), de comment fonctionne la JVM de tous les "trucs" qui rentrent en jeu. Et on apprend aussi pourquoi, quand je ne suis pas à l’intérieur d’une boucle, mes outils d’analyse de code me disent que "Non, te fais pas chier à écrire new StringBuilder().append, mets un + plutôt", "oui mais pourtant à l’école on m’a dit que…", "oui mais regarde le bytecode, c’est le même…, par contre, si t’es dans une boucle, là c’est plus la même limonade."

Ensuite (bis) : des informations très intéressantes, c’est que les optimisations fonctionnent par "recherche de pattern". Donc t’as plus tu codes "comme tout le monde", plus ton code sera potentiellement optimisé (et donc, performant ?).

Enfin : pour voir un peu le process de "recherche" (pas vraiment de la pure recherche) autour de l’optimisation d’une telle fonctionnalité en Java et ça regorge d’informations sur lesquelles je pense qu’il faut, un jour, se documenter, pour au moins savoir de quoi il en retourne. Exemple : invokeDynamic utilisé pour les lambdas de Java 8, et qui est utilisé dans (quasiment, Kotlin va s’y mettre je pense) les langages alternatifs de la JVM et les "MethodHandle". La notion d’intrinsic aussi, dont c’est intéressant d’avoir entendu parler.

Édité par Javier

Happiness is a warm puppy

+2 -0

Mais ce problème de test peut se généraliser pour tous les langages qui utilisent un JIT, non ? Ce n’est pas propre à Java j’ai l’impression.

Saroupille

Pas vraiment, non. Ou plutôt : c’est pas présent dans tout JIT. Le premier gros JIT à s’être mis à optimiser les points chauds d’un programme était… HotSpot. La réponse était dans la question. C’est mentionné ici : https://zestedesavoir.com/articles/1652/quelques-rouages-dun-moteur-javascript/#fn-larsbak

Tu pourrais tout à fait avoir un JIT simple qui ne de soucie pas d’optimiser les trucs chauds.

Vous aimez le frontend ? Il y a un tas de petites tâches faciles si vous voulez contribuer à ZdS : https://github.com/zestedesavoir/zds-site/issues?q=is%3Aissue+is%3Aopen+label%3AC-Front

+0 -0
Vous devez être connecté pour pouvoir poster un message.
Connexion

Pas encore inscrit ?

Créez un compte en une minute pour profiter pleinement de toutes les fonctionnalités de Zeste de Savoir. Ici, tout est gratuit et sans publicité.
Créer un compte