Tags

, , , , , , , , , ,

En ce moment, je réalise des tests de montée en charge du serveur de reporting JasperServer. Je souhaite pouvoir corréler le niveau de stress (nombre de tirs simultanés) appliqué au SUT, le System Under Test, avec des métriques internes du serveur, à la fois système comme la charge CPU du process Java et la quantité de HEAP utilisée mais je souhaite aussi pouvoir mesurer des métriques propres à la librairie JasperReports comme le nombre de rapports en cours de calcul ou la vitesse de remplissage des rapports.

J’utilise JMeter pour effectuer les tirs. Cet outil permet de simuler plusieurs clients simultanés et de visualiser l’évolution des temps de réponse en fonction du temps et du nombre de clients qui tirent. C’est une vision boite noire, externe au SUT.

JMeter ne permet pas de visualiser des métriques propres au SUT comme la charge CPU, le nombre de transactions en cours, le nombre de requêtes SQL en cours ou dans le cas qui m’intéresse le nombre de rapports en cours de calcul.

Il existe plusieurs outils qui permettent de monitorer en temps différé ces informations comme par exemple HypericHQ ou l’une de ses nombreuses variantes, ils sont conçus pour du monitoring de production et pourraient servir à monitorer le SUT pour des tests de charge de longue durée sur une semaine par exemple mais ils ne sont pas adaptés au monitoring temps réel nécessaire pendant un test de stress.

Il existe aussi des consoles JMX permettant de visualiser les métriques JMX en temps réel mais les consoles que je connais (JConsole, Visual VM) ne permettent pas de consolider sur un même graphe plusieurs métriques. JConsole ne permet de grapher qu’une seule métrique. C’est intéressant mais insuffisant.

Pour illustrer cette technique, j’utilise ici les métriques standards Java, relevées à l’aide de JStat, livré en standard avec le JDK de Sun à partir de la version 5.

Pour obtenir le PID du process Java qui m’intéresse, le plus simple est d’utiliser la commande jps qui liste les process Java détectés sur la machine locale. Chez moi, le PID est le 6652.

Ensuite, j’utilise la commande jstat :

jstat -gc -t 6652 100
  • L’option -gc affiche les statistiques du HEAP collectées par le Garbage Collector.
  • L’option -t affiche un timestamp devant chaque ligne c’est important pour pouvoir grapher les données.
  • Le chiffre 100 indique que l’on affiche les données toutes les 100 millisecondes.

Chez moi, cela donne:

$ jstat -gc -t 6652 100
Timestamp        S0C    S1C    S0U    S1U      EC       EU        OC         OU       PC     PU    YGC     YGCT    FGC    FGCT     GCT
 11718,4 704,0  704,0   0,0    0,0    6016,0    33,3    88568,0    41839,7   70912,0 70830,6    703    4,525  56     20,349   24,875
 11718,5 704,0  704,0   0,0    0,0    6016,0    33,3    88568,0    41839,7   70912,0 70830,6    703    4,525  56     20,349   24,875
 11718,6 704,0  704,0   0,0    0,0    6016,0    33,3    88568,0    41839,7   70912,0 70830,6    703    4,525  56     20,349   24,875
 11718,7 704,0  704,0   0,0    0,0    6016,0    33,3    88568,0    41839,7   70912,0 70830,6    703    4,525  56     20,349   24,875
 11718,8 704,0  704,0   0,0    0,0    6016,0    33,3    88568,0    41839,7   70912,0 70830,6    703    4,525  56     20,349   24,875
 11718,9 704,0  704,0   0,0    0,0    6016,0    33,3    88568,0    41839,7   70912,0 70830,6    703    4,525  56     20,349   24,875
 11719,0 704,0  704,0   0,0    0,0    6016,0    33,3    88568,0    41839,7   70912,0 70830,6    703    4,525  56     20,349   24,875
 11719,1 704,0  704,0   0,0    0,0    6016,0    33,3    88568,0    41839,7   70912,0 70830,6    703    4,525  56     20,349   24,875
 11719,2 704,0  704,0   0,0    0,0    6016,0    33,3    88568,0    41839,7   70912,0 70830,6    703    4,525  56     20,349   24,875
 11719,3 704,0  704,0   0,0    0,0    6016,0    33,3    88568,0    41839,7   70912,0 70830,6    703    4,525  56     20,349   24,875
 11719,4 704,0  704,0   0,0    0,0    6016,0    33,3    88568,0    41839,7   70912,0 70830,6    703    4,525  56     20,349   24,875

En l’état, ces données sont difficilement exploitables. Pour les formater, j’utilise l’outil linux sed. Et sous windows, j’utilise cygwin pour émuler l’environnement Linux:

