Hibernate Logging Tips

Chiunque usi Hibernate prima o poi ha la necessità di capire, per debug o per ottimizzazione, come la query scritta utilizzando i Criteria oppure JPQL venga tradotta in SQL nativo.

Il modo più comune, ma che vi sconsiglio, di ottenere questo risultato è quello di impostare a true la property hibernate.show_sql. Ad esempio se stiamo utilizzando Hibernate tramite Spring e JPA dovremo configurare l'entity manager con qualcosa del genere:

<bean id="em" class="org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean"> <property name="dataSource" ref="ds"/> <property name="jpaVendorAdapter"> <bean class="org.springframework.orm.jpa.vendor.HibernateJpaVendorAdapter"> <property name="database" value="MYSQL" /> <property name="showSql" value="true" /> </bean> </property> <property name="persistenceUnitName" value="vlt" > </bean>

Così facendo vedrete in output qualcosa del genere (ovviamente la query cambierà in base a come sono stati mappati i vostri DAO)

Hibernate: select subject0_.id as id1_1_, subject0_.name as name1_2_ from subject subject0_ inner join node subject0_1_ on subject0_.id=subject0_1_.id where subject0_.name like ? limit ?

Il problema di questa soluzione è che vi mostra la query, ma non vi mostra i parametri che vengono passati alla query (vedete infatti solo i punti interrogativi).

La soluzione che vi consiglio invece è la seguente:

• lasciate a false la variabile hibernate.show_sql
• impostare il logger "org.hibernate.SQL" a "debug" (questo vi permetterà di visualizzare la query)
• impostare il logger "org.hibernate.type.descriptor.sql" a "trace" (questo vi permetterà di visualizzare i parametri passati in input alla query ed anche i risultati ottenuti)

L'output, adesso completo di tutto, sarà qualcosa del genere

2016-10-10 21:00:17,929 DEBUG - select subject0_.id as id1_1_, subject0_.name as name1_2_ from subject subject0_ inner join node subject0_1_ on subject0_.id=subject0_1_.id where subject0_.name like ? limit ? 2016-10-10 21:00:18,006 TRACE - binding parameter [1] as [VARCHAR] - [%prova%] 2016-10-10 21:00:18,054 TRACE - extracted value ([id1_1_] : [BIGINT]) - [4] 2016-10-10 21:00:18,071 TRACE - extracted value ([name1_2_] : [VARCHAR]) - [prova]

Se utilizzate Log4j2 questa configurazione è possibile ottenerla così:

<?xml version="1.0" encoding="UTF-8"?> <Configuration> <Appenders> <Console name="STDOUT" target="SYSTEM_OUT"> <PatternLayout pattern="%d %-5p - %m%n"/> </Console> </Appenders> <Loggers> <Logger name="org.hibernate.SQL" level="debug"/> <Logger name="org.hibernate.type.descriptor.sql" level="trace"/> <Root level="info"> <AppenderRef ref="STDOUT"/> </Root> </Loggers> </Configuration>