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 :

public LocationInfo(Throwable t, String fqnOfCallingClass) {
if(t == null || fqnOfCallingClass == null)
return;

String s;
// Protect against multiple access to sw.
synchronized(sw) {
t.printStackTrace(pw);
s = sw.toString();
sw.getBuffer().setLength(0);
}
[...]

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.

Source

Image libre de droits