Perf4J Integration Plugin

  • Tags : performance, profiling
  • Latest : 0.1.1
  • Last Updated: 08 November 2009
  • Grails version : 1.2-M4 (expects)
  • Authors : null
0 vote
Dependency : 
compile ":perf4j:0.1.1"

Documentation

Summary

Installation

grails install-plugin perf4j

Description

Overview

The Perf4j Plugin integrates the Perf4J profiling library into Grails. Perf4J is a simple yet powerful utility for collecting performance statistics.

It is easily described with this analogy (taken from their website):

Perf4J is to System.currentTimeMillis() as log4j is to System.out.println()

For detailed information, please have a look at the Developer Guide.

Usage

General concepts/Workflow overview

The general idea of Perf4J is to wrap critical code blocks with some timing code, which will then result in a message (including timing information) being logged for each execution of such a code block. Perf4J supports various logging infrastructures, however this plugin sticks with Log4J, since this is the built-in standard for Grails applications. So, basically, each execution of a profiled code block results in a Log4J message like this: 
INFO  perf4j.TimingLogger  - start[1236523341290] time[234] tag[someCodeBlock]
Taken alone, this is not very meaningful. However, Perf4J provides some special Log4J appenders that group these single timing messages together and analyze them. You can for example output min/max/mean execution times as well as TPS for each code block in 30 second intervals, or even let Perf4J generate graphical performance stats via the Google Charts API (also in real time!). See below for further information about appender configuration.

Profiling arbitrary code blocks

To collect performance information, you need to tell the plugin which code blocks should be profiled. The first alternative is to wrap arbitrary code blocks with some special code.

The plugin transparently adds a withStopwatch method to all basic artefacts (controllers, service classes and domain classes). You can use this method to wrap code which should be profiled: 

withStopwatch("myCriticalCodeBlock") {
    // code to be profiled with tag "myCriticalCodeBlock"
}
The string parameter ("myCriticalCodeBlock") is called a tag and is used by Perf4j to identify the code block being timed, eg. to be able to group executions with the same tag and calculate min/max/mean times.

You can also provide a message for each code block: 

withStopwatch("myCriticalCodeBlock", "calculate something") {
    // …
}
For further information about tags and messages, please refer to the Perf4J Developer Guide.

Automatic profiling of service methods

Since service methods are often used to encapsulate business logic, it's a common usecase to profile them as a whole. The plugin makes it easy to do this, without you having to wrap all the service code in withStopwatch{} calls (though you can of course use withStopwatch to do profiling at a more fine-grained level).

There are three alternatives for configuring profiling of service methods, all of which involve declaring a static profiled property in your service classes.

Enable profiling for all methods with defaults

static profiled = true
This causes the plugin to intercept calls to all methods of the respective service. In this case, the tag name is set to ${serviceClassName}.${methodName}, eg. "MyService.testMethod".

Enable profiling for specific methods only

static profiled = ['testMethod1', 'testMethod3']
Here, only the specified methods will be intercepted and profiled. The tag name will be the default, see above.

More flexible configuration via DSL

static profiled = {
    testMethod1()
    testMethod2(tag: "tm2")
    testMethod3(message: "only message")
    testMethod4(tag: "tm4", message: "this is testMethod4()")
}
This is the most flexible way to configure profiling. Only the specified methods will be profiled. If no tag is specified (testMethod1 and testMethod3 in the example), defaults apply as explained above.

Toggle profiling during runtime

Sometimes you may want to toggle profiling on/off during runtime, for example in your admin panel. This way, you could quickly enable profiling in a production system without having to repackage/redeploy the whole application.

Just set the profilingEnabled property (it will be available in controllers, service classes and domain classes): 

profilingEnabled = false

withStopwatch("test") {
    // won't be profiled
}
profilingEnabled = true
testService.someMethod()    // will be profiled (if configured)

Note that this setting is global and survives artefact and request boundaries. However, it is not persisted in any way, so when restarting the application, the setting will be discarded.

Configuration of Log4J appenders

