Cómo trazar los sql en java e Hibernate

Descripción del problema 

Si usas Hibernate seguramente estarás cansado de ver trazas con los prepared statement y sus símbolos de interrogación "?".  O bien ver las consultas SQL y no poder ver los resultados de la misma sin tener que echar una linea de código. Te parecería interesante que se mostrasen los resultados en el Log:

Pues veras que fácil es la solución.

Solución

log4jdbc-log4j2 es un driver JDBC que actúa como proxy. Este permite trazar todas las llamadas JDBC y las sentencias SQL usando log4J y SLF4J.

Lo primero es agregar las dependencias al proyecto de las librerias de log4jdbc. La versión de la librería dependerá de la versión de JDK que estés utilizando:

• log4jdbc-log4j2-jdbc3.jar para JDBC 3 que es soportado en  JDK 1.5. 
• log4jdbc-log4j2-jdbc4.jar for JDBC 4 que es soportado en  JDK 1.6.
• log4jdbc-log4j2-jdbc4.1.jar for JDBC 4.1 support in JDK 1.7

En Maven habría que agregar las dependencias de la siguiente forma:

  org.bgee.log4jdbc-log4j2
  log4jdbc-log4j2-jdbcXX
  1.16

Hay que agregar el fichero log4jdbc.log4j2.properties a nivel de classpath. Este fichero sirve para indicarle al driver que tipo de logger usar (Log4j2, SLF4J)

log4jdbc.spylogdelegator.name=net.sf.log4jdbc.log.slf4j.Slf4jSpyLogDelegator

#Optional parameters
#log4jdbc.debug.stack.prefix=^
#log4jdbc.sqltiming.warn.threshold=
#log4jdbc.dump.sql.select=false
#log4jdbc.dump.sql.insert=false
#log4jdbc.dump.sql.update=false
#log4jdbc.dump.sql.delete=false

También se puede agregar como propiedades del sistema en el momento de ejecutar una clase:

-Dlog4jdbc.spylogdelegator.name=net.sf.log4jdbc.log.slf4j.Slf4jSpyLogDelegator

El siguiente paso es la configuración de los Loggers. En función de los datos que nos interesa monitorizar, activamos los loggers requeridos. Por ejemplo vamos a configurar log4j.xml, para que imprima un conjunto de resultados en formato de tabla y también el tiempo necesario para ejecutar cada consulta.

Después de configurar los loggers, ejecute el código y puedes observar las trazas.

create table Item (id bigint generated by default as identity, price double not null, product 
varchar(255), quantity integer not null, order_id bigint, primary key (id))  {executed in 10 msec}
create table T_ORDER (id bigint generated by default as identity, customer varchar(255), primary 
key (id))  {executed in 1 msec}
alter table Item add constraint FK22EF339F325255 foreign key (order_id) references T_ORDER 
{executed in 11 msec}
insert into T_ORDER (id, customer) values (null, NULL)  {executed in 1 msec}
insert into Item (id, order_id, price, product, quantity) values (null, NULL, 0.0, NULL, 0) 
{executed in 0 msec}
batching 1 statements: 0: update Item set ORDER_ID=1 where id=1  {executed in 2 msec}
insert into T_ORDER (id, customer) values (null, NULL)  {executed in 0 msec}
insert into Item (id, order_id, price, product, quantity) values (null, NULL, 0.0, NULL, 0) 
{executed in 0 msec}
batching 1 statements: 0: update Item set ORDER_ID=2 where id=2  {executed in 0 msec}
select order0_.id as id1_0_, order0_.customer as customer1_0_ from T_ORDER order0_ where order0_.id=2 
{executed in 0 msec}
|---------|---------|
|ID       |CUSTOMER |
|---------|---------|
|[unread] |null     |
|---------|---------|
select items0_.ORDER_ID as ORDER5_1_2_, items0_.id as id2_, items0_.id as id0_1_, items0_.order_id 
as order5_0_1_, items0_.price as price0_1_, items0_.product as product0_1_, items0_.quantity 
as quantity0_1_, order1_.id as id1_0_, order1_.customer as customer1_0_ from Item items0_ left 
outer join T_ORDER order1_ on items0_.order_id=order1_.id where items0_.ORDER_ID=2  {executed in 0 msec}
|---------|---|---|---------|------|--------|---------|---|---------|
|ORDER_ID |ID |ID |ORDER_ID |PRICE |PRODUCT |QUANTITY |ID |CUSTOMER |
|---------|---|---|---------|------|--------|---------|---|---------|
|2        |2  |2  |2        |0.0   |null    |0        |2  |[unread] |
|---------|---|---|---------|------|--------|---------|---|---------|
insert into T_ORDER (id, customer) values (null, NULL)  {executed in 0 msec}
insert into Item (id, order_id, price, product, quantity) values (null, NULL, 0.0, 'foo', 0) 
{executed in 0 msec}
batching 1 statements: 0: update Item set ORDER_ID=3 where id=3  {executed in 0 msec}
select order0_.id as id1_, order0_.customer as customer1_ from T_ORDER order0_ inner join Item 
items1_ on order0_.id=items1_.ORDER_ID where items1_.product='foo' limit 2  {executed in 6 msec}
|---|---------|
|ID |CUSTOMER |
|---|---------|
|3  |null     |
|---|---------|
select items0_.ORDER_ID as ORDER5_1_2_, items0_.id as id2_, items0_.id as id0_1_, items0_.order_id 
as order5_0_1_, items0_.price as price0_1_, items0_.product as product0_1_, items0_.quantity 
as quantity0_1_, order1_.id as id1_0_, order1_.customer as customer1_0_ from Item items0_ left 
outer join T_ORDER order1_ on items0_.order_id=order1_.id where items0_.ORDER_ID=3  {executed in 0 msec}
|---------|---|---|---------|------|--------|---------|---|---------|
|ORDER_ID |ID |ID |ORDER_ID |PRICE |PRODUCT |QUANTITY |ID |CUSTOMER |
|---------|---|---|---------|------|--------|---------|---|---------|
|3        |3  |3  |3        |0.0   |foo     |0        |3  |[unread] |
|---------|---|---|---------|------|--------|---------|---|---------|

