Eclipse TPTP : Accélérer le "profiling"

Avant propos :

• Le contenu de ce billet valable à partir de Java 5
• Pour pouvoir tester les exemples présentés dans ce billet vous devez avoir correctement installé l'"Agent Controller" du projet Eclipse TPTP comme cela est décrit ici.
• Si les notions d'"Agent" et d'"Agent Controller" ne vous disent rien vous pouvez vous rendre ici.

Performances, données et outils
Une séance de "profiling" peut très vite se trouver ralentie. Ce phénomène a en règle générale deux origines :

1. La quantité de données collectées par l'outil, à plus forte raison si il s'agit d'une session distante ("Agent" sur une machine, client sur une autre).
2. Les performances de l'outil qui va analyser et restituer ces données, si l'interface graphique fournie par Eclipse TPTP est très fournie il n'en reste pas moins que si la quantité de données à digérer est trop importante votre système pourrait ne plus répondre.

Sérialiser les données de « profiling » sur disque

Il s'agit ici de faire du « profiling » en « différé » : au lieu de connecter un outil qui va analyser directement les données (comme le Workbench Eclipse) nous allons les stocker sur disque, dans un fichier, pour les analyser à posteriori.

Avantages de cette méthode :

• Pouvoir évaluer immédiatement la quantité de données recueillie en suivant l'évolution de la taille du fichier. Si le fichier atteint trop vite plusieurs centaines de Mo il faudra, vraisemblablement, arrêter, configurer des filtres (comme cela est décrit après) et recommencer.
• Savoir clairement où les données collectées sont stockées
• Collecter les données sur un système distant et faire l'analyse à posteriori sur une autre machine

Filtrer/Sélectionner les données à collecter
Afin de limiter la quantité d'information recueillie par l'Agent il est toujours préférable de mettre en place un système de filtrage. Le filtre va être défini par une liste de règles, séparées par des retours à la ligne. Une règle est composée de 3 colonnes, chacune séparées par un espace :

1. La première colonne permet de désigner la classe et/ou le package Java ciblé par la règle
2. La deuxième colonne contient le nom de la méthode. Il n'est pas nécessaire de spécifier une signature, seul le nom de la méthode suffit.
3. La troisième colonne indique la visibilité de l'information : INCLUDE pour inclure la donnée ou EXCLUDE pour ne pas la sauvegarder.
   

Quelques astuces :

• Les règles sont appliquées de haut en bas : plus une règle est en tête du fichier, plus elle est prioritaire.
• Le caractère * peut être utilisé pour représenter n'importe quelle classe ou méthode (voir l'exemple plus bas).
• Une bonne pratique consiste à exclure ce qui n'a pas été explicitement inclus, et donc de terminer le fichier par la ligne :

* * EXCLUDE

Importer les données dans le Workbench Eclipse

• Dans la perspective Eclipse "Profiling and Logging perspective", sélectionner le menu "File" puis "Import" et enfin dans "Profiling and Logging" sélectionner "Profiling File" :

• Sélectionner le fichier qui contient les données collectées et dans la liste des "Show..." bien sélectionner celle qui correspond aux données collectées.
• Faire ensuite un clique droit sur les données importées et choisir l'éditeur qui convient. Dans le cas de données sur le temps d’exécution des méthodes sélectionner "Open with", "Execution Statistics".
  

Mise en pratique et exemple
J'ai développé deux servlets qui vont être déployées sur un serveur Apache Tomcat. Ces servlets ne vont rien faire d'autre que de concaténer des chaînes de caractères identiques mais de 2 manières différentes :

1. L'une en utilisant le signe +
2. L'autre en utilisant un StringBuilder

L'objectif est de mettre en évidence les temps d’exécution bien meilleurs de la classe StringBuilder.
L'option java suivante est ajoutée au démarrage du serveur d'application web Apache Tomcat :

-agentlib:JPIBootLoader=JPIAgent:server=standalone,file=c:\dev\tptp\tomcat_CGProf.trcxml,filters=c:\dev\tptp\tomcat_filter.txt;CGProf:execdetails=true

  Le mot clé "standalone" signifie à l'agent qu'il ne doit pas attendre ou se mettre à l'écoute d'un éventuel client et que les données collectées seront stockées sur disque. Le paramètre "file=" permet de désigner ce fichier.

 Dans un premier temps nous allons nous contenter d'analyser tous les appels aux méthodes doGet des servlets sans se préoccuper d'un package donné, le fichier tomcat_filter.txt va donc contenir :

* doGet INCLUDE

* * EXCLUDE

Chacune des servlets est appelée 2 fois : cela se retrouve dans la colonne Calls.
Description des autres colonnes :

• Cumulative Time : temps total passé dans la méthode
• Base Time : temps passé dans la méthode moins le temps d'appel des méthodes non filtrées appelées au sein de cette méthode : ici comme on filtre toutes les méthodes autres que les doGet on a Cumulative Time = Base Time
• Average Base Time : Base Time moyen sur l'ensemble des appels

Pour analyser tous les appels aux méthodes des classes contenu dans un package donné et mieux comprendre la différence entre le "Base Time" et le "Cumulative Time" nous allons modifier le filtre pour tracer toutes les classes et méthodes de mon projet de test (dont les méthodes appelées dans les doGet), le fichier tomcat_filter.txt va donc contenir :

com.morello.* * INCLUDE

* * EXCLUDE

Notez maintenant comment pour la servlet com.morello.servlet.SimpleStringConcat.doGet(...) le "Base Time" a diminué alors que le "Cumulative Time" reste élevé. Cela est du au fait que l'on analyse plus de méthodes et que le responsable des mauvaises performances de cette servlet est com.morello.util.SimpleStringConcatUtil.getSimpleStringConcat().

Vous pouvez aussi vous rendre compte que pour réaliser une même concaténation de chaînes de caractère le signe + est près de 1000 fois plus lent que le classe StringBuilder !

Un petit exercice pour finir serait d'ajouter une nouvelle servlet pour comparer les résultats obtenu avec un StringBuilder dont le buffer interne est pré-dimensionné ou avec la classe StringBuffer, une version "thread safe" du StringBuilder.