#

Hibernate Query Logging

Ein Problem mit Hibernate: Möchte man heraus finden, welche Anfragen warum besonders langsam sind, hat man keine Möglichkeit im Kode direkt auf die generierte SQL-Abfrage zu zugreifen. Die einzige Möglichkeit: Jede Menge Logging.

Eine recht praktische Log4j Konfiguration erhält dabei folgende Zeilen:

<logger name="org.hibernate.engine.query.HQLQueryPlan">
	<level value="debug"/>
</logger>
 
<logger name="org.hibernate.hql.ast.QueryTranslatorImpl">
	<level value="debug"/>
</logger>
 
<logger name="org.hibernate.engine.QueryParameters">
	<level value="debug"/>
</logger>

Dies erzeugt zu Beginn folgende Logmeldungen, insofern Hibernate beim Startvorgang alle vordefinierten Abfragen (Named queries) kompiliert:

2007-10-12 15:54:27,635 DEBUG org.hibernate.hql.ast.QueryTranslatorImpl : parse() – HQL: from narcanti.bo.Someobject so where so.customer=:customer and so.parentVersion=null and so.isDeleted=false
2007-10-12 15:54:27,872 DEBUG org.hibernate.hql.ast.QueryTranslatorImpl : HQL: from narcanti.bo.Someobject so where so.customer=:customer and so.parentVersion=null and so.isDeleted=false
2007-10-12 15:54:27,872 DEBUG org.hibernate.hql.ast.QueryTranslatorImpl : SQL: select someobject0_.id as id20_, someobject0_.customer_id as customer5_20_, someobject0_.country as country20_, someobject0_.parentversion_id as parentv14_20_, someobject0_.isDeleted as isDeleted20_, someobject0_.active as active20_, someobject0_.creationdate as creatio17_20_ from someobjects someobject0_ where someobject0_.customer_id=? and (someobject0_.parentversion_id is null) and someobject0_.isDeleted=0 and someobject0_.active=1
2007-10-12 15:54:27,894 DEBUG org.hibernate.engine.query.HQLQueryPlan : HQL param location recognition took 5 mills (from Someobject so where so.customer=:customer and so.parentVersion=null and so.isDeleted=false)

Sobald im Laufe der Anwendung neue dynamische Queries benutzt werden, erscheint auch hierfür die eintsprechende Logmeldung. So hat man zumindest alle HQL-Queries mit ihrem SQL-Pendant zusammen.
Sobald Abfragen benutzt werden, zeigt das Logging der Klasse QueryParameters an, welche Parameter an eine Abfrage gebunden werden:

2007-10-12 15:54:34,206 DEBUG org.hibernate.engine.query.HQLQueryPlan : find: select count(so.id), so.customer from Someobject so where so.receiveDate>=:from and so.receiveDate<=:to group by so.customer 2007-10-12 15:54:34,206 DEBUG org.hibernate.engine.QueryParameters : named parameters: {to=2007-10-11 23:59:59, from=2007-10-11 00:00:00}
Tags:, , , , , ,

Leave a Reply »»

Note: All comments are manually approved to avoid spam. So if your comment doesn't appear immediately, that's ok. Have patience, it can take some days until I have the time to approve my comments.