The greatest power of Perf4J lies in its Log4J appenders, which allow to transform the raw collected performance data into meaningful statistics and charts. It's highly recommended that you read the section about log4j appenders in the Perf4J Developer Guide!

The following is just an example to get you started with the Grails syntax for custom appender configuration in Config.groovy (this assumes Grails >= 1.1). For more information on appender configuration in Grails read the logging section in the Grails User Guide.

log4j = {
    appenders {
        // file appender that writes out the URLs of the Google Chart API graphs generated by the performanceGraphAppender
        def performanceGraphFileAppender = new org.apache.log4j.FileAppender(
            fileName: "log/perfGraphs.log",
            layout: pattern(conversionPattern: '%m%n')
        )
        appender name: 'performanceGraphFileAppender', performanceGraphFileAppender
        
        // this appender creates the Google Chart API graphs
        def performanceGraphAppender = new org.perf4j.log4j.GraphingStatisticsAppender(
            graphType: 'Mean',      // possible options: Mean, Min, Max, StdDev, Count or TPS
            tagNamesToGraph: 'tag1,tag2,tag3',
            dataPointsPerGraph: 5
        )
        performanceGraphAppender.addAppender(performanceGraphFileAppender)
        appender name: 'performanceGraph', performanceGraphAppender
        
        // file appender that writes out the textual, aggregated performance stats generated by the performanceStatsAppender
        def performanceStatsFileAppender = new org.apache.log4j.FileAppender(
            fileName: "log/perfStats.log",
            layout: pattern(conversionPattern: '%m%n')  // alternatively use the StatisticsCsvLayout to generate CSV
        )
        appender name: 'performanceStatsFileAppender', performanceStatsFileAppender
        
        // this is the most important appender and first in the appender chain. it aggregates all profiling data withing a certain time frame.
        // the GraphingStatisticsAppender is attached as a child to this appender and uses its aggregated data.
        def performanceStatsAppender = new org.perf4j.log4j.AsyncCoalescingStatisticsAppender(
            timeSlice: 10000    // ms
        )
        performanceStatsAppender.addAppender(performanceStatsFileAppender)
        performanceStatsAppender.addAppender(performanceGraphAppender)
        appender name: 'performanceStatsAppender', performanceStatsAppender
    }
    // configure the performanceStatsAppender to log at INFO level
    info   performanceStatsAppender: 'org.perf4j.TimingLogger'
}

Real-time performance graphs

Perf4J comes with a graphing servlet, which allows real-time performance monitoring by displaying the graphs created by one or more GraphingStatisticsAppenders (see above). This servlet is automatically registered by the plugin. By default, it is only enabled in development mode, reachable via http://localhost:8080/your-app/perf4j and plots the graph created by an appender with the name performanceGraph. You can configure these options via Config.groovy, see below for details.

Configuration

General

  • perf4j.enabled (bool) - Determines whether Perf4J functionality is enabled at all (default: only enabled in development environment)

Graphing Servlet

  • perf4j.graphingServlet.enabled (bool) - Determines whether the graphing servlet (see Real-time performance graphs above) is enabled (default: only enabled in development environment)
  • perf4j.graphingServlet.graphNames (String) - Comma-separated list of GraphingStatisticsAppender names, for which the servlet should draw a real-time graph (default: "performanceGraph")
  • perf4j.graphingServlet.urlPattern (String) - The URL pattern for the servlet (default: "/perf4j")

Roadmap

There is no explicit roadmap for further development. However, some random ideas that might be implemented some day are:
  • lap-support in withStopwatch blocks
  • automatic profiling of controller actions (similar to services) - probably via filters
  • provide access to stats and graphs via Grails controller (with more functionality than GraphingServlet)
  • ...

Help/Feedback

If you have any problems with the plugin or want to provide feedback, please send a mail to the Grails user mailing list (and include "perf4j" somewhere in the subject).

Please report bugs or add feature requests via JIRA.

The project is hosted on GitHub. Feel free to fork and contribute.

Version history

0.1.1 (2009-11-08)

0.1 (2009-10-09)
  • initial release