JavaPerf Consulting joue à son tour les démineurs (tests de performance 1ère partie)

A l’instar de travaux déjà menés par une société de conseil (« rendons à César ce qui appartient à César »… et à Xebia ce qui est à Xebia), nous avons également souhaité vous démontrer, sur un cas d’école très simple, la démarche de diagnostic et d’optimisation des performances d’une application JEE. L’application minée par nos soins est une application web de vente d’animaux appelée « jpetstore ». La version installée s’appuie sur la couche  ORM IBatis. Elle est déployée sur un serveur Tomcat 5.5 /JVM 1.6. Les données sont stockées dans une base de données MySQL 5.

La version originale de cette application est plutôt très performante et monte très bien en charge.  Comme nous sommes de mauvais élèves nous avons truffé cette version de l’application de différents bogues ou problèmes de configuration de l’infrastructure.

Des scripts JMeter ont été également développés pour pouvoir tester l’application et mettre en exergue les différents dysfonctionnements.  Le scénario implémenté simule l’identification d’un internaute la commande de deux animaux de compagnie, la consultation détaillée d’une commande, puis la déconnexion de l’utilisateur.

Durant cet exercice nous ferons également appel à un outil que notre lab a développé pour nous aider dans cette tâche qui peut devenir relativement complexe lorsqu’il s’agit par exemple de déboguer le code applicatif. Il s’agit plus précisément d’un agent développé en java que nous allons déployé sur le serveur Tomcat. L’agent va instrumenter le code à la volée et restituer de façon sommaire des informations très précieuses nous permettant d’établir ou de consolider un diagnostic très précis. Nous utiliserons également l’outil VisualVM 1 .3 qui nous fournira quelques indicateurs tout aussi importants.

Nous lançons l’application… La page d’accueil s’affiche, tout semble fonctionner parfaitement.

La première étape consiste à lancer un test de performance avec un seul utilisateur pour nous assurer du fonctionnement de l’application (une seule itération sur le scénario jmeter est suffisante).

A la première itération, nous constatons des temps de réponse plus importants qui correspondent à la transformation des JSP en code Java et la compilation du code généré et à l’initialisation de différents composants.

Nous illustrons plus tard ce mécanisme à l’aide de l’agent que nous avons développé.

Pour le moment nous nous contentons de constater des temps de réponse très intéressants sur la seconde tentative illustrée ci-dessous.

Nous avons donc des temps de réponse de référence qui nous servirons de base de travail lors des tests de performance suivants.

Avant d’en finir avec cette première étape nous allons valider ces premiers résultats en exécutant un nouveau test de charge avec dix utilisateurs virtuels successifs (soit un utilisateur exécutant plusieurs itérations).

On constate que sur certaines transactions les temps de réponse ne sont pas conformes aux premiers résultats. Pourtant il ne peut pas y avoir de contentions applicatives dans ces conditions de tests. Bien que tous les composants soient déployés sur la même machine, la vérification de l’utilisation des ressources systèmes n’indique pas de problème de saturation quelconque.

A ce stade, sans outillage supplémentaire il n’est pas possible de savoir précisément ce qui se passe dans notre application. Or nous avons l’agent que notre lab a développé. L’installation est très rapide et l’overhead très faible puisque seulement quelques classes et méthodes sont instrumentées. Nous allons franchir le pas pour élucider ce premier mystère.

Le déploiement de l’agent est très rapide, nous insérons la ligne -javaagent:</path/installation/javaperf_agent.jar> dans le script de lancement du serveur tomcat et nous relançons le serveur.
Après une phase d’initialisation nous constatons que notre agent nous indique qu’une méthode particulière de l’application est au cœur de notre premier constat. Cette méthode consomme l’essentiel du temps de réponse. Dans l’exemple ci dessous la méthode getItem() s’exécute en 1516 ms sur 1520 ms nécessaires au traitement de la requête. Le temps d’exécution « inherent » est équivalent au temps d’exécution total de la méthode (le concept du temps « inhérent » est simple mais difficile à expliquer clairement, en simplifiant il s’agit du temps d’exécution d’une méthode à l’exception du temps d’exécution des méthodes appelées) . Ce constat nous indique que la méthode concernée est celle qui pose problème. Le temps cpu cumulé n’étant pas équivalent au temps d’exécution de la méthode, on peut supposer que la méthode concernée réalise des opérations d’entrée/sortie.
Nous ne préciserons pas davantage la signification des autres indicateurs qui ne sont pas valorisés dans la trace suivante mais sachez que l’agent est en mesure de mesurer l’impact d’un gc sur le temps d’exécution d’une méthode, ou qu’il peut préciser la durée de blocage et/ou d’attente d’une méthode, etc.

Exemple de trace de l’agent
com.ibatis.jpetstore.persistence.sqlmapdao.ItemSqlMapDao.getItem(..) execution time=1516, inherent time=1516, time in called method=0, cumuled cpu time=1467, inherent cpu time=1451, blocked time=0, inherent blocked time=0, waited time=0, inherent waited time=0, gc time=0, inherent gc time=0, gc count=0, inherent gc count=0, events =[]

Un regard sur le code de la méthode nous indique que la méthode getItem() fait appel à la méthode synchronisée getImage() de la classe UtilIO non supervisée par l’agent. Cette méthode récupère l’image d’un animal octet/octet à partir d’un fichier déployé dans l’application. Or certaines images qui ont un poids de plusieurs centaines de kilos génèrent ces temps de réponse hors norme comme l’indique la trace suivante.

loading file ../images/cat3.gif take 20 ms. size is 5024
loading file ../images/dog4.gif take 48 ms. size is 12267
loading file ../images/lizard3.gif take 30 ms. size is 4759
loading file ../images/bird1.bmp take 1512 ms. size is 368254

loading file ../images/dog5.gif take 81 ms. size is 12703
loading file ../images/bird2.bmp take 1490 ms. size is 368254

Extrait du code de la classe ItemSqlMapDao
public Item getItem(String itemId) {
Integer i = (Integer) queryForObject(« getInventoryQuantity », itemId);
Item item = (Item) queryForObject(« getItem », itemId);
item.setQuantity(i.intValue());
//  Récupération du nom de l’image et recuperation

byte[] img = getImage(filename);
//
return item;
}

private byte[] getImage(String filename)
{
// construction du chemin d’accès au fichier

return UtilIO.getImage(newFilename, path);
}

Nous supprimons donc l’invocation de la méthode getImage() qui n’a pas de valeur ajoutée dans l’application (ce n’est qu’une petite mine posée par nos soins). Notons que nous n’aurions pas pu résoudre ce premier problème sans notre agent (sauf à avoir beaucoup de chance lors de la génération des threads dump).

Une nouvelle prise de mesure nous indique que tout semble désormais fonctionner.

Nous allons donc procéder à la seconde étape dans cet audit de performance : Nous allons monter légèrement en charge pour valider les résultats précédents.

http://www.jperf.com

Publicités

A propos jlerbsc

founder of JavaPerf Consulting Http://www.jperf.com
Cet article a été publié dans performance. Ajoutez ce permalien à vos favoris.

Laisser un commentaire

Entrez vos coordonnées ci-dessous ou cliquez sur une icône pour vous connecter:

Logo WordPress.com

Vous commentez à l'aide de votre compte WordPress.com. Déconnexion / Changer )

Image Twitter

Vous commentez à l'aide de votre compte Twitter. Déconnexion / Changer )

Photo Facebook

Vous commentez à l'aide de votre compte Facebook. Déconnexion / Changer )

Photo Google+

Vous commentez à l'aide de votre compte Google+. Déconnexion / Changer )

Connexion à %s