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

Depuis un certain temps, on vous propose plusieurs articles allant d'une démo avancée d'un outil de performance, jusqu'à des mises en situation poussant l'analyse de fuites mémoires dans ses retranchements.

Nous allons vous proposer un cas pratique, décrivant une intervention d'audit de performance, l'histoire d'une application critique pour laquelle on déplore de gros problèmes de performances.

Partant de ce postula, nous allons tenter de vous proposer une approche méthodique par laquelle nous aborderons chaque étape comme des étapes significatives dans l'augmentation de gains en performance.

Le contexte :

Voici le scénario de notre histoire, quelque peu romancée au passage mais qui reste à l'image de nombreuses situations réelles déjà rencontrées !

Une fédération de syndicats Vétérinaires de France a mis au point une application web déployée sur tout le territoire national, permettant de tracer l'ensemble des actes médicaux effectués sur nos animaux domestiques (ex : un rendez-vous chez le vétérinaire, un suivi d'intervention ... une sorte de carnet de santé numérique).

 

Pour cela, nous nous appuierons sur l'application Petclinic de Spring Source.

Évidemment la phase de déploiement a déjà été faite sur la plupart des régions de France, ce qui porte aujourd'hui la charge réelle de production à :

  • une base de données de plusieurs milliers de vétérinaires (environ 3 000 lignes)
  • un référentiel de plusieurs millions clients (environ 10M de lignes)
  • une table de suivi de plusieurs millions de lignes (environ 100M de lignes)
  • un pic journalier d'utilisation de la plateforme à environ 1000 vétérinaires connectés simultanément.

Constat et Objectifs :

 

Service indisponible : fédération en panique, vétérinaires alarmés !
Actuellement, l'application n'est plus utilisable en l'état.
L'impact financier commence à se faire sentir, d'autant plus que la fédération propose actuellement ce service gratuitement, dans l'optique de proposer un abonnement payant à terme. La question à ce jour ne se pose même plus !

Les simples critères de tolérance sont loin d'être remplis :

