A la recherche du temps de réponse perdu

Récemment en mission chez un acteur majeur du marché de l’énergie français, j’ai été confronté à un problème de performance sur l’un de leurs portails Web. Le symptôme était le suivant : lors de montées en charge, sur l’environnement de production, les temps de génération de certaines pages s’accroissaient dramatiquement (jusqu’à 12 secondes). Brièvement, les composants techniques constituant le portail sont les suivants :

  • un cluster de trois serveurs Apache,
  • un cluster de trois serveurs Weblogic Portal 8.1sp5,
  • un cluster .de trois serveurs Weblogic Integration 8.1sp5,
  • un connecteur iWay Adapter for SAP 5.5.006.R2, de iWay Software, installé sur chaque instance WLI,
  • SAP,
  • Oracle 9i.

L’environnement de production était dépourvu d’outil de diagnostic et aucun message d’erreur suspect n’apaisait dans les différents fichiers de traces.

Premiers réflexes :

  • Vérifier la charge des processeurs des serveurs Solaris. La charge des CPU était très faible.
  • Vérifier les accès aux entrées/sorties. Le volume de données lues et écrites était très faible ainsi que le nombre d’accès aux disques et aux réseaux.
  • Vérifier l’activité du ramasse-miettes des différentes JVM depuis les consoles d’administration Weblogic. Rien à signaler.

Nous pouvions exclure les erreurs de programmation entraînant des surconsommations de CPU et d’I/O, les boucles infinies, et les fuites-mémoires de l’ensemble de nos hypothèses. Le ralentissement semblait être lié à un problème d’accès à une ressource critique tels que un pool JDBC, un pool de threads ou un bloc synchronisé.

Deuxièmes réflexes :

  • contrôler le nombre et l’activité des threads au travers des consoles Weblogic,
  • générer un “Thread Dump” en lançant un signal SIGQUIT (“kill -3” sous Unix ou “Control+Pause” sous Windows) à destination des processus exécutant les JVMs. Pour rappel, cette opération ne termine pas l’exécution des JVMs. Lorsqu’une JVM reçoit ce signal, elle suspend momentanément l’exécution de toutes ses threads, génère une trace d’exécution (“stack trace”) pour chacune d’elles, puis les réactivent.

L’outil idéal pour analyser un “Thread Dump” est … “Thread Dump Analyzer”. Il s’agit une application gratuite disponible à l’adresse : http://tda.dev.java.net

Premier constat : près de la moitié des threads des serveurs WLI étaient en attentent sur le même bloc synchronisé. Le point de contention était localisé dans la méthode “debug” appartenant à la classe “LoggerDecorator” du connecteur iWay.

Pour aller plus en avant dans nos investigations, nous avons installé le produit Introscope de CA | Wily Technology sur les serveurs WLI de l’environnement de qualification, puis nous avons généré du trafic afin de reproduire l’anomalie. Introscope est un outil de supervision et de diagnostic permettant de suivre l’activité de tous les composants sollicités durant une transaction, sur plusieurs serveurs. Son faible surcoût en ressource machine permet de le déployer sur des environnements de production.

Deuxième constat : 92% du temps de production des pages du portail était consommé par le mécanisme de trace (log) du connecteur SAP !!

Ne disposant pas des sources du connecteur iWay pour le corriger, un cas a été ouvert auprès de BEA Systems.

En conclusion,

  1. TDA nous a permis de cerner la source du problème. Ce petit outil gratuit doit faire parti de votre trousse de secours.
  2. Instroscope nous a permis d’identifier la méthode générant les ralentissements et de mesurer leurs importances. Cet outil nous a également permis de corréler les ralentissements avec les accès simultanés à la classe de trace en superposant la courbe des temps de réponse de la méthode incriminée et la courbe du nombre des accès à la méthode. Il s’agit d’un produit évolué permettant de superviser des applications complexes en production et de diagnostiquer rapidement les sources d’une anomalie.