Tutoriel sur P6Spy, une bibliothèque pour tracer les requêtes SQL via JDBC

Olivier Croisier

Ce tutoriel s'intéresse à présenter la bibliothèque P6Spy, un proxy de pilote JDBC pour tracer les requêtes.

Cet article a été rédigé par Olivier Croisier. L'article original (P6Spy, l'espion qui m'aidait !) peut être vu sur le blog/site d'Olivier Croisier.

Pour réagir au contenu de cet article, un espace de dialogue vous est proposé sur le forum Commentez .

- Titre : Tutoriel sur P6Spy, une bibliothèque pour tracer les requêtes SQL via JDBC

- Auteur : Olivier Croisier

- Parution : 16 juin 2014

- Licence : Copyright ® 2014 Olivier Croisier. Aucune reproduction, même partielle, ne peut être faite de ce site et de l'ensemble de son contenu : textes, documents, images, etc. sans l'autorisation expresse de l'auteur. Sinon vous encourez selon la loi jusqu'à trois ans de prison et jusqu'à 300 000 € de dommages et intérêts.

Sommaire

- I. Introduction

- II. P6Spy, l'espion qui m'aidait

- II-A. Mise en place

- II-B. On ne nous dit pas tout !

- III. Conclusion

I - Introduction

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.

II - P6Spy, l'espion qui m'aidait

II-A - 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.

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 sympatiques 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.

II-B - 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 cela. 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 !

III - 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 œil 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/).

Cet article a été publié avec l'aimable autorisation de Olivier Croisier. L'article original (P6Spy, l'espion qui m'aidait) peut être vu sur le blog http://thecodersbreakfast.net/.

Nous tenons à remercier jacques_jean pour sa relecture attentive de cet article et Mickaël Baron pour la mise au gabarit.