About a year ago I stumbled upon a great post by Himanshu Seth on the IntelliGrape website about tracking Hibernate stats across Grails actions/requests. It involves: adding a new Grails controller filter to enable stats before a request is processed, letting Grails execute the action, and then logging the stats after the action is finished. I’ve found it very useful as an at-a-glance tool to determine if the work I’ve done in a controller or service has affected the total number of transactions, flush counts, or other performance metrics before and after the change. Since I’ve started using this filter in my code, I’ve added a few extra features that fit my needs and thought I’d share them in case they’re useful.

Baseline filter

Let’s start with a (slightly modified) version of the original code, added to the filters portion of ControllerFilters.groovy:

def sessionFactory

// ...

logHibernateStats(controller: '*', action: '*') {
    before = {
        Statistics stats = sessionFactory.statistics

        log.info "\n### In action: $controllerName/$actionName ###"

        if (!stats.statisticsEnabled) {
            stats.statisticsEnabled = true
        }
    }

    afterView = {
        Statistics stats = sessionFactory.getStatistics()

        log.info """
            ############## Hibernate Stats ##############
            Action: /${controllerName}/${actionName}

            Transaction Count: ${stats.transactionCount}
            Flush Count: ${stats.flushCount}
            Prepared Statement Count: ${stats.prepareStatementCount}
            #############################################
        """

        stats.clear() // We assume no one else is using stats
    }
}

Note the added comment on the stats.clear() call — we assume that our code is the only one using the Hibernate stats, so if there’s any sort of logging going on independently, the clear() method may skew that data.  Furthermore, this filter is intended for development environments and as such should not typically be enabled in prod.  Along with that, I’ve removed some of the stats I don’t typically need, and added logging of the controller name and action name that the request was sent to.  The first call (on line 9) is particularly useful when logSql is enabled, as it gives you a rough idea of which queries were made in an action. Finally, I changed the println() to a log.info() call instead, so be sure that your logging for ‘grails.app.filters’ is set to ‘info’ or lower in the config. Now that we’ve established a new baseline, let’s add a couple of new features.

Logging the elapsed time

Having a timer on the action so we have a general idea of how long the request took could be useful.  We need a way to transmit the start time from the ‘before’ to the ‘afterView’ filter, though, and the request itself seems like a well-scoped object to do that.  Once we have that, we can subtract the start time from the current time to get the total.

private static final String START_TIME = 'Hibernate_Start_Time'

def filters = {
    logHibernateStats(controller: '*', action: '*') {
        before = {
            request[START_TIME] = System.currentTimeMillis()
        }

        afterView = {
            Long end = System.currentTimeMillis()
            Long start = request[START_TIME]

            log.info "Total time: ${end - start} ms"
        }
    }
}

Pretty straightforward, but it’s helpful nonetheless.

Configuration

The last thing I felt I needed was a way to selectively enable Hibernate statistics since there does seem to be a minor performance hit with them and the logging isn’t always needed. Since the filter acts on individual requests, it makes sense to send the “start tracking” signal via HTTP parameters. At the same time, since this feature is intended only for development, we should have a way to enable/disabling the filter per environment. We can do this via the config by creating a new property in Config.groovy:

logHibernateStats = 'NEVER'

// ...

development {
    logHibernateStats = 'ALWAYS' // From ALWAYS, ALLOWED, NEVER
}

As visible from the above snippet, if we set the value to “ALLOWED”, we can invoke the Hibernate logging whenever we need by appending ‘logHibernateStats’ to the request’s params (similar to the debugResources parameter for the Grails Resources plugin) such as \localhost:8080/mySite/controller/action?logHibernateStats=true_. If we don’t send that parameter, then the stats are disabled. If the value is set to “ALWAYS”, then each request will be logged, without the need to send the parameter key. Otherwise we can set the value to “NEVER” for environments like production, so that we do not need to comment out the code when we aren’t using it.

Now we have our final iteration of the filter:

private static final String START_TIME = 'Hibernate_Start_Time'

def sessionFactory

// ...

logHibernateStats(controller: '*', action: '*') {
    before = {
        String enabledString = grailsApplication.config.logHibernateStats
        Statistics stats = sessionFactory.statistics

        if (enabledString == 'ALWAYS' || (enabledString == 'ALLOWED' && params.logHibernateStats)) {
            log.info "\n### In action: $controllerName/$actionName ###"

            if (!stats.statisticsEnabled) {
                stats.statisticsEnabled = true
            }

            request[START_TIME] = System.currentTimeMillis()

        }  else if (enabledString == 'ALLOWED' && stats.statisticsEnabled) {
            stats.statisticsEnabled = false // We assume no one else is using stats
        }
    }

    afterView = {
        String enabledString = grailsApplication.config.logHibernateStats

        if (enabledString == 'ALWAYS' || (enabledString == 'ALLOWED' && params.logHibernateStats)) {
            Long end = System.currentTimeMillis()
            Long start = request[START_TIME]

            Statistics stats = sessionFactory.statistics

            log.info """
                ############## Hibernate Stats ##############
                Action:                     /${controllerName}/${actionName}

                Transaction Count:          ${stats.transactionCount}
                Flush Count:                ${stats.flushCount}
                Prepared Statement Count:   ${stats.prepareStatementCount}

                Total time:                 ${end - start} ms
                #############################################
            """

            stats.clear() // We assume no one else is using stats
        }
    }
}

Caveats

Just a couple points to remember — the logs may not be accurate if you have multiple requests processing in rapid succession, and as such, the filter works best when isolating one controller action at a time. Secondly, the filter assumes that it is the only code using Hibernate stats, so if you use them elsewhere, you may need to more selectively clear or disable the stats.

Igor Shults