JAVAPERF CONSULTING joue les démineurs (tests de performance – 2ème partie)

Pour votre information, nous sommes actuellement en train de faire évoluer la plateforme de tests qui nous a permis d’élaborer ce document. Prochainement nous mettrons à jour cet article avec des informations plus pertinentes.

Continuons l’audit de performance de notre application « vérolée » par nos soins dans un but didactique. Certes vous constaterez au cours de cet exercice que les temps de réponse obtenus dans 90% des cas restent plutôt très bons. Cela est probablement lié au mode de déploiement de l’application ou tous les composants sont co-localisés, à la faible volumétrie des données et à une infrastructure de tests sous dimensionnée qui ne nous permet pas de monter significativement en charge. Pourtant vous pouvez nous faire confiance, nous avons volontairement introduit un paramétrage susceptible de poser beaucoup de problèmes de montée en charge. Ces problèmes auraient été accentués si nous avions pu faire des simulations avec un nombre d’utilisateurs virtuels plus important.

La seconde étape de notre analyse des performances consiste à monter légèrement en charge afin de vérifier que notre application web fonctionne toujours aussi bien lorsque l’activité devient plus importante.

Ajustement du niveau de trace

Nous procédons donc à un nouveau test de charge configuré pour lancer simultanément 5 utilisateurs virtuels chacun exécutant 10 fois le scénario. Pour élaborer cet article, nous ajustons également les temps d’attente entre chaque transaction (think time) afin d’accélérer la découverte de problèmes potentiels.

tests de charge JavaPerf Consulting

JavaPerf Consulting joue les démineurs d'une application web

Nous constatons une légère augmentation des temps de réponse moyens, en percentile, et des temps de réponse maximaux. Par exemple le « 90e centile » de la transaction « LIST ORDERS » a augmenté de 735%, celui de la transaction « LOGIN » de 156%, etc. Heureusement, à l’aide de VisualVM nous avons pris soin de faire quelques threads dump qui vont peut être nous permettre d’expliquer ce phénomène.

En effet les quelques threads « utilisateur »,  surpris par notre action, sont en train d’exécuter à peu près la même fonctionnalité. Il s’agit de la journalisation d’une trace avec un niveau de verbosité de très bas niveau « DEBUG ».

« http-127.0.0.1-8080-8 » daemon prio=6 tid=0x0d01d000 nid=0x3fd4 runnable [0x0e37f000]    java.lang.Thread.State: RUNNABLE
                        at java.io.FileOutputStream.writeBytes(Native Method)
                        at java.io.FileOutputStream.write(FileOutputStream.java:260)
                        at
java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
                        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
                        – locked <0x046eff70> (a java.io.BufferedOutputStream)
                        at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:278)
                        at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122)
                        – locked <0x046ef8e0> (a java.io.OutputStreamWriter)
                        at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212)
                        at java.io.PrintWriter.flush(PrintWriter.java:276)
                        – locked <0x046ef8e0> (a java.io.OutputStreamWriter)
                        at org.apache.juli.FileHandler.publish(FileHandler.java:141)
                        at java.util.logging.Logger.log(Logger.java:458)
                        at java.util.logging.Logger.doLog(Logger.java:480)
                        at java.util.logging.Logger.logp(Logger.java:596)
                        at org.apache.commons.logging.impl.Jdk14Logger.log(Jdk14Logger.java:99)
                        at org.apache.commons.logging.impl.Jdk14Logger.debug(Jdk14Logger.java:114)

Un coup d’œil rapide sur l’onglet « overview » de VisualVM nous indique que l’application web utilise le composant de log du JDK et nous fournit le chemin d’accès au fichier de configuration.

Deux éléments nous interpellent dans le fichier de configuration de l’API de log.  Nous y trouvons non seulement la déclaration de 2 handlers (la sortie standard, et un fichier), mais également un niveau de trace très verbeux défini pour certaines API. Un rapide regard sur le fichier de log nous confirme que la verbosité est trop élevée. Ceci a pour conséquence de rendre quasiment inexploitables les informations présentes dans le fichier.

.handlers = 1catalina.org.apache.juli.FileHandler, java.util.logging.ConsoleHandler

org.apache.catalina.level=FINEorg.apache.struts.level=FINEST
com.ibatis.level=FINEST
java.sql.Connection.level=FINEST
java.sql.PreparedStatement.level=FINEST

Nous allons donc reconfigurer le composant de trace en déclarant un seul handler (FileHandler), et un niveau de log facilitant la lecture des traces.

