Optimiser une application JEE : mesurer l’impact sur un cas pratique (3ème partie)

3ème partie de notre saga performance.

Lors de notre dernier article, nous avons pu "faire sauter les verrous" en augmentant le pool de threads qui nous limitait le nombre de traitements simultanés dans la montée en charge. Attardons nous maintenant sur la JVM.

Nous n'allons pas perdre de temps dans le fonctionnement d'une JVM plusieurs articles sauront vous le rappeler très simplement comme le chapitre 3 de cet article qui traite de l'overhead, ou bien celui plus spécifique du fonctionnement de la JVM d'IBM J9.

Partant de cela, allons voir un peu comment la notre préfigure ...

Commençons par activer le port JMX sur notre serveur Glassfish pour introspecter avec un outil de monitoring (plusieurs existent comme JConsole inclue dans le J2SE, VisualVM ...).

1er constat à vide :

La Heap semble sous-dimentionnée : environ 134Mo avec une taille ré-allouable à 256Mo.

Les options de démarrage de notre serveur Glassfish nous confirment cela :

Compte tenu de la charge que nous souhaitons atteindre, la taille de la JVM est aujourd'hui beaucoup trop petite.

Alors maintenant quelle valeur proposer ?

Plusieurs éléments sont à tenir en compte : environnement 64 Bits , en théorie pas de limite de sizing. Les ressources mémoires natives réellement mises à disposition. Enfin le comportement attendu de l'application (lourdeur des traitements - lourdeurs des objets Java manipulés - caches managés ... )

L'article sur le Tuning Tomcat rappelle les conséquences d'un trop grand sizing (Garbage Collection Time Spent)

Nous allons partir sur le sizing suivant :

  • -Xms1024m
  • -Xmx1024m
  • -XX:NewRatio=2  (allocation de la Eden à 1/3 de la taille globale)
  • -XX:PermSize=128mo

Redémarrons notre tir à 300 users :

On constate encore une fois que plus la charge augmente, plus les temps de réponse se dégradent. Et particulièrement sur l'étape 2 de recherche avec une moyenne de 15 secondes (étape qui inclue les requêtes Jdbc).

Aucun signe de saturation de la Heap malgré une augmentation linéaire bien graduée de l'allocation mémoire dûe en partie à la montée de charge du nombre de users ...

Ce comportement pourrait cependant paraître suspect (mauvaise gestion de la Heap), mais ne devrait en aucun cas dégrader les temps de réponse tant que l'espace mémoire est suffisant. Nous y reviendrons plus tard, attardons nous plutôt sur ces problèmes de ralentissement.

Générons un thread Dump à la volée, qui pourrait nous donner des pistes sur ce problème de ralentissement à l'étape 2 : et voilà plusieurs dizaines de threads blockés sur la même méthode [FindOwner] :

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
"http-thread-pool-8080(367)" daemon prio=6 tid=0x0000000010548000 nid=0x351c waiting on condition [0x0000000031ecd000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at com.aliecom.utils.BusinessObjectFactory.sendInformationsByWebServices(BusinessObjectFactory.java:27)
at org.springframework.samples.petclinic.jdbc.SimpleJdbcClinic.findOwners(SimpleJdbcClinic.java:162)
at sun.reflect.GeneratedMethodAccessor457.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:77)
at org.springframework.samples.petclinic.aspects.CallMonitoringAspect.invoke(CallMonitoringAspect.java:65)
at sun.reflect.GeneratedMethodAccessor454.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)

Reste à savoir maintenant si le traitement de cette méthode Java serait l'origine d'un ralentissement quelconque. C'est à ce stade qu'il va être judicieux d'aller introspecter le code de l'application en temps réel, et particulièrement cette fameuse étape2.

Pour cela, à défaut d'avoir outillé une supervision applicative (Application Performance Management), plusieurs outils de profiling peuvent faire facilement l'affaire pour notre besoin.

 

Notre choix s'est porté sur JProfiler de ej-technologie. Nous aurons le temps de passer en revu prochainement les fonctionnalités de cet outil, qui offre de multiples facettes de profiling JEE : JPA, JSP, JMS, JNDI, JDBC ... sur une palette élargie de serveurs d'applications.
Nous en profiterons pour parler des APM nouvelle génération qui intègrent désormais le profiling en complément du monitoring initial.