Si utilizas logback.xml, puedes agregar los loggers de esta forma

  

    
        
        logs/access-%d{yyyy-MM-dd}.log
        
        10
    
    
        %d{HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n
    
    
    
        INFO
        ACCEPT
        DENY 
    
    
    
        10MB
    









    

Cómo detectar bloqueos en Oracle

Uno de los errores comunes que ocurren en cualquier sistema informático es el bloqueo de tablas. Si has trabajado con Java y algún framework (PDA, Hibernate, iBatis ) seguramente te has encontrado con un error típico:

• org.hibernate.exception.GenericJDBCException: Could not open connection
• SQLException: Connections could not be acquired from the underlying database!
• om.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@4f8244b -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!
• 
  

Posiblemente haya ocurrido un Deadlock. Si tenemos acceso, con privilegios de administrador, a la base de datos podemos revisar los logs y detectar el error.

¿Qué es un Deadlock? 

Un Deadlock es cuando un mínimo de 2 usuarios se quedan esperando algún dato que está siendo bloqueado por alguna otra sesión. Si ésto sucede, los usuarios involucrados en el Deadlock deben esperar y no pueden continuar con el procesamiento.

En mi caso, hablaremos de detectar bloqueos en la base de datos de Oracle.

Detectar el bloqueo en Oracle

Cuando Oracle detecta que se produjo un Deadlock, lo que hace es parar la ejecución del procedimiento y mostrar el siguiente mensaje de error: ORA-00060: deadlock detected while waiting for resource. Cuando se produce un error como este, Oracle genera un archivo de trace en el directorio UDUMP con información acerca del error.

En Oracle hay una vista v$lock que indica los objetos que se encuentran en bloqueo, el identificador de usuario, sesion y el tipo de bloqueo. Si realizamos un join con la tabla dba_objects podemos obtener el nombre y tipo de los objetos bloqueados:

SELECT
  decode(L.TYPE,'TM','TABLE','TX','Record(s)') TYPE_LOCK,
  decode(L.REQUEST,0,'NO','YES') WAIT,
  S.OSUSER OSUSER_LOCKER,
  S.PROCESS PROCESS_LOCKER,
  S.USERNAME DBUSER_LOCKER,
  O.OBJECT_NAME OBJECT_NAME,
  O.OBJECT_TYPE OBJECT_TYPE,
  concat(' ',s.PROGRAM) PROGRAM,
  O.OWNER OWNER
FROM v$lock l,dba_objects o,v$session s
WHERE 
  l.ID1 = o.OBJECT_ID
  AND s.SID =l.SID
  AND l.TYPE in ('TM','TX');

Los dos tipos de bloqueos:

• (TM) bloqueos de tablas
• (TX) bloqueos a nivel de fila

Bloqueos de tablas

Los bloqueos a nivel de tabla son creados cuando se ejecuta una sentencia DML del tipo: update, insert, delete, select ..for update sobre la tabla entera.

Un ejemplo de sentencias DML:

DELETE from mitabla;

UPDATE mitabla SET campo1 = valor;

Bloqueos a nivel de fila

Los bloqueos a nivel de fila se crean cuando se ejecutan sentencias DML contra un conjunto de registros específicos. La siguiente consulta nos permite rápidamente saber que procesos están bloqueados. Si ademas hacemos un join con v$open_cursor podemos ver que consulta es la que se encuentra parada a la espera de que se produzca el desbloqueo para poder ejecutarse.

En la consulta siguiente podemos ver las sentencias paradas y el id de proceso que las esta bloqueando.

-- Esta query permite ver los objetos que estan esperando 
-- a que termine un bloqueo y la sentencia que quieren ejecutar. 
-- el id de proceso nos da la pista de quien esta bloqueando.

select /*+ ordered
no_merge(L_WAITER)
no_merge(L_LOCKER) use_hash(L_LOCKER)
no_merge(S_WAITER) use_hash(S_WAITER)
no_merge(S_LOCKER) use_hash(S_LOCKER)
use_nl(O)
use_nl(U)
*/
/* first the table-level locks (TM) and mixed TM/TX TX/TM */
S_LOCKER.OSUSER OS_LOCKER,
S_LOCKER.USERNAME LOCKER_SCHEMA,
S_LOCKER.PROCESS LOCKER_PID,
S_WAITER.OSUSER OS_WAITER,
S_WAITER.USERNAME WAITER_SCHEMA,
S_WAITER.PROCESS WAITER_PID,
'Table lock (TM): '||U.NAME||'.'||O.NAME||
' - Mode held: '||
decode(L_LOCKER.LMODE,
0, 'None', /* same as Monitor */
1, 'Null', /* N */
2, 'Row-S (SS)', /* L */
3, 'Row-X (SX)', /* R */
4, 'Share', /* S */
5, 'S/Row-X (SSX)', /* C */
6, 'Exclusive', /* X */
'???: '||to_char(L_LOCKER.LMODE))||
' / Mode requested: '||
decode(L_WAITER.REQUEST,
0, 'None', /* same as Monitor */
1, 'Null', /* N */
2, 'Row-S (SS)', /* L */
3, 'Row-X (SX)', /* R */
4, 'Share', /* S */
5, 'S/Row-X (SSX)', /* C */
6, 'Exclusive', /* X */
'???: '||to_char(L_WAITER.REQUEST))
SQL_TEXT_WAITER
from
V$LOCK L_WAITER,
V$LOCK L_LOCKER,
V$SESSION S_WAITER,
V$SESSION S_LOCKER,
sys.OBJ$ O,
sys.USER$ U
where S_WAITER.SID = L_WAITER.SID
and L_WAITER.TYPE IN ('TM')
and S_LOCKER.sid = L_LOCKER.sid
and L_LOCKER.ID1 = L_WAITER.ID1
and L_WAITER.REQUEST > 0
and L_LOCKER.LMODE > 0
and L_WAITER.ADDR != L_LOCKER.ADDR
and L_WAITER.ID1 = O.OBJ#
and U.USER# = O.OWNER#
union
select /*+ ordered
no_merge(L_WAITER)
no_merge(L_LOCKER) use_hash(L_LOCKER)
no_merge(S_WAITER) use_hash(S_WAITER)
no_merge(S_LOCKER) use_hash(S_LOCKER)
no_merge(L1_WAITER) use_hash(L1_WAITER)
no_merge(O) use_hash(O)
*/
/* now the (usual) row-locks TX */
S_LOCKER.OSUSER OS_LOCKER,
S_LOCKER.USERNAME LOCKER_SCHEMA,
S_LOCKER.PROCESS LOCK_PID,
S_WAITER.OSUSER OS_WAITER,
S_WAITER.USERNAME WAITER_SCHEMA,
S_WAITER.PROCESS WAITER_PID,
'TX: '||O.SQL_TEXT SQL_TEXT_WAITER
from
V$LOCK L_WAITER,
V$LOCK L_LOCKER,
V$SESSION S_WAITER,
V$SESSION S_LOCKER,
V$_LOCK L1_WAITER,
V$OPEN_CURSOR O
where S_WAITER.SID = L_WAITER.SID
and L_WAITER.TYPE IN ('TX')
and S_LOCKER.sid = L_LOCKER.sid
and L_LOCKER.ID1 = L_WAITER.ID1
and L_WAITER.REQUEST > 0
and L_LOCKER.LMODE > 0
and L_WAITER.ADDR != L_LOCKER.ADDR
and L1_WAITER.LADDR = L_WAITER.ADDR
and L1_WAITER.KADDR = L_WAITER.KADDR
and L1_WAITER.SADDR = O.SADDR
and O.HASH_VALUE = S_WAITER.SQL_HASH_VALUE

Ejemplo  

En este ejemplo tenemos la tabla SMT_TESTCASE bloqueada con una sentencia:

SELECT * FROM SMT_TESTCASE FOR UPDATE

(En esta sentencia no se ha realizado el commit), así que cualquier sentencia posterior que intente acceder a la tabla se queda en espera (En este caso se paran las dos sentencias DELETE FROM hasta que la tabla bloqueada ya no este en situación de bloqueo).

Usando la consulta de detección de bloqueos

Usando la consulta de filas bloqueadas

Esta última consulta es muy útil porque podemos anotar el "id del proceso bloqueante" y ejecutando la primera consulta con el id de proceso averiguar que objeto (SMT_TESTCASE) y que tipo se encuentra bloqueado (TABLE).

Se debe tener en cuenta que muchas situaciones de bloqueo se producen porque podemos tener el cliente (por ejemplo el Toad) sin activar la opción de “autocommit”.  Así, que al salir del cliente es cuando se nos indica que realicemos el “commit” o “rollback”.  Pero, si ejecutamos una sentencia DDL sin hacer un “commit”, a continuación podemos provocar una situación de bloqueo a otro proceso que intente actualizar la tabla o filas bloqueadas.

Fuentes de ayuda

Detectar bloqueos en oracle

Deadlocks --> ORA-00060