P6Spy, l'espion qui m'aidait

Hibernate est un bon outil, mais complexe. Pour surveiller les requêtes qu'il envoie à la base de données, il est possible d'activer différentes options :

hibernate.show_sql         = true
hibernate.format_sql       = true
hibernate.use_sql_comments = true

Mais les traces ainsi produites ne sont pas vraiment satisfaisantes : on voit bien la structure des statements, mais pas les véritables valeurs des paramètres :

Hibernate: 
    insert 
        into
            VILLE
            (version, nom, PAYS_ID, ID) 
        values
            (?, ?, ?, ?)

On sent bien qu'Hibernate a fait de son mieux pour nous aider, qu'une petite goutte de sueur a ruisselé sur son front fiévreux au cours de l'effort, mais tout de même, le résultat est loin d'être satisfaisant.

Et c'est là que P6Spy intervient.

Mise en place

P6Spy est une toute petite librairie fort pratique. Il s'agit d'un proxy de pilote JDBC, qui wrappe votre véritable pilote (Oracle, mySQL, H2...) et en profite pour tracer les requêtes que celui-ci envoie à la base.
Les vraies requêtes, donc, avec tous leurs paramètres.

Pour configurer P6Spy, il vous faut :

p6spy.jar dans le classpath
spy.properties, également dans le classpath
déclarer le pilote JDBC com.p6spy.engine.spy.P6SpyDriver à la place du véritable, dans la configuration d'Hibernate
~~300g de persil~~

Dans le fichier spy.properties, vous n'avez plus qu'à déclarer le véritable pilote JDBC, ainsi que les options de logging, et le tour est joué :

# Le véritable pilote JDBC
realdriver = <votre pilote>

# Le logger : console...
appender=com.p6spy.engine.logging.appender.StdoutLogger

# ...ou Log4J
appender=com.p6spy.engine.logging.appender.Log4jLogger
log4j.appender.p6spy-console=org.apache.log4j.ConsoleAppender
log4j.appender.p6spy-console.layout=org.apache.log4j.PatternLayout
log4j.appender.p6spy-console.layout.ConversionPattern=[P6SPY] %m%n
log4j.logger.p6spy=TRACE,p6spy-console
log4j.additivity.p6spy=false

Une fois tout ceci configuré, on obtient des traces nettement plus sympa pour l'exploitation. On voit passer les statements avec leurs paramètres, les commits et rollbacks, et même les résultats des requêtes.

La même requête d'insertion d'une Ville que plus haut, tracée par P6Spy :

[P6SPY] 1347557275551|0|0|statement|insert into VILLE (version, nom, PAYS_ID, ID) values (?, ?, ?, ?)|insert into VILLE (version, nom, PAYS_ID, ID) values (0, 'Paris', 1, 1)
[P6SPY] 1347557275552|0|0|commit||

Le format des traces est bien défini, il est facile de les passer dans un analyseur afin de surveiller automatiquement le trafic SQL des applications.

On ne nous dit pas tout !

P6Spy donc est très utile, mais peut réserver des surprises.

