Thoughts on…

Java Middleware & Systems Management

Performance Monitoring using Hibernate

with 13 comments

Performance monitoring is, by its very nature, a slippery slope. Once you start looking for inefficiencies in code, it’s easy to get carried away wanting to optimize every last line for supreme efficiency. It’s thus important to balance the value of an optimization versus the time spent investigating the proper fix, the effort and difficulty required to implement it, and its importance relative to other things on the roadmap.

Every environment, every team, and every piece of software is different – so I won’t dare try to formulate any hard and fast rules for what is an appropriate or inappropriate amount of optimization. Suffice it to say, before any decisions can be made as to whether an optimization should be implemented, the nature of the problem must be understood. Below I will show how to use functionality built into Hibernate to help understand where the performance issues in your application lie as well as the nature of each.

—–

The first thing to do is to turn on Hibernate Statistics.

Once enabled, this service will start recording metrics on a per session factory basis. However, we’re going to want to collect “windows” of information from the statistics object. These windows will help us answer questions such as how many entities were loaded during a particular session bean method call or how many database roundtrips were required to render an entire page of the UI.

So let’s implement a kind of “stop watch” that will take a snapshot of some of the more interesting metrics offered through the statistics API. We’ll record the values of the metrics at two different points in time, and then calculate the delta metrics for hand-off to a logger or some analyzer.

public class HibernateStatisticsStopWatch {

    private org.hibernate.stat.Statistics stats;

    // some interesting metrics
    long queryExecutions;
    long transactions;
    long entityLoads;
    long connects;
    long time;

    public HibernateStatisticsStopWatch() {
        this.stats = // get statistics service from the MBeanServer
    }

    public void start() {
        queryExecutions = -stats.getQueryExecutionCount();
        transactions = -stats.getTransactionCount();
        entityLoads = -stats.getEntityLoadCount();
        connects = -stats.getConnectCount();
        time = -System.currentTimeMillis();
    }

    public void stop() {
        queryExecutions += stats.getQueryExecutionCount();
        transactions += stats.getTransactionCount();
        entityLoads += stats.getEntityLoadCount();
        connects += stats.getConnectCount();
        time += System.currentTimeMillis();
    }

    // getter methods for various delta metrics

    public String toString() {
        return "Stats" 
            + "[ queries=" + queryExecutions 
            + ", xactions=" + transactions 
            + ", loads=" + entityLoads 
            + ", connects=" + connects 
            + ", time=" + time + " ]";
    }
}

Since the idea is to instrument all different parts of the codebase with these stopwatches, things could get rather hairy and difficult to manage over time. That’s why it’s prudent to create a central authority to manage them. The centralization will make it easy to turn off/on the logging across the system, or even enable/disable the stopwatches themselves.

import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.ConcurrentMap;
import java.util.concurrent.atomic.AtomicLong;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;

public class HibernatePerformanceMonitor {
    private static final Log log = LogFactory.getLog(HibernatePerformanceMonitor.class);

    private ConcurrentMap<Long, HibernateStatisticsStopWatch> watches;
    private AtomicLong idGenerator = new AtomicLong(0);
    private static HibernatePerformanceMonitor singleton = 
        new HibernatePerformanceMonitor();

    private HibernatePerformanceMonitor() {
        watches = new ConcurrentHashMap<Long, HibernateStatisticsStopWatch>();
    }

    public static HibernatePerformanceMonitor get() {
        return singleton;
    }

    public long start() {
        if (log.isDebugEnabled()) {
            HibernateStatisticsStopWatch watch = new HibernateStatisticsStopWatch();
            long id = idGenerator.incrementAndGet();
            watches.put(id, watch);
            watch.start();
            return id;
        }
        return 0;
    }

    public void stop(long id, String callingContext) {
        if (log.isDebugEnabled()) {
            HibernateStatisticsStopWatch watch = watches.remove(id);
            if (watch == null) {
                // could happen if debugging was enabled after start() was called
                return;
            }
            watch.stop();
            String caller = (callingContext == null ? "(unknown)" : callingContext);
            log.debug(watch.toString() + " for " + caller);
        }
    }
}

