LendKey

Sunday, May 17, 2009

Monitor detailed SQL transactions issued by Hibernate

Hibernate help us translate access to Java objects from HQL to native SQL and automatically take care of object relationships, which saves developers lots of time, but at the same time, hide lots of details, such as how cross table queries are created, how tables are related and, very important, what data parameters are used for each prepared statetment is called.
To show SQL commands generaeted by Hibernate, we can normally use Hibernate config:
true
With this setting, Hibernate dumps all SQL it executed against DB as below:


Hibernate: select device0_.iid as iid1_0_, device0_.iname as iname1_0_, device0_.iip as iip1_0_, device0_.iinfourl as iinfourl1_0_, device0_.istate as istate1_0_, device0_.irecordState as irecordS6_1_0_, device0_.idevlocation as idevloca7_1_0_ from ieai_device device0_ where device0_.iid=?


However, if you want to see what exact value is passed into the SQL statement, and further more, what result was returned from the SQL command, we need to do more.
Basically we need to set log4j settings of the follow two Hibernate classes into DEBUG:

org.hibernate.SQL
org.hibernate.Type


So the log4j.properties file will have the following settings:

log4j.logger.org.hibernate.SQL=DEBUG,console
log4j.logger.org.hibernate.type=DEBUG,console


Then Hibernate will dump debug information as below:

76033 [DEBUG] AbstractBatcher.log(): - select device0_.iid as iid1_0_, device0_.iname as iname1_0_, device0_.iip as iip1_0_, device0_.iinfourl as iinfourl1_0_, device0_.istate as istate1_0_, device0_.irecordState as irecordS6_1_0_, device0_.idevlocation as idevloca7_1_0_ from ieai_device device0_ where device0_.iid=?
Hibernate: select device0_.iid as iid1_0_, device0_.iname as iname1_0_, device0_.iip as iip1_0_, device0_.iinfourl as iinfourl1_0_, device0_.istate as istate1_0_, device0_.irecordState as irecordS6_1_0_, device0_.idevlocation as idevloca7_1_0_ from ieai_device device0_ where device0_.iid=?
76033 [DEBUG] NullableType.nullSafeSet(): - binding '3' to parameter: 1
76043 [DEBUG] NullableType.nullSafeGet(): - returning 'Device3' as column: iname1_0_
76044 [DEBUG] NullableType.nullSafeGet(): - returning '192.168.0.12' as column: iip1_0_
76044 [DEBUG] NullableType.nullSafeGet(): - returning 'http://www.infolexllc.com/site/' as column: iinfourl1_0_
76047 [DEBUG] NullableType.nullSafeGet(): - returning '1' as column: istate1_0_
76047 [DEBUG] NullableType.nullSafeGet(): - returning '2' as column: irecordS6_1_0_
76048 [DEBUG] NullableType.nullSafeGet(): - returning 'test device location' as column: idevloca7_1_0_


If you are a newbie in Hibernate, you will be amazed to see what is going on underneath by Hibernate, either in a positive and encouraging way or a very bad negative way.

Cheers!

No comments: