Publié par

Il y a 10 ans -

Temps de lecture 7 minutes

Performance, les Xebians jouent les démineurs 2

Suite de nos investigations sur l’application PetClinic dégradée.

Après une première passe qui nous a permis de calibrer les logs de manière un peu plus pertinente, il est temps, toujours sans l’aide du code source, de mettre les mains sous le capot de Tomcat (6.0.20).

Et pour cela, rien de mieux que de jeter de nouveau un œil à notre VisualVm.

Tant de threads pour un seul utilisateur.

Pour (re)commencer, penchons nous sur nos threads, juste après le démarrage du serveur (et donc avant la première connexion d’un utilisateur)

threadsOverview

Lorsque l’on démarre un serveur Tomcat, un certain nombre de threads sont affectés à sa ‘tuyauterie’ interne (connecteurs RMI, JMX). Mais de là à avoir 165 threads, il y a certainement un souci quelque part !
Creusons un peu, et entrons dans le détail de ces threads en utilisant l’onglet Threads.

threadsDetails

Hormis les threads ‘connecteurs’ de Tomcat, on voit apparaître 150 threads catalina-exec. Ces threads sont en charge des traitements des requêtes HTTP, via le HTTP-8080-acceptor. Nous avons donc, « à froid » 150 unités d’œuvre prêtes à traiter nos requêtes. Sachant que pour l’instant nos tests se limitent à un utilisateur, on sent que nous sommes très légèrement surarmés par rapport à nos besoins.
Tomcat ne devrait-il pas gérer automatiquement ces problématiques de montée ou descente en charge ?
Allons faire un petit tour dans la documentation, du côté du connecteur HTTP.

httpConnector

Si nous recherchons le paramètre minSpareThreads dans nos fichiers de configuration, nous le trouvons dans server.xml. Repassons le à une valeur plus réaliste de 10 threads, sachant que Tomcat montera automatiquement en charge si besoin.
Cela n’a pas d’impact visible sur les performances, mais au moins, les ThreadDumps deviennent lisibles (obfusquer les ThreadDumps était le but recherché de ce paramétrage).
Autre paramètre qui a interpellé les connaisseurs de Tomcat, la classe de l’Executor. org.apache.catalina.core.extended.PrestartingThreadExecutor n’est pas une classe courante. D’habitude, on utilise plutôt le StandardThreadExecutor. Une fois encore, on peut remercier nos buggers en chef : PrestartingThreadExecutor est une classe custom, qui démarre automatiquement tous les threads HTTP. De nouveau, l’impact sur les performances est négligeable pour un utilisateur, mais mieux vaut laisser Tomcat gérer toutes les problématiques de vie du serveur d’application. Sans vouloir leur faire offense, nos maîtres de cérémonie n’ont pas le niveau des équipes Apache rodées à l’exercice depuis de très nombreuses années ;)
Dernier paramètre « malin » introduit au niveau de Tomcat, le paramètre -Xss. Celui-ci peut être découvert via l’overview de VisualVm. -Xmx, -Xms sont des paramètres classiques (nous reviendrons dessus) que grand nombre de développeurs connaissent. Mais -Xss ? Comme d’habitude, notre meilleure arme est la documentation de Sun.

-Xssn
    Set thread stack size.

Avons nous réellement besoin d’une taille de stack de 1024 Ko ? Difficile à dire, surtout a priori. Mais une fois encore, le plus simple est de faire confiance à Tomcat, quitte à devoir intervenir a posteriori. Nous ne sommes plus à un redémarrage près.

Maintenant que notre application est déployée et paramétrée de manière à peu près correcte, il est temps de rentrer « dans le dur » : mettre les mains dans le cambouis et explorer le code source.

Fuite mémoire, threads dump, ça explose de tous les côtés.

Dès que nous avons eu le code source entre les mains, plusieurs stratégies se sont dégagées :

  • la première consiste à conserver un seul utilisateur dans les scripts JMeter et à le pousser à faire plus d’itérations,
  • la seconde consiste à mettre plus d’utilisateurs JMeter en parallèle.

Toujours dans le but de rester très didactique, nous allons appliquer la première stratégie. Qui trouve rapidement sa limite :

Aux environs de la 70ème itération, la heap used tangente la heap max, le Garbage Collector est déclenché plusieurs dizaines de fois par seconde de manière totalement inefficace, et la JVM finit par faire un joli OutOfMemory. Les symptômes classiques de la fuite mémoire.

memoryLeak

Comment faire pour la trouver ?
C’est à la fois simple et complexe : depuis la JVM 6, il est très facile, grâce à VisualVm de réaliser des « photographies » exhaustives de la mémoire de la JVM, les célèbres heap dumps. Malheureusement, ce n’est possible que sur les JVM locales.
Conformons nous donc à l’énoncé et n’installons pas notre Tomcat en local. La solution consiste à utiliser la commande jmap.
Commençons par générer un histogramme, que nous allons filtrer.
jmap -histo <pid_jvm> | grep org.spring
Notre premier candidat arrive en 16ème position dans l’histogramme :
16: 14000 560000 org.springframework.samples.petclinic.Vet
14 000 vétérinaires, voilà qui est surprenant… De là à dire que notre fuite tourne autour de cet objet métier, il n’y a qu’un pas. Malheureusement, à part en allant dans le code à la pioche, il va être difficile de colmater la fuite avec aussi peu d’information. De nouveau, jmap va nous rendre service, cette fois en générant un heap dump.
jmap -dump:format=b,file=/tmp/dump.hprof <pid_jvm>
Pour exploiter ce dump, nous avons choisi d’utiliser l’outil Eclipse Mat. Dès l’ouverture, Mat nous propose de rechercher les leak suspects
Et là, le diagnostic est assez évident.