With these two items in place – the stopwatch class and the centralized, thread-safe manager for them – we’re now ready to instrument the application. If you want to monitor the performance of any particular block of code, all you have to do is:

long correlationId = HibernatePerformanceMonitor.get().start();
...
// some XYZ code block that appears not to perform well
...
HibernatePerformanceMonitor.get().stop(correlationId, "XYZ Code Block");

This, however, could get tedious if you had to instrument a few dozen places like this all over the code base. More problematic is the fact that you have to be nearly clairvoyant to know where issues might be without either seeing significant slowness in your application during normal QA, seeing performance degradation during scale testing, or having customer-filed support tickets.

Therefore, it would be nice to get an overall profile of the application first, before digging down into specific parts and wrapping smaller code blocks to see how they perform in isolation. Since RHQ‘s backend is written as a set of stateless session bean services, I can simply add an interceptor to get metrics for all method invocations across the entire system:

public class PerformanceMonitorInterceptor {
    @AroundInvoke
    public Object monitorHibernatePerformance(InvocationContext context) 
    throws Exception {
        String callingContext = 
                context.getMethod().getDeclaringClass().getSimpleName() + "." + 
                context.getMethod().getName();
        long monitorId = HibernatePerformanceMonitor.get().start();
        Object results = context.proceed();
        HibernatePerformanceMonitor.get().stop(monitorId, callingContext);
        return results;
    }
}

Make sure you add this interceptor declaration to your ejb-jar.xml file:

<ejb-jar>
   ...
   <assembly-descriptor>
      <interceptor-binding>
         <ejb-name>*</ejb-name>
         <interceptor-class>your.package.PerformanceMonitorInterceptor</interceptor-class>
      </interceptor-binding>
   </assembly-descriptor>
</ejb-jar>

Once this is all deployed, all you have to do is start clicking around your application and the performance information will start flowing to the server logs. Below is a snapshot of what is produced when visiting the inventory browser in RHQ:

01:04:03,165 DEBUG [HibernatePerformanceMonitor] 
    Stats[ queries=2, xactions=0, loads=0, connects=2, time=2 ]
    for ResourceGroupManagerBean.getResourceGroupCountByCategory 
01:04:03,166 DEBUG [HibernatePerformanceMonitor] 
    Stats[ queries=2, xactions=0, loads=0, connects=2, time=1 ]
    for GroupDefinitionManagerBean.getGroupDefinitionCount 
01:04:03,167 DEBUG [HibernatePerformanceMonitor] 
    Stats[ queries=13, xactions=0, loads=0, connects=13, time=12 ] 
    for ResourceBossBean.getInventorySummary 

Although these metrics will help you to determine if any individual SLSB method is a bottleneck, it is difficult to know how these methods are composed together to render larger functional chucks of your application. Since RHQ uses JSF/Facelets, we can capture the end-to-end cost of rendering a View with a ViewHandler:

public class PerformanceMonitorViewHandler extends FaceletViewHandler {
    ...
    @Override
    public void renderView(FacesContext context, UIViewRoot viewToRender) 
    throws IOException, FacesException {
        String callingContext = "URL " + viewToRender.getViewId();
        long monitorId = HibernatePerformanceMonitor.get().start();
        super.renderView(context, viewToRender);
        HibernatePerformanceMonitor.get().stop(monitorId, callingContext);
    }
}

Make sure you add this view handler declaration to your faces-config.xml file:

<faces-config ...>
   <application>
      <view-handler>your.package.PerformanceMonitorViewHandler</view-handler>
   </application>
</faces-config>

Now as you click around the application, the URL performance metrics appear end the end of each block of method-level metrics:

...
01:04:03,167 DEBUG [HibernatePerformanceMonitor] 
    Stats[ queries=13, xactions=0, loads=0, connects=13, time=12 ] 
    for ResourceBossBean.getInventorySummary 
