Performance, les Xebians jouent les démineurs
Le premier XKE dans nos nouveaux locaux a donné lieu à de bien curieuses scènes : des bisounours ont hué des poubelles sous le regard moqueur de pokemons ! Et, non, les cartons de déménagement ne nous sont pas tombés sur la tête. Ce n'était là que quelques uns des noms choisis par des équipes de 3 à 4 consultants, qui se sont mesurés dans un concours de tuning de performance, sur une application Java EE standard, buggée (volontairement, pour une fois) par les maîtres de cérémonie, Guillaume Bodet et Cyrille Le Clerc. Tous les participants se sont vus remettre une VM, contenant un Tomcat, une application (PetClinic de Spring, revue et "corrigée") et des scripts de performance JMeter. Le code source n'a, dans un premier temps, pas été fourni.
Pour tous, un seul but : faire diminuer les temps de réponses de l'application.
Les règles étaient les suivantes :
- Un bug n'est considéré comme trouvé que lorsqu'il a été identifié, qu'un correctif a été proposé et que la preuve est faite que ce correctif permet d'améliorer significativement les temps de réponse.
- Il existe trois niveaux de difficulté, allant du bug évident à l'anomalie la plus fourbe.
- Le choix des outils est libre.
A vos marques... Prêts ? Débuggez !
Préambule
L'un des buts de ce Xke était d'être très didactique, dans les méthodes de recherche et dans l'utilisation des outils. Les bombes placées dans le code permettaient de réaliser une progression linéaire (dans la difficulté comme dans les gains attendus). Cette progression est retranscrite dans cet article et ceux qui vont suivre.
Cependant, pour différentes raisons que nous aurons l'occasion d'expliquer, l'ordre des analyses, et donc de découvertes des bugs, n'est pas celui qu'aurait choisi un champion de la performance, j'ai nommé Kirk Pepperdine. Nous lui avons soumis notre application, et nous vous exposerons sa méthode d'analyse et les raisons qui la motivent dans le dernier article de la série.
Premier contact avec l'application...
Ouverture du navigateur, entrée de l'url, et, pas de surprise, l'application PetClinic s'ouvre.
Premier lancement de JMeter, et première constatation : avec un seul utilisateur, l'application met en moyenne plus de 2 secondes à répondre. Inacceptable pour la plupart des sites web (surtout avec un seul utilisateur actif).
... et premiers réglages
A première vue, la machine ne semble pas à genoux, on peut donc incriminer directement l'application.
Nous allons donc chercher à savoir ce qu'elle fait. Un réflexe classique, qu'un certain nombre d'entre nous a eu, est d'aller ouvrir les logs. Catalina.out est vide, on n'a pas de répertoire de logs applicatives évident, à priori le coupable classique, la configuration log4j, est à écarter. Et pourtant... Pour savoir ce que fait réellement notre application, il est possible de réaliser une série de thread dumps. Pour cela, deux possibilités :
- la vieille école, qui va dumper le contenu des threads à l'aide d'un kill -3 sur la jvm.
- l'école moderne, qui va utiliser JVisualVm (et ses plugins) pour réaliser la même opération à l'aide d'une belle interface.
Et là, demie surprise, notre thread actif est souvent surpris dans la méthode org.apache.log4j.spi.LoggingEvent.getLocationInformation. Nous aurions donc un logger actif. Nos soupçons initiaux se confirment, ne reste plus qu'à débusquer le coupable.
Nous n'avons pas (encore) le code source. Or, cette bombe plombe tellement l'application qu'il n'est pas envisageable que nous ne puissions pas la résoudre de suite. On doit donc avoir un fichier de paramétrage de la log externalisé. Là encore, VisualVm va nous aider. Dans la fenêtre overview, les paramètres de démarrage de la VM sont affichés. Et l'on voit apparaitre une directive de configuration log4j, -Dlog4j.configuration.
Un petit grep dans le répertoire de lancement de Tomcat ($TOMCAT_HOME/bin), et nous voyons apparaître dans le setEnv.sh la ligne -Dlog4j.configuration=file:$CATALINA_HOME/conf/log.xml. Et si nous ouvrons ce fichier, le root Logger est bien en DEBUG. Mais aucune directive spécifique pour logger ailleurs que dans la console. Tout devrait donc aller dans catalina.out. Ca sent la redirection 'sauvage'. Continuons à parcourir les fichiers de lancement. Un petit tour dans catalina.sh, et surprise, une belle redirection Unix "$CATALINA_BASE"/logs/catalina.out 1> /var/log/catalina/tomcat.log &
Et en ouvrant ce fichier, on comprend mieux le temps perdu : des milliers de lignes de debug !
Celles ci ont d'ailleurs une particularité sympathique : à chaque ligne de debug, le numero de ligne de la classa Java est indiqué.
C'est pratique ! Pourquoi ne met on pas systématiquement en place cette configuration sur nos projets ?
Un petit tour dans la documentation Log4J nous apprend :
Log4J nous prévient, ces méthodes sont sous performantes. Si l'on creuse un peu dans le source, on trouve la classe affichant les pattern %M et %L, org.apache.log4j.spi.LocationInfo, qui contient le constructeur suivant :
Autrement dit, pour chaque ligne de log, Log4J génère une stackTrace pour pouvoir récupérer le numéro de la ligne et le nom de la méthode. Pas vraiment performant.
Modifions donc le pattern et observons le résultat.
- Suppression de %M:%L dans le pattern du Logger
- Temps moyen de 2,3 s à 2,0 s pour 1 utilisateur
- 2 points pour l'équipe qui a trouvé
Toujours concernant ce fichier de log, nous voyons apparaître une ligne ne respectant pas le PatternLayout de Log4J, préfixée par Hibernate, qui trace une requête SQL. Gardons cette ligne en mémoire, nous y repenserons quand nous aurons le code source.
Deuxième amélioration immédiate envisageable, une application, qui plus est en production, ne devrait pas avoir besoin d'un niveau de log aussi fin. Passons le donc à ERROR.
- Logger de DEBUG à ERROR
- Temps moyen de 2,0 s à 1,75 s pour 1 utilisateur
- 1 point pour l'équipe qui a trouvé
Nous avons fait un sort au logger. Mais nous n'en avons pas encore fini avec la configuration out-of-the-box de cette application.
Alors mon petit pronostic pour la suite:
- gzip
- peut etre des synchronized qui font goulet d'etranglement
- pour améliorer les perts multi trheader des tâches
- showSql à false
- lazy à true
- des requêtes HQL trop complexes
- augmenter le pool de connexion SQL
- du @transaction en trop
- un petit cache peut etre
Je suis curieux de savoir ce que vous allez mettre en place pour la suite
@Pronostic: A croire que tu étais présent au XKE ^^
Très bon exercice, qu'il serait intéressant de reprendre... L'appli source est dispo qqpart?
Bonjour,
) ) puis 672 (merveilleux!).
A première vue la démonstration est séduisante, mais lorsqu'on regarde de plus prêt les informations transmises par JMeter, elle devient tout d'un coup beaucoup moins convainquante. En effet, l'essentiel de la démonstration consiste à analyser les améliorations en comparant le temps de réponse moyen du scénario. Ors on peut se demander si c'est vraiment une bonne approche lorsqu'on regarde par exemple les TR moyens de la transaction "Owner details", ils se sont malheureusement dégradés sur le dernier tir (celui bénéficiant de toutes les optimisations décrites dans cette page). Par contre si l'on prend le TR moyen de la transaction "vets", il passe respectivement de 2928 ms à 2818 (jusque là tout va bien
En fait les TR de réponses ne semblent pas vraiment stables et je ne pense pas que l'on puisse conclure que ces 2 optimisations ont, à elles seules, permis de diminuer les temps de réponse d'une façon aussi spectaculaire... Ou alors il faudrait m'expliquer également la raison pour laquelle avec les mêmes optimisations, les TR moyens de certaines transactions augmentent.
Je ne conteste pas l'action visant notamment à diminuer la sollicitation du mécanisme de trace qui peut s'avérer contre productive (surtout lorsqu'on s'interesse à l'exploitabilité de la solution).
J'attends avec impatience le reste de la démonstration!
@JPL
.
Merci pour votre commentaire.
En effet, le temps global de transaction n'est qu'un moyen de mesure parmi d'autres et comme annoncé en préambule, cette démonstration est plus scolaire que "dans les conditions du réel". Cependant, il n'est pas choquant de voir le temps global s'améliorer alors que le temps d'exécution de certaines transactions se dégrade. La levée d'un point de contention peut reporter et / ou mettre en évidence un problème plus loin dans l'enchainement des actions (cf, pour les parisiens, l'A10, avec l'enchainement péage de Saint Arnoult - Cuvette des Ulis
Quoi qu'il en soit, votre remarque est pertinente, pour être exhaustif, il aurait fallu déterminer les scenarii critiques (ceux dont on veut absolument valider la bonne santé), surveiller le comportement aux limites (en particulier en terme de nombres d'utilisateurs), la sollicitation des ressources machines (mémoire, CPU, comportement en environnement distribué)... Encore une fois, il s'agit d'aborder les performances sous le jour d'un exercice didactique, et de donner des pistes et des outils à tous ceux qui ne se sont jamais frotté à ce type de diagnostic.
@Pablo
Soit... Mais j'aurais préféré une conclusion s'attachant à démontrer qu'il s'agit d'actions préalables (une mise en bouche en quelque sorte) plutôt qu'une conclusion trop axée, à mon goût, sur le bénéfice en terme de performance des premières optimisations.
Sans polémique, la démontration reposant sur les problèmes de circulation de l'A10 (que je connais très bien puisque je vis sur la région bordelaise)/péage de St Arnoult/Cuvette des Ulis lorsqu'il n'y a qu'un seul automobiliste sur la route n'est pas très convainquante. (:-))