Hibernate, sous le capot, il fait quoi ?

Hibernate est un formidable outil pour les développeurs, mais il a cependant un inconvénient, il éloigne le développeur de ce qu’il se passe réellement entre son application et sa base de données. Ce post a juste pour objectif de vous donner quelques pistes que j’utilise pour comprendre un peu mieux ce que fait hibernate derrière mon dos.

Tracer les requêtes SQL

On interagit avec une base de données via des ordres SQL. Afin de vérifier que des dizaines de requêtes ne sont pas exécutées lorsque je récupère une collection d’objet, il suffit d’activer le show_sql sur hibernate, je vais également activer le sql_comments que m’en dit encore un peu plus

Fichier de configuration spring :

<bean id="sessionFactory" class="org.springframework.orm.hibernate3.annotation.AnnotationSessionFactoryBean">
	...
	<property name="hibernateProperties">
		<value> hibernate.show_sql=true use_sql_comments=true </value>
	</property>
	...
</bean>

Avec cette configuration, vous aurez en premier lieu, un commentaire sur le traitement JPA lancé (un criteria par exemples), ensuite vous verrez la ou les requêtes SQL résultantes.

Tracer la valeur des paramètres hibernate

Vos requêtes SQL sont désormais bien tracées, cependant, la valeur des paramètres est remplacée par le caractère ? Pour afficher la valeur de ce paramètre, il suffit d’ajouter dans votre fichier de configuration log4j :

<logger name="org.hibernate.type" additivity="false">
	<level value="debug">
	<appender-ref ref="console">
</appender-ref>
</level>

Et maintenant, vous verrez dans votre console les traces suivantes :

Hibernate: /* criteria query */ select this_.id as id4_0_, this_.name as name4_0_, this_.nbPersonnes as nbPerson3_4_0_ from Chambre this_
2009-02-24 21:02:48,939  DEBUG [org.hibernate.type.LongType] (btpool0-0:) returning '1' as column: id4_0_
2009-02-24 21:02:48,939  DEBUG [org.hibernate.type.StringType] (btpool0-0:) returning 'STANDARD' as column: name4_0_
2009-02-24 21:02:48,939  DEBUG [org.hibernate.type.IntegerType] (btpool0-0:) returning '2' as column: nbPerson3_4_0_
2009-02-24 21:02:48,939  DEBUG [org.hibernate.type.LongType] (btpool0-0:) returning '2' as column: id4_0_
2009-02-24 21:02:48,939  DEBUG [org.hibernate.type.StringType] (btpool0-0:) returning 'SUPERIEURE' as column: name4_0_
2009-02-24 21:02:48,940  DEBUG [org.hibernate.type.IntegerType] (btpool0-0:) returning '2' as column: nbPerson3_4_0_
2009-02-24 21:02:48,940  DEBUG [org.hibernate.type.LongType] (btpool0-0:) returning '3' as column: id4_0_
2009-02-24 21:02:48,940  DEBUG [org.hibernate.type.StringType] (btpool0-0:) returning 'MEZZANINE' as column: name4_0_
2009-02-24 21:02:48,940  DEBUG [org.hibernate.type.IntegerType] (btpool0-0:) returning '4' as column: nbPerson3_4_0_
2009-02-24 21:02:48,940  DEBUG [org.hibernate.type.LongType] (btpool0-0:) returning '4' as column: id4_0_
2009-02-24 21:02:48,940  DEBUG [org.hibernate.type.StringType] (btpool0-0:) returning 'aaaaa' as column: name4_0_
2009-02-24 21:02:48,940  DEBUG [org.hibernate.type.IntegerType] (btpool0-0:) returning '5' as column: nbPerson3_4_0_

Tracer les transactions Hibernate :

Maintenant nous allons activer les logs sur les transactions hibernate, en modifiant le fichier de configuration log4j

<logger name="org.hibernate.transaction">
	<level value="DEBUG">
</level>
</logger>

Ce qui vous donnera les traces suivantes

22:08:15,518 INFO  [STDOUT] 2009-02-11 22:08:15,518  DEBUG [org.hibernate.transaction.JDBCTransaction] (http-127.0.0.1-8080-2:) begin
22:08:15,524 INFO  [STDOUT] 2009-02-11 22:08:15,524  DEBUG [org.hibernate.transaction.JDBCTransaction] (http-127.0.0.1-8080-2:) current autocommit status: true
22:08:15,524 INFO  [STDOUT] 2009-02-11 22:08:15,524  DEBUG [org.hibernate.transaction.JDBCTransaction] (http-127.0.0.1-8080-2:) disabling autocommit
22:08:15,527 INFO  [STDOUT] 2009-02-11 22:08:15,527  DEBUG [com.cestpasdur.reservation.managedbeans.back.ReservationBean] (http-127.0.0.1-8080-2:) ChambreService.create : Chambre : [id: null], [name: aaaaa]
22:08:15,537 INFO  [STDOUT] Hibernate: /* insert com.cestpasdur.reservation.domain.Chambre */ insert into Chambre (name, nbPersonnes) values (?, ?)
22:08:15,613 INFO  [STDOUT] 2009-02-11 22:08:15,613  DEBUG [org.hibernate.transaction.JDBCTransaction] (http-127.0.0.1-8080-2:) commit
22:08:15,652 INFO  [STDOUT] 2009-02-11 22:08:15,652  DEBUG [org.hibernate.transaction.JDBCTransaction] (http-127.0.0.1-8080-2:) re-enabling autocommit
22:08:15,653 INFO  [STDOUT] 2009-02-11 22:08:15,653  DEBUG [org.hibernate.transaction.JDBCTransaction] (http-127.0.0.1-8080-2:) committed JDBC Connection

Statistiques hibernate

Il est possible d’activer les statistiques sur la sessionFactory hibernate, ce qui nous permettra d’obtenir entre autre les données suivantes :

EntityNames,
ConnectCount,
EntityLoadCount,
FlushCount,
SessionOpenCount ...

Fichier de configuration spring :

<bean id="sessionFactory" class="org.springframework.orm.hibernate3.annotation.AnnotationSessionFactoryBean">
	...
	<property name="hibernateProperties">
		<value>hibernate.generate_statistics=true</value>
	</property>
	...
</bean>

Il faut maintenant exporter ces données via JMX

<bean id="jmxExporter" class="org.springframework.jmx.export.MBeanExporter">
	<property name="beans"><map>
			<entry key="Hibernate:name=statistics">
				<ref local="statisticsBean"></ref>
		</entry></map>
	</property></bean>
<bean id="statisticsBean" class="org.hibernate.jmx.StatisticsService">
	<property name="statisticsEnabled">
		<value>true</value>
	</property>
	<property name="sessionFactory">
		<ref local="sessionFactory">
	</ref>
</property>

Si vous utilisez jboss, une console jmx est directement disponible sur le serveur :

http://localhost:8080/jmx-console/

Sinon, vous pouvez utiliser des outils tels que la JConsole fournie avec le JDK.

Conclusion

J’espère que cet article vous donnera quelques pistes concernant les traces à activer lors de vos développements. Pensez cependant à désactiver toutes ces traces en Re7 et en prod bien sûr...