Cómo trazar las consultas a bdd con Java

Cuando estamos desarrollando aplicaciones que acceden a una base de datos es importante saber qué consultas se están realizando. Si usas JDBC directamente o un JDBCTemplate de Spring en todo momento sabemos qué consultas se van a realizar pero si usamos Hibernate como motor de persistencia es otra cosa.

HIbernate genera automáticamente las consultas con el mapeo que haya definido entre las entidades y las tablas de base de datos y, con ello, se pierde el control de qué consultas se van a ejecutar. Aunque Hibernate escribe un montón de trazas interesantes en el log, a la práctica no son muy útiles.

En el fichero de log se pueden añadir los siguientes packages para trazar:

_{^{log4j.category.org.hibernate.SQL
log4j.category.org.hibernate.jdbc
log4j.category.org.hibernate.engine.query}} 

Trazar el package org.hibernate.SQL permite ver la consulta que Hibertane proporciona al Statement de JDBC pero no se pueden ver los parámetros de la consulta. Por ejemplo, podemos ver la siguiente traza:

^{DEBUG org.hibernate.SQL  – select table10_.ID as TCT1_0_0_, table10_.TCT001_DESCRIPCION as TCT2_0_0_, from SCHEMA.TABLE1 table10_ where table10_.ID=?} 

Si añadimos las trazas del pacakage org.hibernate.jdbc veremos las trazas que hacen rererencia a los PraparedStatement, ResultSets y cuando se abren y cierran las transaccions, como por ejemplo:

_{^{DEBUG org.hibernate.jdbc.AbstractBatcher  – about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
TRACE org.hibernate.jdbc.AbstractBatcher  – preparing statement
DEBUG org.hibernate.jdbc.AbstractBatcher  – about to close ResultSet (open ResultSets: 1, globally: 1)
DEBUG org.hibernate.jdbc.AbstractBatcher  – about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
TRACE org.hibernate.jdbc.AbstractBatcher  – closing statement
TRACE org.hibernate.jdbc.ConnectionManager  – registering flush begin
TRACE org.hibernate.jdbc.ConnectionManager  – registering flush end
TRACE org.hibernate.jdbc.JDBCContext  – before transaction completion
TRACE org.hibernate.jdbc.JDBCContext  – after transaction completion
DEBUG org.hibernate.jdbc.ConnectionManager  – aggressively releasing JDBC connection
DEBUG org.hibernate.jdbc.ConnectionManager  – releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]}} 

Finlamente, con el package org.hibernate.type podremos ver el valor de los parámetros de la query:

^{_{DEBUG org.hibernate.SQL  – select table10_.ID as TCT1_0_0_, table10_.TCT001_DESCRIPCION as TCT2_0_0_, from SCHEMA.TABLE1 table10_ where table10_.ID=?
TRACE org.hibernate.type.StringType  – returning ‘1’ as column: table10_.ID}} 

Estas trazas no son muy útiles cuando tienes muchas consultas y de más de un parámetro.

Para poder ver la consulta exacta que se va a hacer podemos usar log4jdbc. Log4jdbc es un driver que hace de proxy por delante del DataSource de la aplicación y permite trazar a través de log4j todas las consultas que se realicen en la base de datos.

En el siguiente ejemplo usaremos log4jdbc-remix, un fork de log4jdbc, aunque la versión más recomendada hoy en día es log4jdbc-log4j2

Para poder usar esta librería deberemos seguir los siguientes pasos::

1) Añadirel jar de la librería a Maven (o descargarlo manualmente si cabe)

^{_{<dependency>
<groupId>org.lazyluke</groupId>
<artifactId>log4jdbc-remix</artifactId>
<version>0.2.7</version>
</dependency>}} 

2) Añadir al fichero de configuración de log4j lo que se quiere trazar:

^{_{log4j.logger.jdbc=DEBUG
log4j.logger.jdbc.sqltiming=DEBUG
log4j.logger.jdbc.connection=DEBUG
log4j.logger.jdbc.audit =DEBUG
log4j.logger.jdbc.resultset=DEBUG
log4j.logger.jdbc.resultsettable=DEBUG}}

El primer logger Es el que muestra la query SQL completa. El resto nos dá información adicional (consultad la documentación)

3) Modificar la configuración de vuestro DataSource, por ejemplo:

^{_{<bean id=”dataSource” class=”org.apache.commons.dbcp.BasicDataSource” destroy-method=”close”>
<property name=”driverClassName” value=”${jdbc.driver}” />
<property name=”url” value=”${jdbc.url}” />
<property name=”username” value=”${jdbc.user}” />
<property name=”password” value=”${jdbc.password}” />
</bean>}} 

Por el siguiente:

^{_{<bean id=”originalDataSource” class=”org.apache.commons.dbcp.BasicDataSource” destroy-method=”close”>
<property name=”driverClassName” value=”${jdbc.driver}” />
<property name=”url” value=”${jdbc.url}” />
<property name=”username” value=”${jdbc.user}” />
<property name=”password” value=”${jdbc.password}” />
</bean>}}

^{_{<bean id=”dataSource” class=”net.sf.log4jdbc.Log4jdbcProxyDataSource”>
<constructor-arg ref=”originalDataSource”/>
</bean>}}

He renombrado el bean del DataSource y he creado otro con el nombre anterior del tipo Log4jdbcProxyDataSource. Este bean es el que hará de proxy por delante del DataSource original y serà el encargado de trazar las consultas.

Una vez hemos hecho esto, en el log deberíamos ver las siguientes trazas:

^{_{DEBUG org.hibernate.SQL  – select table10_.ID as table10_ID, table10_.DESCRIPTION as table10_DESCRIPTION, from SCHEMA.TABLE1 table10_ where table10_.ID=?
TRACE org.hibernate.type.StringType  – returning ‘1’ as column: table10_.ID
INFO  jdbc.sqlonly  – SQL:SELECT ID, DESCRIPTION FROM SCHEMA.TABLE1 WHERE ID = 1}}

A nivel de INFO vemos la consulta real que se va a ejecutar.

Esta librería, recientemente me ha ayudad a optmizar un proceso reduciendo los accesos a la base de datos considerablemente y, por consiguiente, el tiempo de ejecución. Seguramente existen otras librerías más nuevas y potentes que te permiten realizar lo mimsmo que log4jdbc así que, si queréis, os animo a que expliquéis. vuestras experiencias

Nota final: En este artículo, cuando hable de d’Hibernate hago referencia a la versión 3.2.x. Desconozco si en versiones posteriores existen mejores trazas.