Par exemple, le problème suivant m'a mystifié un certain temps cet après-midi : lors de l'insertion successive de plusieurs objets en base (des Villes, en l'occurrence), une seule ligne apparaissait dans les traces de P6Spy.

Voici le code en question - rien de bien exotique au royaume d'Hibernate :

Ville paris = new Ville("Paris");
Ville bordeaux = new Ville("Bordeaux");
Ville rennes = new Ville("Rennes");
 
Configuration config = new  Configuration();
config.configure();
SessionFactory sessionFactory = config.buildSessionFactory();
 
Session session = sessionFactory.openSession();
Transaction tx = session.beginTransaction();
session.persist(paris);
session.persist(bordeaux);
session.persist(rennes);
tx.commit();
session.close();
 
sessionFactory.close();

Et les traces associées :

[P6SPY] 1347558060375|2|8|statement|insert into VILLE (version, nom, PAYS_ID, ID) values (?, ?, ?, ?)|insert into VILLE (version, nom, PAYS_ID, ID) values (0, 'Rennes', '', 3)
[P6SPY] 1347558060376|0|8|commit||

On ne voit ici qu'une seule requête d'insertion, pour la troisième ville. Mais où sont passées les deux autres ?

Ma première idée est qu'Hibernate utilise sans doute un PreparedStatement pour insérer les Villes, et que P6Spy ne trace donc peut-être que la structure du statement et pas ses utilisations successives.

En réalité, c'était presque ça. Afin d'optimiser les insertions simultanées d'entités de même type, Hibernate utilise le mode batch.
Et justement, dans la configuration de P6Spy, que voit-on ?

#list of categories to exclude: error, info, batch, debug, statement, commit, rollback and result are valid values
excludecategories=info,debug,result,batch

Et effectivement, en retirant "batch" des traces à exclure, ça marche tout de suite mieux :

[P6SPY] 1347558498540|0|9|batch|insert into VILLE (version, nom, PAYS_ID, ID) values (?, ?, ?, ?)|insert into VILLE (version, nom, PAYS_ID, ID) values (0, 'Paris', '', 160)
[P6SPY] 1347558498540|0|9|batch|insert into VILLE (version, nom, PAYS_ID, ID) values (?, ?, ?, ?)|insert into VILLE (version, nom, PAYS_ID, ID) values (0, 'Bordeaux', '', 161)
[P6SPY] 1347558498540|0|9|batch|insert into VILLE (version, nom, PAYS_ID, ID) values (?, ?, ?, ?)|insert into VILLE (version, nom, PAYS_ID, ID) values (0, 'Rennes', '', 162)
[P6SPY] 1347558498542|1|9|statement|insert into VILLE (version, nom, PAYS_ID, ID) values (?, ?, ?, ?)|insert into VILLE (version, nom, PAYS_ID, ID) values (0, 'Rennes', '', 162)
[P6SPY] 1347558498542|0|9|commit||

Trois villes, le compte est bon.
Mais je m'interroge sur la pertinence d'exclure les opérations de batch des traces par défaut...

J'espère que cette astuce vous évitera de perdre du temps à courir après les traces fantômes !

Conclusion

P6Spy est un bon petit outil, facile à installer et à configurer -- nonobstant quelques réglages par défaut contestables. Je recommande chaudement son utilisation lors des phases de développement, pour garder un oeil sur Hibernate et vérifier qu'il se comporte en gentleman avec votre base de données.

Vous pouvez télécharger P6Spy sur Sourceforge (http://sourceforge.net/projects/p6spy/).

Commentaires

1. Le jeudi 13 septembre 2012, 22:58 par Damien B

Note : pour avoir les valeurs des paramètres qui sont bindés sur les requêtes Hibernate, il suffit de mettre org.hibernate.type à TRACE. Ça reste moins puissant que p6spy évidemment, mais si il faut juste les valeurs paramétrées, ça évite de sortir l'artillerie lourde.

2. Le vendredi 14 septembre 2012, 08:44 par Antoine

Je confirme ce que dit Damien. En fixant par exemple le niveau TRACE du logger org.hibernate.type.descriptor.sql.BasicBinder, on peut obtenir des logs du type :
insert into VILLE (version, nom, PAYS_ID, ID) values (?, ?, ?, ?)
binding parameter 1 as INTEGER - 0
binding parameter 2 as VARCHAR - Rennes
binding parameter 3 as VARCHAR - <null>
binding parameter 4 as INTEGER - 162

3. Le vendredi 14 septembre 2012, 10:48 par Jérôme D

log4jdbc est aussi une alternative.
---
http://code.google.com/p/log4jdbc/
---
log4jdbc is a Java JDBC driver that can log SQL and/or JDBC calls (and optionally SQL timing information) for other JDBC drivers using the Simple Logging Facade For Java (SLF4J) logging system.

4. Le vendredi 14 septembre 2012, 10:50 par Johann

Hello,

Merci pour partager ce genre d'info ;)

Juste pour signaler qu'il existe aussi log4jdbc (http://code.google.com/p/log4jdbc/) qui est sur le même principe. Je l'utilise et c'est très pratique !

5. Le vendredi 14 septembre 2012, 12:42 par Nicolas

Cet outil est formidable, mais utilisé seul il ne permet que difficilement de régler les problèmes de performance causé par une utilisation "à l'aveugle" d'Hibernate, comme des lazy loading de collection dans une itération.

Allié avec IronTrack SQL, c'est une véritable tuerie (même si l'interface Swing pourrait être meilleure...).

Voir un article au hasard sur le sujet, qui propose également le téléchargement de l'outil (maintenant très difficile à trouver car la société qui le faisait a fermé).

http://www.360emedia.fr/2007/01/29/...

6. Le vendredi 14 septembre 2012, 13:16 par Tibo

Je pense que le meilleur moyen n'est pas de le monitorer au niveau de l'application mais au niveau de la DB. Primo, c'est toujours un peu ennuyeux de devoir configurer son app en fonction du context (Test, prod, debug). Secondo, on rajoute encore une dépendance a notre projet... Tertio, on est jamais a l'abris d'un bug de la librairie qui ne montre pas exactement ce qui est envoyé, d'un problème de configuration quelconque, d'une configuration qui pointe sur la mauvaise DB, etc...
En ce moment, j'utilise MySQL, j'ai activé le general query log et hop "tail -f mysql.log" : j'ai en en live toute les requêtes effectuées. C'est hyper simple a activer/desactiver, je peux suivre les requêtes en luve et je suis sur de ce qui est réellement executé cote DB. Toutes les bases de données un minimum évolué permettent de logger les requêtes!
Si la BD est partagé par plusieurs clients, ca peut même aider a comprendre certains problèmes du genre "mais pourquoi cette requête a mis une plombe?? Ah oui d'accord, Jackie mon co-developpeur a encore execute une requete avec 20 cross join en meme temps que moi..."
A part cas particulier ou la BD ne peut être configurer ou dont les logs ne sont pas accessibles, je ne vois aucune raison d'utiliser ce genre de librairies.

7. Le vendredi 14 septembre 2012, 13:51 par lapsus63

La librairie contient la documentation (un peu vieillissante) pour installer P6Spy sur JBoss 2.X ; JBoss 3.X ; Orion ; Jakarta ; JOnas ; BEA WebLogic ; ATG Dynamo ; Sun iPlanet ; IBM WebSphere ; Caucho Resin et propose une doc standard pour tout autre type de serveur d'applications.

Utilisant Glassfish v3, j'ai regardé un peu si on pouvait intégrer cette librairie dans ce serveur. Un blog d'Oracle propose une solution assez simple à mettre en oeuvre : https://blogs.oracle.com/enterprise... ; il s'adresse à Glassfish v2 mais pour la v3 c'est sensiblement la même chose. Juste penser à placer le spy.properties dans le domain/config (Nul besoin d'avoir Netbeans comme indiqué).

8. Le vendredi 14 septembre 2012, 15:06 par lapsus63

Pour compléter mon précédent commentaire (s'il se fait valider), il semblerait que les requêtes construites à l'aide de l'API Criteria ne soient pas "compatibles" avec P6Spy.
Erreur retournée :
Internal Exception: java.sql.SQLException: Column 'ID' not found.
Error Code: 0
Call: SELECT t0.ID AS ID1, ...
--> java.sql.SQLException : Column 'ID' not found.

Les champs sont suffixés d'un numéro de colonne, mais le parcours du ResultSet cherche ces colonnes sans ce suffixe. Bizarre bizarre. Bug ?
Si quelqu'un a des infos à ce sujet je suis preneur.

9. Le dimanche 16 septembre 2012, 16:13 par Nicolas

@lapsus63

On utilise p6spy (et irontrack) depuis plus de 3 ans, via JNDI (sous jetty, tomcat, ou via simple-jndi), pour tous les développements, avec des requêtes SQL natives, des requêtes HQL ou des Criteria Hibernate, et je n'ai jamais eu le problème que tu décris.

10. Le lundi 17 septembre 2012, 09:11 par lapsus63

Nous nous sommes sur GlassFish Server Open Source Edition 3.0.1 (build 22) ; peut-être est-ce dû à la version bêta de GF.
Merci pour votre retour.

11. Le jeudi 4 octobre 2012, 10:56 par Brice

A noter qu'il faut ne faut pas oublier d'activer les modules

module.log=com.p6spy.engine.logging.P6LogFactory

module.outage=com.p6spy.engine.outage.P6OutageFactory

12. Le dimanche 7 octobre 2012, 18:27 par smougenot

plus de 6 ans d'utilisation (p6spy + Irontrack) c'est un vrai confort
On y trace :
- les requêtes
- les transactions
- les stat des requêtes (nombre de fois lancée, nombre de lignes retournées, temps de traitement)
- un petit graph temporel des requêtes

En pratique il est activé en dev et intégration (déploiement et tests automatisés).
Comme cela a déjà été précisé, j'utilise une ressource Jndi, donc la config n'est pas compliquée.
Contrairement à l'opinion de certains je trouve bien plus efficace de faire des traces coté applicatif et non coté SGBD ; au moins j'ai la trace en local, je ne perturbe pas la base et si quelqu'un d'autre l'utilise on ne se gène pas.

Par rapport aux logs hibernate en mode trace, on a en plus le numéro de la connexion (SQL) qui sert à identifier les transactions.