Une nouvelle prise de mesure nous confirme, si nous avions un doute, qu’un mauvais paramétrage de la verbosité des logs peut avoir un impact sur les performances d’une application, sur son exploitabilité, et potentiellement sur sa stabilité.

Notons que les 96% d’erreurs sur la transaction « LOGIN » donne lieu à la création de nouveaux utilisateurs. Il s’agit de la simulation d’un utilisateur réalisant un premier achat.

Ajustement des paramètres iBatis

Un nouveau test de charge est exécuté pour valider de nouveau le comportement de l’application lorsque l’activité augmente. Ce test est réalisé avec 10 utilisateurs virtuels réalisant chacun 10 itérations.

Ce nouveau test nous montre de nouveau une dégradation des performances et les threads dump que nous avons pris de façon préventive illustrent un nouveau problème. Plusieurs threads sont en attente d’un moniteur lors du démarrage d’une session/transaction iBatis.

« http-127.0.0.1-8080-11 » daemon prio=6 tid=0x0d2b7000 nid=0x3d50 in Object.wait() [0x0f5be000]    java.lang.Thread.State: WAITING (on object monitor)
                        at java.lang.Object.wait(Native Method)
                        at java.lang.Object.wait(Object.java:485)
                        at com.ibatis.common.util.Throttle.increment(Throttle.java:44)
                        – locked <0x04ab14b0> (a java.lang.Object)
                        at com.ibatis.common.util.ThrottledPool.pop(ThrottledPool.java:24)
                        at com.ibatis.sqlmap.engine.impl.SqlMapExecutorDelegate.popSession(SqlMapExecutorDelegate.java:539)
                        at com.ibatis.sqlmap.engine.impl.SqlMapSessionImpl.<init>(SqlMapSessionImpl.java:34)
                        at com.ibatis.sqlmap.engine.impl.SqlMapClientImpl.getLocalSqlMapSession(SqlMapClientImpl.java:169)
at com.ibatis.sqlmap.engine.impl.SqlMapClientImpl.startTransaction(SqlMapClientImpl.java:87)

Quelques recherches supplémentaires dans la documentation iBatis indiquent que nous sommes en présence d’une veille version de l’ORM. Dans cette version l’on pouvait encore spécifier les 3 paramètres suivants.

maxRequests A request is any SQL operation—an insert, update, delete, or a stored procedure Call (the default value of 512).
maxSessions A session is a thread-level mechanism that is used to track information about a group of related transactions and requests (the default value of 128).
maxTransactions A transaction is just what it appears: a database transaction (the default value of 32).

Notre application est configurée avec les paramètres suivants :
maxRequests=1
maxTransactions=1
maxSessions=1

Par curiosité intéressons nous également aux résultats fournis par notre solution de diagnostic. Ci-dessous la trace tronquée illustrant ce dysfonctionnement.

Wed Mar 21 18:27:16 CET 2012 http-127.0.0.1-8080-7 INFO jperf: org.apache.struts.action.ActionServlet.doGet execution time=425 inherent time=0 time in called method=425, cumuled cpu time=0 inherent cpu time=0 blocked time=0 inherent blocked time=0 waited time=421 inherent waited time=0 gc time=7 inherent gc time=0 gc count=5 inherent gc count=0 events =[type=HTTP,contents=[/jpetstore/shop/newOrderForm.shtml]]

com.ibatis.dao.engine.impl.DaoContext.startTransaction(…) execution time=423 inherent time=0 time in called method=423, cumuled cpu time=0 inherent cpu time=0 blocked time=0 inherent blocked time=0 waited time=421 inherent waited time=0 gc time=7 inherent gc time=0 gc count=5 inherent gc count=0 events =[]
com.ibatis.dao.engine.transaction.sqlmap.SqlMapDaoTransactionManager.startTransaction(..) execution time=423 inherent time=421 time in called method=2, cumuled cpu time=0 inherent cpu time=0 blocked time=0 inherent blocked time=0 waited time=421 inherent waited time=421 gc time=7 inherent gc time=7 gc count=5 inherent gc count=5 events =[]

Encore une fois notre agent identifie précisément l’origine du problème. Dans ce cas précis le temps d’exécution de la méthode constituant le point d’entrée (requête Http) est de 425 ms. La méthode SqlMapDaoTransactionManager.startTransaction(…) s’exécute en 421 ms (inherent time) et 421 ms sont consacrées à attendre quelque chose (inherent waited time).

L’exercice n’est pas encore terminé… et nous ne sommes pas au bout des surprises.

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