Hibernate Smoke Detector
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.
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:
Set up logger in your application to write all hql queries to a separate file
Run your end-to-end tests (in our case Selenium tests) or just let testers do some clicking through your application
Get sources from https://github.com/tdziurko/hibernate-smoke-detector
mvn clean install
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]
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 :) ):
1 2 3
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:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20
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 :)
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.