$ jstat -gc -t 6652 100 | sed -e "s/^ +//" -e "y/ ,/,./" -e "s/,+/,/g"

Pour formater ces données, j’utilise successivement trois expressions sed:

  • s/^ +//: supprime les espaces en tête de ligne
  • y/ ,/,./: remplace les espaces par des virgules et les virgules par des points (similaire à l’outil linux tr)
  • s/,+/,/g: remplace les occurrences multiples de virgules par une seule virgule

Nous obtenons le flux de données suivant:

$ jstat -gc -t 6652 100 | sed -e "s/^ +//" -e "y/ ,/,./" -e "s/,+/,/g"
Timestamp,S0C,S1C,S0U,S1U,EC,EU,OC,OU,PC,PU,YGC,YGCT,FGC,FGCT,GCT,
12086.0,704.0,704.0,0.0,0.0,6016.0,21.3,88568.0,41840.5,70912.0,70830.6,703,4.525,62,22.500,27.026
12086.1,704.0,704.0,0.0,0.0,6016.0,21.3,88568.0,41840.5,70912.0,70830.6,703,4.525,62,22.500,27.026
12086.2,704.0,704.0,0.0,0.0,6016.0,21.3,88568.0,41840.5,70912.0,70830.6,703,4.525,62,22.500,27.026
12086.3,704.0,704.0,0.0,0.0,6016.0,21.3,88568.0,41840.5,70912.0,70830.6,703,4.525,62,22.500,27.026
12086.4,704.0,704.0,0.0,0.0,6016.0,21.3,88568.0,41840.5,70912.0,70830.6,703,4.525,62,22.500,27.026
12086.5,704.0,704.0,0.0,0.0,6016.0,21.3,88568.0,41840.5,70912.0,70830.6,703,4.525,62,22.500,27.026
12086.6,704.0,704.0,0.0,0.0,6016.0,21.3,88568.0,41840.5,70912.0,70830.6,703,4.525,62,22.500,27.026
12086.7,704.0,704.0,0.0,0.0,6016.0,21.3,88568.0,41840.5,70912.0,70830.6,703,4.525,62,22.500,27.026

Il nous faut ensuite rediriger ces données vers un fichier afin de pouvoir les charger dans LiveGraph:

$ jstat -gc -t 6652 100 | sed -u -e "s/^ +//" -e "y/ ,/,./" -e "s/,+/,/g" > /cygdrive/c/temp/jstat.log

Attention à ne pas oublier le paramètre -u pour que sed alimente le fichier de sortie en temps réel au lieu de le bufferiser.

De plus, pour visualiser le flux de données tout en le redirigeant vers un fichier, j’utilise tee en complément:

$ jstat -gc -t 6652 100 | sed -u -e "s/^ +//" -e "y/ ,/,./" -e  "s/,+/,/g" | tee /cygdrive/c/temp/jstat.log

Voila, nous avons maintenant un flux de données temps réel sur les statistiques internes de notre SUT prêt à être visualisé dans LiveGraph.

Pour lancer LiveGraph, il suffit d’exécuter le jar:

java -jar LiveGraph-[version].jar

Puis dans la fenêtre “Data file settings”, ouvrez le fichier:

livegraph-conf

Sélectionner l’option indiquant de ne conserver que la queue des données afin d’obtenir une fenêtre coulissante sur les données temporelles. A noter que LiveGraph ne semble malheureusement pas permettre de configurer la largeur de la fenêtre temporelle, c’est dommage.

Sélectionner également la fréquence de mise à jour. Ici j’ai choisi une fréquence de 10Hz soit toutes les 100 millisecondes pour être en phase avec la configuration de jstat.

Dans la configuration du graph, préciser 0 en minimum des ordonnées et indiquer qu’il s’agit d’une “Data series” utilisant la série “Timestamp” comme donnée temporelle :

livegraph-settings

Dans la fenêtre des séries de données, dé-sélectionner la série “Timestamp”:

livegraph-series

Nous obtenons le graph suivant:

livegraph-plotter

Nous venons de montrer comment visualiser graphiquement un flux de données temps réel issu de notre SUT. Ici, les données sont les statistiques standards Java, ce que nous aurions pu obtenir plus simplement avec JConsole, mais nous verrons dans un prochain article comment valoriser la technique présentée ici en l’utilisant avec une sonde BTrace afin de visualiser et corréler des informations ad-hoc comme le nombre de rapports JasperReports en cours de remplissage.

Par ailleurs, le flux de données obtenu est ici utilisé pour être visualisé en temps réel mais il pourra évidemment être utilisé pour une analyse à posteriori dans un tableur comme Excel ou OpenOffice.

Enfin, ici, le SUT et la console LiveGraph sont sur une même machine, nous verrons également comment obtenir ces informations depuis un SUT distant.

Advertisements