In production you may have run into problems where a certain flow is slow, turning hibernate statistics on using the jmx-console would be a good idea, but debugging what actually corresponds to this slow flow could be like searching for a needle in this haystack. The obvious thing would be to organize the data in such a way that all queries for a flow along with their time are presented together. The blog discusses one approach for doing so assuming we are using spring and hibernate.

In our case we were interested in the hql, sql and time taken for them. We were also running into some issues with the session size, so had a piece to capture that too. The whole approach is based on these simple steps:

1. Putting in a flow identifier
2. Inject our own SessionStatsCollector
3. Wire it via JMX
4. Get callbacks for the original sql

Flow identifier
The utility of this approach depends on how easily can we pin point each flow. The url along with the thread id is a good starting point. However if the urls are kind of the same and the request parameters have a special token, we can use that as our flow discriminators. This token is injected into the NDC for the later part of the tool to pick it up and arrange diagnostic information.

Inject SessionStatsCollector
Hibernate does not allow any hook points to the session stats collector, so to get our custom stats collector in, we used a simple cglib proxy for it. The proxy intercepts only queryExecuted and closeSession methods. While queryExecuted is used to capture the hql, time and number of rows, closeSession callbacks helps us log all the collected information together.

Wire it via JMX
Since the original mbean does not support logging flows, the new jmx bean exposes one method profileFlows which takes the flow pattern and a boolean to indicate if the session size should be logged. Determining the session size is a heavy operation, so on most cases we may not want to do so. There is another method to reset the bean which would revert to the original statistics collector from our souped up version.

Sql callbacks
We were interacting with our dba group, for whom the hql was like greek, so the original sql was important to us, since the original stats implementer does not get any callbacks for this, we injected our own entity interceptor which gives a callback to the stats collector for the sql.

So in short with about 8 classes, we can create something which gives us some indicators of the flow performances. The performance and memory overhead introduced by this is nominal and can be turned off at any point.

The classes for this are easy to code, if laziness gets in your way, post a comment and will upload it.