leakMat

Un type d’objet monopolise à lui seul 92 % de la mémoire. Il ne reste plus qu’à creuser dans le heap dump pour déceler l’allocation coupable.
Passons donc à la vue dominator tree. En dépliant progressivement la pile mémoire (en cliquant sur l’objet qui a la plus grande retained heap), on constate que la mémoire est occupée par de très nombreuses occurences de org.springframework.samples.petclinic.util.CacheFilter$CacheEntry

memoryLeakMat

Maintenant que nous avons un coupable, il est temps, pour la première fois, d’ouvrir notre code source sous Eclipse. En faisant une simple recherche de classe sur notre coupable désigné, nous arrivons au code suivant :

HttpSession session = request.getSession();
Map<String, CacheEntry> cache = (Map<String, CacheEntry>) session.getAttribute("pages.cache");
if (cache == null){
    cache = new Hashtable<String, CacheEntry>();
    session.setAttribute("pages.cache", cache);
}

...

//Return cached content if available
String path = context.getRealPath("") + request.getRequestURI() + request.getQueryString();
CacheEntry cacheEntry = cache.get(path);
if (cacheEntry != null) {
    response.setContentType(cacheEntry.t);
} else {
    //Else, fetch it
    cacheEntry = new CacheEntry();
    CacheResponseWrapper wrapper = new CacheResponseWrapper(response);
    chain.doFilter(request, wrapper);
            
    byte[] buf = cacheEntry.buf;
    InputStream in = wrapper.getContentAsInputStream();
    OutputStream out = cacheEntry.c;
    int length;
    while((length = in.read(buf)) >= 0) {
        out.write(buf, 0, length);
    }
            
cacheEntry.t = wrapper.getContentType();
cache.put(path, cacheEntry);
}

Chaque page est donc mise en cache dans la session de l’utilisateur. Le timeout du cache étant fixé à l’infini, on voit de manière assez évidente que chaque fois que notre JMeter lance une campagne de test, il ouvre une nouvelle Session dans laquelle l’ensemble des pages vues est gardée en mémoire (avec un taux de réutilisation proche de zéro).
L’utilisation des ressources mémoire de notre JVM est ici particulièrement mauvaise.
Deux solutions sont envisageables :

  • basculer le cache dans un scope application. Mais dans ce cas, attention, la taille de celui-ci peut vite exploser et l’utilisation d’un filtre qui cache systématiquement tout le contenu de la réponse peut rapidement échapper à tout contrôle.
  • supprimer purement et simplement ce cache dont le taux de hit est ridiculement bas. C’est la solution que nous choisirons ici, car c’est la plus économique (une ligne à commenter dans le web.xml).

Cette correction ne devrait toutefois pas affecter notre nombre élevé de Vets trouvés via l’histogramme… Nous y reviendrons probablement.

Ne reste alors plus qu’à re-construire (via Maven) et relivrer l’application pour voir le résultat.

Cette fois, le gain de performance ne se mesure pas directement dans JMeter. Les temps de réponse de l’application sont sensiblement identiques à ce qu’ils étaient avant nos interventions.

En revanche, nous avons largement gagné en performance dans deux domaines :

  • le plus immédiat, celui du ressenti utilisateur : plus la peine de rebooter notre serveur tous les 70 scenarii, et ça toutes les équipes d’exploitation vous le diront (sauf les mauvais élèves qui ont bêtement automatisé leurs redémarrages), c’est un énorme gain.
  • celui plus égoïste, d’avoir des traces propres et peu nombreuses, donc beaucoup plus exploitables.

Pour finir, les points attribués :

  • Fuite mémoire de CacheFilter en session
  • Passage de la barre des 70 scenarii pour 1 utilisateur
  • 2 points pour l’équipe qui a trouvé

Comme l’a très bien pressenti l’un de nos lecteurs (voir les commentaires sur l’article précédent), nous ne sommes pas encore au bout de nos surprises

Publié par

Publié par Pablo Lopez

Pablo est directeur technique chez Xebia et formateur Hadoop certifié par Cloudera au sein de Xebia Training .

Commentaire

2 réponses pour " Performance, les Xebians jouent les démineurs 2 "

  1. Publié par , Il y a 10 ans

    Bravo pour l’article.

    Visualvm j’avoue je n’y aurais pas pensé.

  2. Publié par , Il y a 10 ans

    Super article, très didactique et instructif.

    J’attend le happy end avec impatience :p

Laisser un commentaire

Votre adresse de messagerie ne sera pas publiée. Les champs obligatoires sont indiqués avec *

Nous recrutons

Être un Xebian, c'est faire partie d'un groupe de passionnés ; C'est l'opportunité de travailler et de partager avec des pairs parmi les plus talentueux.