Hace poco me vi en la necesidad de analizar los queries que genera Hibernate, pero la información que estaba necesitando era relacionada a los valores de los parámetros que recibía mi query.
Hibernate posee un par de opciones bastante conocidas para mostrar el SQL generado, una es agregar el parámetro "hibernate.show_sql" con valor true, en la configuración del SessionFactory. Como acotación al margen, existen otros dos parámetros interesantes: "hibernate.format_sql", el cual si el valor es verdadero, formatea la sentencia SQL generada (útil cuando analizamos consultas complejas), y la otra es "hibernate.use_sql_comments", que cuando tiene el valor verdadero agrega a las sentencias, comentarios relevantes (ej.: se está persistiendo la clase com.xxxx.yyyy.ClaseZZZ). Este enfoque tiene la contra de que se usa la salida estándard (no es compatible con frameworks de logging como log4j) y además no muestra los parámetros utilizados para ejecutar la consulta.
Otra opción es configurar el output mediante log4j. En este caso es necesario activar el logger "org.hibernate.SQL". Luego de hacerlo, hibernate comenzará a mostrar las líneas por nuestros appenders configurados, lo cual es mejor que el escenario anterior, pero sigue sin mostrar los parámetros. Sin embargo existe otro logger, el cual si permite mostrar esta información: "org.hibernate.type". El problema es que si tenemos varios parámetros, los va a mostrar en muchas líneas:
Hibernate: INSERT INTO transactions (CHANGE, CLOSE, DATE, OPEN, CURRENT_ID, VOLUME)
VALUES (?, ?, ?, ?, ?, ?)
15:33:07,243 DEBUG FloatType:133 - binding '10.0' to parameter: 1
15:33:07,243 DEBUG FloatType:133 - binding '1.2' to parameter: 2
15:33:07,243 DEBUG DateType:133 - binding '30 December 2009' to parameter: 3
15:33:07,259 DEBUG FloatType:133 - binding '1.4' to parameter: 4
15:33:07,259 DEBUG IntegerType:133 - binding '12' to parameter: 5
15:33:07,259 DEBUG LongType:133 - binding '344444' to parameter: 6
Por lo tanto me dispuse a buscar otra solución, que de paso me sirviera para mostrar todas las sentencias SQL que se vayan generando, incluso, porque no, otras que no provengan de Hibernate mismo.
Me encontré con el proyecto
Log4JDBC, el cual era más o menos lo que estaba necesitando. Luego de analizarlo me encontré con el problema de que no funciona muy bien con aplicaciones que usan pooles de conexiones provistos por el application server (en mi caso Tomcat), y era complicado de configurar para que funcione correctamente.
Continuando la búsqueda me encontré con un fork:
Log4JDBCRemix, que si bien, advierten de ser bastante experimental, funciona de maravillas. La diferencia con Log4JDBC original, es que es más amigable a Maven, y además más simple de configurar, porque funciona como un wrapper de un datasource.
A grandes rasgos, para hacerlo andar es necesario hacer lo siguiente:
1) Agregar la dependencia Maven:
<dependency>
<groupId>org.lazyluke</groupId>
<artifactId>log4jdbc-remix</artifactId>
<version>0.2.7</version>
</dependency>
2) Si se usa spring, agregar un bean que funcione como indirección al verdadero datasource:
<bean id="dataSourceSpied" class="...">
<property name="driverClass" value="${datasource.driverClassName}"/>
<property name="jdbcUrl" value="${datasource.url}"/>
<property name="user" value="${datasource.username}"/>
<property name="password" value="${datasource.password}"/>
...
</bean>
<bean id="dataSource" class="net.sf.log4jdbc.Log4jdbcProxyDataSource">
<constructor-arg ref="dataSourceSpied" />
</bean>
3) Configurar que mostrar finalmente en el log (en mi caso, solo necesitaba la sentencia con los parámetros reemplazados):
log4j.logger.jdbc.audit=FATAL
log4j.logger.jdbc.resultset=FATAL
log4j.logger.jdbc.resultsettable=FATAL
log4j.logger.jdbc.sqlonly=DEBUG
log4j.logger.jdbc.sqltiming=FATAL
log4j.logger.jdbc.connection=FATAL
Al momento de usar el aplicativo, vamos a poder ver en nuestro archivo de log, todas las sentencias SQL logueadas con los parámetros correspondientes, reemplazados en la misma línea:
29.07.2013 23:49:05 DEBUG (Slf4jSpyLogDelegator.java:232) - org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)
5. select groups0_.id_user as id2_3_1_, groups0_.id_group as id1_1_, group1_.id_group as id1_1_0_,
group1_.creation_date as creation2_1_0_, group1_.last_modification_date as last3_1_0_, group1_.creation_user
as creation4_1_0_, group1_.last_modification_user as last5_1_0_, group1_.name as name1_0_ from
public.groups_users groups0_ inner join groups group1_ on groups0_.id_group=group1_.id_group
where groups0_.id_user=45
29.07.2013 23:49:06 DEBUG (Slf4jSpyLogDelegator.java:232) - org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)
6. select roles0_.id_group as id1_1_1_, roles0_.id_role as id2_1_, role1_.id_role as id1_2_0_,
role1_.creation_date as creation2_2_0_, role1_.last_modification_date as last3_2_0_, role1_.creation_user
as creation4_2_0_, role1_.last_modification_user as last5_2_0_, role1_.name as name2_0_, role1_.id_super_role
as id7_2_0_ from public.groups_roles roles0_ inner join roles role1_ on roles0_.id_role=role1_.id_role
where roles0_.id_group=44
Luego de usarlo, me enteré de que existe un nuevo proyecto, denominado
log4jdbc-log4j2, que posee todas las mejoras de
Log4JDBCRemix, y algunas más.