...
2010-03-24 03:32:51,674 DEBUG [HibernatePerformanceMonitor] 
    Stats[ queries=19, xactions=27, loads=46, connects=64, time=622 ] 
    for URL /rhq/inventory/browseResources.xhtml 

OK, great. We have all of these performance metrics. Now what do they mean? How does one sift through the hundreds (if not thousands) of services calls to pinpoint application bottlenecks? Well…instead of paging through all of these raw metrics, it’s a lot easier to come up with a set of performance “equations”. Once you formulate these application-specific patterns to look for potential issues, you can trim down the log file by recording only the instances where certain thresholds were violated.

For instance, you might want to look for “slowness” in your application, which could be defined as some URL that takes longer than 3 seconds to load end-to-end, or an individual method that takes more than 500 milliseconds to return. This is easily obtained because the stopwatch records the amount of time between the calls to start() and stop(), and we’ve instrumented our codebase to wrap all SLSB method calls as well as all JSF views.

Another thing to look out for is the classic “N+1 selects” problem. Luckily, instances of this can be found by comparing the ratio of connects to query executions and entity loads. If you have many more connects than queries / loads (say 5 connects or more for each query / load) it’s likely the method in question suffers from the N+1 problem and is making many more trips to the database than should be necessary.

Fortunately, the “N+1 selects” problem is not the only issue that can be determined using derivative metrics. It’s also possible to find excessive transactions by comparing the ratio of transactions to query executions / entity loads. If you find many more transactions than queries / loads, chances are you have a method already inside a transaction that is calling into other methods that start their own transactions. This may in fact by the intended semantic, but not always. Regardless, if the inner methods are called in tight loops, the number of transactions required to carry out a single business workflow can explode. So obtaining this derivative metric can help determine whether your SLSB methods need to be refactored to carry out the business workflows in more appropriately sized transactional chunks. In general, though, it’s a good idea to be on the lookout for any single SLSB method that uses excessive transactions, regardless of the number of queries / loads.

All of these rules can be captured in just a few lines of code. Instead of logging every single method / URL in the HibernatePerformanceMonitor, can we instead narrow our focus by logging only those invocations that violate our rules:

public class HibernatePerformanceMonitor {
    ...
    public void stop(long id, String logPrefix) {
        if (log.isDebugEnabled()) {
            HibernateStatisticsStopWatch watch = watches.remove(id);
            if (watch == null) {
                return; // could happen if debugging was turned on and the start() call was already skipped
            }
            watch.stop();
            if (watch.getTransactions() > 10) {
                debug(watch, "(too many xactions?)", logPrefix);
            }
            if (watch.getQueryExecutions() != 0) {
                if ((watch.getConnects() / (double) watch.getQueryExecutions()) >= 5.0) {
                    // might indicate need for LEFT JOIN FETCHes
                    debug(watch, "(N+1 issue?) ", logPrefix); 
                }
                if ((watch.getTransactions() / (double) watch.getQueryExecutions()) >= 5.0) {
                    // might indicate excessive @REQUIRES_NEW
                    debug(watch, "(xaction nesting?) ", logPrefix); 
                }
            }
            if (watch.getTime() > 3000) {
                // might indicate inefficient query or table contention
                debug(watch, "(slowness?) ", logPrefix); 
            }
        }
    }

    private void debug(HibernateStatisticsStopWatch watch, String cause, String logPrefix) {
        String callingContext = " for " + (logPrefix == null ? "(unknown)" : logPrefix);
        log.debug(watch.toString() + cause + callingContext);
    }
}

It should be noted that these equations are only a starting off point. First, the thresholds they use must be tweaked to more appropriately match performance targets for your application…but even then they will not find every bottleneck in the system. Also, just because some of your business methods or UI pages violate these thresholds does not mean they are necessarily candidates for improvement. It may be the case that a particular page is known to consistently take 20 seconds to render, but it might be OK if it represents an executive report which aggregates lots of data across many subsystems. Another page might seem to use excessive transactions, but that might be OK if it is a system dashboard whose individual portlets are isolated from one another and request data independently.