Déployons l'agent sur notre serveur Glassfish  -agentpath:[JPROFILER_ROOT]\jprofilerti.dll=port=8849 dans domain.xml

Une fois l'agent déployé, lançons à nouveau un test, mais cette fois-ci à charge réduite (20 users simultanés) pour minimiser l'impact de l'overhead causée par JProfiler.

 

A partir de l'interface, traçons la connexion JDBC :

 

Côté temps d’exécution des requêtes, quelques dizaines de millisecondes seulement.

 

Idem si on intègre la requête et la récupération des résultats (serialization/deserialization des résultats) nous ne dépassons pas plus d'1 seconde par appel SQL, loin des 30 secondes constatées lors de notre tir !

 

Nous basculons dans la vue Profiling de méthodes :

 

Et voilà notre problème ! on remarque que sur un appel URL /petclinic/findOwners.do, une méthode BusinessObjectsFactory.sendInformationsByWebServices() est appelée, et prend plus de 4 secondes du temps de la transaction globale.

Après avoir généreusement récupéré un accès SVN, j'accède enfin au code source du WAR :

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
	/**
	 * Loads {@link Owner Owners} from the data store by last name, returning
	 * all owners whose last name <em>starts</em> with the given name; also loads
	 * the {@link Pet Pets} and {@link Visit Visits} for the corresponding
	 * owners, if not already loaded.
	 */
	@Transactional(readOnly = true)
	public Collection findOwners(String lastName) throws DataAccessException {
		List owners = this.simpleJdbcTemplate.query(
				"SELECT id, first_name, last_name, address, city, telephone FROM owners WHERE last_name like ?",
				ParameterizedBeanPropertyRowMapper.newInstance(Owner.class),
				lastName + "%");
		loadOwnersPetsAndVisits(owners);
 
                // Start sending statistics for businessObjects reporting into external application partner 
                BusinessObjectFactory bof = new BusinessObjectFactory();
                akOk = bof.sendInformationsByWebServices(owners);
                // End 
  		return owners; 
	}

On voit bien le découpage de la méthode en 2 parties : la requête SQL (qui comme on a vu, prends quelques millisecondes), et l'appel d'un webservice externe, qui enverrait des statistiques sur le nombre de vétérinaires consultés par jour (plus de 4 secondes de temps d’exécution).

Désactivons cette option (non critique) et lançons à nouveau notre tir :

L'étape 2 a chuté et passe de 14 secondes à moins d'1 seconde

Par contre, le comportement de la Heap est à nouveau confirmé : il y a une augmentation constante et anormale de l'allocation mémoire.

Conclusion 3ème partie

Dans cette étape d'analyse, nous avons redimensionné la taille de la Heap. Nous avons pu constater que les temps de réponse de l'étape de recherche se dégradaient au fûr et à mesure du temps et de la montée du nombre d'utilisateurs.

Le thread dump nous a montré plusieurs threads restant bloqués sur une méthode Java.

Pour affiner cette information, et mesurer le temps d’exécution de cette méthode, nous avons utilisé un outil de profiling Java , en reproduisant le problème à charge réduite.

Enfin, une fois le problème isolé, nous avons relancé notre test pour mesurer l'impact positive du correctif apporté (désactivation de l'appel Webservice externe).

Nous aurions pu nous passer de profiler l'application, en traçant l'appel de la méthode suspecte (Log4j). Cependant, la force de ce genre d'outil réside aussi dans une revue complète des méthodes suspectes, ainsi que plusieurs autres options de profiling que nous vous montrerons prochainement.

Il nous rester maintenant à comprendre le comportement anormale de la Heap et de viser la cible finale de 1000 users simultanés !

 

<<  Optimiser une application JEE : mesurer l'impact sur un cas pratique : partie 1
<<  Optimiser une application JEE : mesurer l'impact sur un cas pratique : partie 2

 

Laisser un commentaire

Merci d'effectuer cette opération simple pour valider le commentaire *

Mots-clés
RSS Feed