Simplest way to log Hibernate SQL only for current thread/session

Question

I'm looking for simplest way to trace execution time of SQL query generated by Hibernate. Unfortunately it cannot be done in traditional way - just by setting show_sql or hibernate logger, because monitored application is multithread on production environment and sql times tracing should be done only for one service, which is mots problematic. Service means some component running within Spring application. But in my case it is safe to tell, that it is thread - thread is not changed during invocation. Service implementation is a Java method and this method calls others methods, components, etc, everything i one thread. It is possible for me to change one method source and deploy it, but I cannot release application. Unfortunately AspectJ cannot be used as is, because I cannot change whole application, recompile nor plug something into JVM. Unfortunately (next) DB administrators cannot turn on sql queries tracing - they don't know how to do it. Please help, how to tune Hibernate execution without digging the whole application? What is the simplest way?

Facts: Hibernate 3.x, Spring 2.x, java 1.5

Answer 1

Here is how I would do it, assuming you're using Logback as your logging framework.

1. Make sure you have scanning enabled on your logback configuration:

   <?xml version="1.0" encoding="UTF-8"?>

   <configuration debug="false" scan="true" scanPeriod="30 seconds" >

2. Make sure your file logger includes thread name in the output (%t):

   <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">

   <pattern>%d{yyyy-MM-dd HH:mm:ss} %-5p %C{1} %t - %m%n</pattern>

   </encoder>

3. Start with SQL logging turned off:

   <logger name="org.hibernate.SQL" level="OFF">

   <appender-ref ref="FILE_APPENDER"/>

   </logger>

   <logger name="sql-log" level="OFF">

   <appender-ref ref="FILE_APPENDER"/>

   </logger>

4. Once your application is up and running, and you're ready to execute your test, edit the logback.xml file of the deployed application, and change those levels to 'DEBUG'. Then execute your tests. When tests are done, set those levels back to 'OFF'.

5. Look through the log output, and identify the thread name of interest, then grep for that thread name:

   grep "thread-1-pool-7" debug.log > sqldebug.log

A bit cumbersome, but it will work.

Answer 2

You are not very specific about filtering criteria: do you want to filter SQLs by thread/HTTP session or from a given service (sql times tracing should be done only for one service)?

Nevertheless everything can be done on logging framework level. First you need to enable logging of all queries and then filter out non-interesting ones. I am assuming you are using Logback (BTW Spring 2.x and Java 1.5.x are becoming obsolete...):

Per thread

Implement Logback filter and discard logs from not interesting thread. Alternatively use SiftingAppender with thread id as a key. All logs from a given thread will be dispatched to a separate file.

Per HTTP session

This is a bit tricky because you need to get access to HTTP session/session id from logging framework level. The easy way is to use MDC (see example: Logging user activity in web app). Having session id you can do filtering similar to Per thread section.

Per service

It's not obvious what do you mean. Do you only want to log SQL queries issued from a given class or from a class and all the methods and classes it calls? In both cases you need to examine a call stack while filtering, which isn't very effective. Also AspectJ has within directive - too heavyweight for you I guess.

If this is what you want to achive please clarify your question, I have some other ideas.