des temps de réponse alarmants sur plusieurs étapes (plusieurs secondes voir dizaines de secondes d'attente avant affichage)

plusieurs crash du serveur d'application par semaine nécessitant un redémarrage de l'instance

le constat que les ressources systèmes dédiées à l'application sont anormalement élevées. (peu de marge de manœuvre)

Notre objectif : améliorer la robustesse du système, et en mesurer directement l'impact utilisateur.

meilleur rendu utilisateur : amélioration des temps de réponse par des actions correctives si besoin

meilleure gestion des ressources systèmes et applicatives

propositions d'évolutions en terme de scalabilité, en vue d'absorber une charge supplémentaire importante

L'architecture technique  :

L'approche qui va être démontrée dans cette article côté "serveur Glassfish" reste applicable à n'importe quel autre serveur Tomcat, JBoss, Weblogic, Websphere ...

Aucun APM en vue déployé en production.
A défaut d'avoir un véritable outil de supervision et de monitoring de production (sans parler de Appdynamics ou Dynatrace, Centreon aurait été bienvenue ...), nous nous armons de notre palette d'outils de monitoring Jmx, analyser de ThreadDump et HeapDump.

 

Let's Go !

On enfile les gants , prêt à mettre les mains dans le cambouis.

Après être allé à la pêche aux infos sur la manière dont est utilisé Petclinic, on se rend compte très rapidement qu'un seul scénario devrait couvrir l'ensemble des cases :

1. [Page d'accueil]

2. [Rechercher un animal par nom de son propriétaire]

3. [Sélectionner la personne dans la liste de résultat]

4. [Afficher le détail de la fiche client]

Nous n'irons pas plus loin dans la complexité du scénario, sachant pertinemment que nous allons être confronté aux problèmes rien qu'avec ce script.

Dans cette 1ère étape, on va chercher à reproduire le comportement de l'application avec une charge très limitée : commençons par 40 utilisateurs connectés simultanément, avec des temps de pause d'environ 5 secondes entre chaque étape.

 

Les premiers constats sont effectivement inquiétants :

On constate que l'étape 2 "Recherche par nom" prend en moyenne près de 27 secondes, et reste très étroitement liée à l'augmentation de la charge. Moi qui pensait que 40 utilisateurs seraient une formalité, je me dis que la route est encore longue avant d'attendre les 1000 ....

Continuons en allant jeter un œil sur la partie système :

 

En faisant une revue rapide des ressources systèmes allouées au process Java , on remarque une activité anormalement élevée de l'accès disque : plusieurs 100Ko d'écriture par seconde de manière régulière. Ce qui laisse supposer une activité d'écriture importante sur les disques.

Le moniteur Windows nous montre facilement dans son compte-rendu, que les fichiers impactés par cette activité d'IO sont ni plus ni moins les fichiers de sorties de logs standards de Glassfish (server.log)

Effectivement le taux de remplissage des fichiers de logs est anormalement élevé, et quand on édite un de ces fichiers  :

1
2
3
4
5
6
7
8
9
10
11
12
[#|2012-11-08T21:30:32.002+0100|INFO|glassfish3.1.2|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=27;_ThreadName=Thread-3;|[TopLink Fine]: 2012.11.08 09:30:32.002--ServerSession(1118540264)--Connection(1834074860)--Thread(Thread[http-thread-pool-8080(8),5,grizzly-kernel])--SELECT ID, BIRTH_DATE, NAME, OWNER_ID, TYPE_ID FROM PETS WHERE (OWNER_ID = ?)
bind => [44836]
|#]
[#|2012-11-08T21:30:32.002+0100|INFO|glassfish3.1.2|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=28;_ThreadName=Thread-3;|[TopLink Fine]: 2012.11.08 09:30:32.002--ServerSession(1118540264)--Connection(1179401710)--Thread(Thread[http-thread-pool-8080(9),5,grizzly-kernel])--SELECT ID, BIRTH_DATE, NAME, OWNER_ID, TYPE_ID FROM PETS WHERE (OWNER_ID = ?)
bind => [44736]
|#]
[#|2012-11-08T21:30:32.049+0100|INFO|glassfish3.1.2|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=22;_ThreadName=Thread-3;|[TopLink Fine]: 2012.11.08 09:30:31.815--ServerSession(1118540264)--Connection(1894599577)--Thread(Thread[http-thread-pool-8080(5),5,grizzly-kernel])--SELECT ID, VISIT_DATE, DESCRIPTION, PET_ID FROM VISITS WHERE (PET_ID = ?)
bind => [4527]
|#]
[#|2012-11-08T21:30:32.049+0100|INFO|glassfish3.1.2|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=27;_ThreadName=Thread-3;|[TopLink Fine]: 2012.11.08 09:30:32.002--ServerSession(1118540264)--Connection(1665498934)--Thread(Thread[http-thread-pool-8080(8),5,grizzly-kernel])--SELECT ID, VISIT_DATE, DESCRIPTION, PET_ID FROM VISITS WHERE (PET_ID = ?)
bind => [44849]
|#]

On constate que chaque requête SQL est tracée, ce qui représente des centaines de milliers de lignes par minutes ! Ce qui confirme bien la lenteur de l'étape 2 qui est une étape de recherche en base de données.

Allons faire un tour sur la configuration des logs côté Glassfish :

Surprise ! java.util.logging.ConsoleHandler=INFO

Si nous allons dans le logging.properties de Glassfish, on voit bien que ConsoleHandler est le handler par default :

1
2
3
handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.formatter=com.sun.enterprise.server.logging.UniformLogFormatter
com.sun.enterprise.server.logging.GFFileHandler.logFormatDateFormat=yyyy-MM-dd'T'HH\:mm\:ss.SSSZ

Un petit tour sur l'excellent référentiel Oracle tuning Glassfish  et particulièrement sur la partie Logger Settings pour bien comprendre l'importance de limiter les niveaux de logs , particulièrement en environnement de Production. Vegard Skjefstad en fait un cheval de bataille dans sa synthèse GlassFish Production Tuning.

Modifions java.util.logging.ConsoleHandler=WARNING

Arrêt/redémarrage du serveur pour prise en compte des modifications, le constat est évident :

Impact importante sur les temps de réponse: passage de 27 sec à moins de 5 sec sur l'étape 2 !

Chute de l'activité des IO qui se retrouve diminué par 12 !

Avis aux plus curieux : avant de modifier les paramètres de niveau de logs, je me suis permis de faire un ThreadDump en pleine charge pour en analyser le comportement des threads actifs. Je suis tombé sur 5 Threads BLOCKED, en attente de la même chose : écrire dans la log du server à l'étape 2,  findOwners() que l'on voit en dernière ligne de cette Stack.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:662)
 
   Locked ownable synchronizers:
	-  (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
 
"http-thread-pool-8080(10)" daemon prio=6 tid=0x000000001c24c800 nid=0x29c8 waiting for monitor entry [0x000000001e90c000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at oracle.toplink.essentials.logging.DefaultSessionLog.log(DefaultSessionLog.java:85)
	- waiting to lock  (a oracle.toplink.essentials.logging.DefaultSessionLog)
	at oracle.toplink.essentials.internal.sessions.AbstractSession.log(AbstractSession.java:1992)
	at oracle.toplink.essentials.internal.sessions.AbstractSession.log(AbstractSession.java:2883)
	at oracle.toplink.essentials.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:466)
	at oracle.toplink.essentials.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:437)
		at oracle.toplink.essentials.queryframework.ObjectLevelReadQuery.executeDatabaseQuery(ObjectLevelReadQuery.java:709)
	at oracle.toplink.essentials.queryframework.DatabaseQuery.execute(DatabaseQuery.java:609)
	at oracle.toplink.essentials.queryframework.ObjectLevelReadQuery.execute(ObjectLevelReadQuery.java:677)
	at oracle.toplink.essentials.internal.sessions.AbstractSession.internalExecuteQuery(AbstractSession.java:1815)
	at oracle.toplink.essentials.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:937)
	at oracle.toplink.essentials.internal.indirection.NoIndirectionPolicy.valueFromQuery(NoIndirectionPolicy.java:235)
	at oracle.toplink.essentials.mappings.ForeignReferenceMapping.valueFromRowInternal(ForeignReferenceMapping.java:953)
	at oracle.toplink.essentials.mappings.ForeignReferenceMapping.valueFromRow(ForeignReferenceMapping.java:890)
	at oracle.toplink.essentials.mappings.DatabaseMapping.readFromRowIntoObject(DatabaseMapping.java:1007)
	at oracle.toplink.essentials.internal.descriptors.ObjectBuilder.buildAttributesIntoObject(ObjectBuilder.java:266)
	at oracle.toplink.essentials.internal.descriptors.ObjectBuilder.buildObject(ObjectBuilder.java:515)
	at oracle.toplink.essentials.internal.descriptors.ObjectBuilder.buildWorkingCopyCloneNormally(ObjectBuilder.java:436)
	at oracle.toplink.essentials.internal.descriptors.ObjectBuilder.buildObjectInUnitOfWork(ObjectBuilder.java:406)
	at oracle.toplink.essentials.internal.descriptors.ObjectBuilder.buildObject(ObjectBuilder.java:372)
	at oracle.toplink.essentials.queryframework.ReportQueryResult.processItem(ReportQueryResult.java:205)
	at oracle.toplink.essentials.queryframework.ReportQueryResult.buildResult(ReportQueryResult.java:167)
	at oracle.toplink.essentials.queryframework.ReportQueryResult.(ReportQueryResult.java:83)
	at oracle.toplink.essentials.queryframework.ReportQuery.buildObject(ReportQuery.java:579)
	at oracle.toplink.essentials.queryframework.ReportQuery.buildObjects(ReportQuery.java:628)
	at oracle.toplink.essentials.queryframework.ReportQuery.executeDatabaseQuery(ReportQuery.java:776)
	at oracle.toplink.essentials.queryframework.DatabaseQuery.execute(DatabaseQuery.java:609)
	at oracle.toplink.essentials.queryframework.ObjectLevelReadQuery.execute(ObjectLevelReadQuery.java:677)
	at oracle.toplink.essentials.queryframework.ObjectLevelReadQuery.executeInUnitOfWork(ObjectLevelReadQuery.java:731)
	at oracle.toplink.essentials.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2219)
	at oracle.toplink.essentials.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:937)
	at oracle.toplink.essentials.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:909)
	at oracle.toplink.essentials.internal.ejb.cmp3.base.EJBQueryImpl.executeReadQuery(EJBQueryImpl.java:346)
	at oracle.toplink.essentials.internal.ejb.cmp3.base.EJBQueryImpl.getResultList(EJBQueryImpl.java:453)
	at org.springframework.samples.petclinic.jpa.EntityManagerClinic.findOwners(EntityManagerClinic.java:53)

 

Conclusion de la 1ère partie :

J'espère que chacun comprendra enfin pourquoi les architectes s'entêtent à sensibiliser tout le monde sur la manipulation dangereuse des niveaux de logs dans une infrastructure Java portée en Production. Le constat l'est d'autant plus si l'application doit faire face à une charge croissante.

Avant goût de ce qui nous attend au prochain post

Notre objectif étant toujours 1000 utilisateurs simultanées :

  •  Nous mesurerons l'impact des pools de threads - Jdbc  et Http Session sur l'application
  • Nous passerons en revue la gestion globale de la Heap pour en sortir une utilisation plus performante
  • Peut être serons-nous confronté à une fuite mémoire ...
  • Enfin, nous proposerons une évolution d'architecture à base nœuds supplémentaires loadbalancés, et la mise en place d'un cache distribué tout en mesurant l'impact directe sur notre application.

 

 

2 réponses à to “Optimiser une application JEE : mesurer l’impact sur un cas pratique (1ère partie)”

Laisser un commentaire

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

Mots-clés
RSS Feed