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

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.

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 !