Tomcat ou Jboss, enregistrer le temps de traitement des requêtes HTTP

Avec Tomcat ou Jboss, il est possible d’enregistrer le temps de traitement d’une requête HTTP. Il y a en effet une valve AccessLogValve (désactivée par défaut) qui trace les accès (requêtes) HTTP qui sont effectués sur le serveur. Avec une petite modification du format du log, on peut ajouter l’enregistrement du temps de traitement coté Tomcat ou Jboss de la requête.

Ceci est particulièrement utile pour décorréler le temps de traitement par rapport au temps de réponse enregistré dans un outil de test de charge, comme JMeter.

Voici comme faire dans Tomcat :

Au niveau du fichier Tomcat_Home/conf/server.xml, on trouve la section suivante en commentaires :

<!--
<Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
prefix="localhost_access_log." suffix=".txt" pattern="common" resolveHosts="false"/>
--->

Il faut d’abord la décommenter, puis modifier l’attribut pattern comme suit :

<Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
prefix="localhost_access_log." suffix=".txt"
pattern='%h %l %u %t "%r" %s %b %D'
pattern="common" resolveHosts="false"/>

Le %D correspondra au temps de traitement de la requête en millisecondes.

Pour Jboss qui, (je le rappelle) contient un serveur Tomcat (plus exactement un dérivé appelé Jboss Web), c’est la même valve que l’on retrouve.

Cette fois-ci, il faut aller dans le dossier Jboss_Home/server/<default|nom instance>/deploy/jboss-web.deploy/server.xml, puis procéder au même type de changement sur l’attribut pattern :

<!-- Access logger -->
<Valve className="org.apache.catalina.valves.AccessLogValve"
prefix="localhost_access_log." suffix=".log"
pattern='%h %l %u %t "%r" %s %b %D'
directory="${jboss.server.log.dir}" resolveHosts="false" />

Bien entendu, dans les deux cas, il faut redémarrer le serveur pour la prise en compte.

Ensuite dans le fichier localhost_access_log.<date>.log, on aura des lignes de ce type :

123.45.67.89 - - [01/Mar/2010:00:05:39 +0000] "POST /App1/Modification.action HTTP/1.1" 200 24039 458

le 458 à la fin correspond au temps de traitement exprimé en millisecondes.

On notera qu’il est possible de changer (ou d’ajouter) le %D en %T pour avoir le temps de traitement en secondes plutôt que millisecondes.

Plus d’infos sur la valve et les formats possibles ici.

PS. Bien entendu, Apache ou IBM HTTP Server propose la même fonctionnalité. Il peut même être très intéressant de l’activer à son niveau dans le cas d’une architecture de type Apache+mod_jk+Tomcat.

./