So I leave it up to the reader to build on this solution and come up with increasingly sophisticated rules that operate off of application-specific thresholds and more accurately track potential issues within their environment.

About these ads

Written by josephmarques

March 24, 2010 at 6:40 pm

Posted in hibernate

Tagged with

13 Responses

Subscribe to comments with RSS.

  1. [...] Performance Monitoring using Hibernate Good stuff. [...]

  2. Good post and a useful utility for preliminary profiling of Hibernate.

    Good point regarding selective optimization. It never ceases to amaze me when people are willing to throw around unsubstantiated comments on application performance etc. and jump in to optimization without first performing appropriate profiling.

    Highlighting ‘smells’ in the generated statistics (HibernatePerformanceMonitor) is a good way to quickly extract the most useful information.

    John

    John Turner

    March 29, 2010 at 5:01 am

  3. Great Post,you helping me in solving monitoring problem. Thank You.

    Keep posting :)

    indra

    November 29, 2010 at 9:41 pm

  4. The example HibernatePerformanceMonitor is excellent — taking the data and turning it into useful information/actionable results!!

    I might suggets adding another check in the watch.getTime() > 3000 control to get a ‘resultCount’ > 500 or similar metric for “too many results, maybe limit” rule.

    dhartford

    February 15, 2011 at 2:29 pm

  5. Aren’t you going to get meaningless results, because, while the stopwatch may be threadlocal, the statistics it’s reading from are shared for the entire SessionFactory? That is, the delta in the stats represent not just the queries run in the current thread, but also every other thread that’s interacting with the SessionFactory. I don’t understand how you can interpret anything meaningful from the results, unless you’re running in a single-threaded environment.

    Andrew McCormick

    July 27, 2011 at 5:51 pm

  6. I have some doubt about how it will work on a multi threaded environnement. That might work on a simple sequential junit test but not in a multithreaded context. I have posted a question about that regarding it here : http://stackoverflow.com/questions/7022493/statistics-with-hibernate-per-thread

    omarus

    August 11, 2011 at 3:48 am

  7. [...] First, while databases might offer simple and easy interfaces, these often reduce the complexity on the surface, trading local simplifications against increased global complexity. For instance, it is often non-trivial to estimate the performance of SQL queries (which in themselves are relatively simple but embedded in the global complexity of the database solution). This problem is highlighted when using further abstraction layers such as an ORM framework. [...]

  8. Reblogged this on Anirban's Empire! and commented:
    Great post on Performance monitoring using Hibernate

    Anirban Chowdhury

    June 14, 2012 at 7:37 am

  9. What a information of un-ambiguity and preserveness of precious knowledge on the topic of unexpected feelings.

  10. Hi! I just wanted to ask if you ever have any trouble with hackers?
    My last blog (wordpress) was hacked and I ended up losing
    many months of hard work due to no backup. Do you have any solutions to prevent
    hackers?

  11. What’s Going down i am new to this, I stumbled upon this I’ve found
    It positively useful and it has aided me out loads. I hope
    to give a contribution & help different customers like its
    aided me. Good job.

  12. Great beat ! I would like to apprentice while you amend
    your site, how can i subscribe for a blog web site?
    The account helped me a acceptable deal. I had been tiny bit acquainted of this your
    broadcast provided bright clear idea

    Mose

    May 31, 2013 at 1:44 pm

  13. Hi there, I found your blog by means of Google at the same time
    as looking for a comparable matter, your site came up, it looks good.
    I’ve bookmarked it in my google bookmarks.
    Hello there, simply turned into aware of your blog through Google, and found that it is really informative. I’m going to
    watch out for brussels. I will appreciate if you continue
    this in future. Many people shall be benefited from your writing.
    Cheers!

    www.przedciaza.pl

    August 6, 2013 at 4:35 pm


Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

%d bloggers like this: