URL: https://linuxfr.org/users/spacefox/journaux/optimisation-microbenchmark-et-compilation-just-in-time-quand-1-1-ne-font-pas-2 Title: Optimisation, microbenchmark et compilation Just In Time : quand 1 + 1 ne font pas 2 Authors: SpaceFox Date: 2017年11月03日T16:20:08+01:00 Tags: java, jdk et jit Score: 50 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 : ```java 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. ```java 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 : ```console 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 : ```console 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 : ```java 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](https://zestedesavoir.com/media/galleries/4618/a4eab91b-fa69-43d6-9ff7-6a35c5dc8f7c.png) 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](https://zestedesavoir.com/media/galleries/4618/76badb9b-bffc-45db-a22b-a6c1eff11977.png) 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 : ```console 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](https://zestedesavoir.com/media/galleries/4618/002087b6-86cb-4553-a5df-8638b4bf1274.png) 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 - [Cet article](http://www.brendangregg.com/usemethod.html) sur la façon de faire des tests en Java. - [Utilisez JMH pour tout microbenchmark en Java](http://www.oracle.com/technetwork/articles/java/architect-benchmarking-2266277.html). - [Cette conférence](https://www.youtube.com/watch?v=U97zT8kA7G4) sur les optimisations cachées de la JVM. ------------------------------ Ce journal, placé sous licence Creative Commons Paternité 4.0 (CC BY), est une légère modification de l'original [disponible ici](https://zestedesavoir.com/billets/2217/optimisation-microbenchmark-et-compilation-just-in-time/?page=1#p165592) et de [ce commentaire](https://zestedesavoir.com/billets/2217/optimisation-microbenchmark-et-compilation-just-in-time/?page=1#p165531), que je repartage ici parce que j'imagine que ça peut intéresser.

AltStyle によって変換されたページ (->オリジナル) /