There is a time in the life of every project when Database Administrator starts to look suspiciously at queries generated by our application. And then he (or she) sends us long list of queries that are not optimized, do not have proper indexes set or are executed multiple times in a very short time. And of course our role is to fix it.

Some issues are hard to solve but most of them are effect of our mistakes: N+1 problem in Hibernate is well-known (e.g. StackOverflow discussion) or checking the same condition (e.g. count something to figure visibility) multiple times for many components on the same page without caching it it any way. Of course we could turn on sql/hql logging during development process but sometimes we might not notice that here or there there is a problem with some query.

Solution

And here comes the solution. Simple parser analyzing hql logs and reporting which queries are executed too often. It’s far from being perfect or super universal but it works I called it Hibernate Smoke Detector.

How it works:

  1. Set up logger in your application to write all hql queries to a separate file
  2. Run your end-to-end tests (in our case Selenium tests) or just let testers do some clicking through your application
  3. Get sources from https://github.com/tdziurko/hibernate-smoke-detector
  4. mvn clean install
  5. Run Hibernate Smoke Detector with your log file: java -jar hibernate-smoke-detector/target/hibernate-smoke-detector-1.0-jar-with-dependencies.jar [your_log_file] >  [your_report_file]
  6. Analyze the report and fix problems.

Hibernate Smoke Detector counts how many times each query was executed in each second, then compiles report starting from queries that have the highest counter. Currently the only drawback is that parser needs specific date time format in the logs, it should look like: 14:10:44,714 DEBUG [org.hibernate.SQL] select …

Below some example settings for JBoss and Logback (thanks Lev for feedback :) ):

pattern="%d{HH:mm:ss,SSS} %-5p [%c] %s%E%n"  // for JBoss Logger

%date{"HH:mm:ss,SSS"} %-5p [%c] %message%ex%n   // for Logback

This part of log is indispensable so parser could put each query to the proper “date-time basket”, so if you want to use if out of the box, you should setup your logger accordingly. If you can not change date format in hql log file, you have to fork the project and change source code a little bit.

Example report might look like presented below:

Report contains all sql commands with the number of executions in each second
Number of executions: 41
Time: 15:07:44
Command:
 select
     count(*)
 from
     PROJECT.client client0
 where
     client0.active=?
----------------------------------
Number of executions: 34
Time: 14:29:03
Command:
 select
     count(*)
 from
     PROJECT.application applic0
 where
     applic0.client_id=?

So if you compare execution times from this report with time of test execution from report generated by your testing library (TestNG, JUnit, etc.) you will be able to find places and actions that fire those queries. And then maybe fix something to make application better and your DBAs  happier :)

Summary

Hibernate Smoke Detector is simple but quite useful parser that checks your application and helps to cut identical queries fired many times in a very short period of time. It generates a report showing which queries are executed most often in a one-second time window and when they fired so developer could find them in his code easily. Using this mini-application should help you to avoid some problems with your queries that often go to the production unnoticed: N+1 problems and duplicated calls to the database checking condition on the same page/view.

Source code is available on GitHub: https://github.com/tdziurko/hibernate-smoke-detector . If you have any comments, please share them below.


Be Sociable, Share!