Saturday, March 2, 2013

Write your own profiler with JEE6 interceptor

JEE6 interceptors are powerful components that interpose on method invocations and then provide an easy way to execute some given code just before and after method execution.

It is then trivial to build a basic profiler that would consist in starting a stopwatch before some method execution and stopping it just after the end. This can be easily done with a custom annotation to identify methods that are eligible to profiling and an interceptor to handle stopwatch.

The first step is to create the @Profiled annotation:
/**
 * The profiled annotation. Use it to mark methods that must be profiled.
 */
@Inherited
@InterceptorBinding
@Retention(RUNTIME)
@Target({METHOD, TYPE})
public @interface Profiled {
}

The next step is to write the interceptor that deals with methods that have the @Profiled annotation:
/**
 * An interceptor for profiling methods that have the
 * @Profiled annotation.
 */
@Profiled
@Interceptor
public class BasicProfiledMethodInterceptor {

    private static final Logger LOGGER = LoggerFactory.getLogger(BasicProfiledMethodInterceptor.class);

    /**
     * starts a stopwatch before a given method execution and stops it after the
     * method is proceeded. Then logs the elapsed time.
     *
     * @param context the invocation context.
     * @return the object produced by the method execution.
     * @throws Exception if an error occurs.
     */
    @AroundInvoke
    public Object profile(InvocationContext context) throws Exception {

        // starts the stopwatch
        final long startTime = System.currentTimeMillis();

        // executes the method that is profiled
        Object o = context.proceed();

        // stops the stopwatch and computes elapsed time
        final long elapsedTime = System.currentTimeMillis() - startTime;

        // logs method and time
        final String methodSignature = context.getMethod().toString();
        LOGGER.info("Profiled Method: {} in {} ms", methodSignature, elapsedTime);

        return o;
    }
}

Notice that logging is done with SLF4J and Logback in this example, but it is up to you to adapt the previous code to use your favorite logging library.

Now, to enable the interceptor, you must put a beans.xml file into the WEB-INF directory of your enterprise application (or META-INF directory with EJB modules or JAR), with the following content:
<?xml version="1.0" encoding="UTF-8"?>

    
        org.javabenchmark.BasicProfiledMethodInterceptor
    


Let's go now with a more sophisticated interceptor, that relies on Metrics (for monitoring) and Guava (for caching monitors) : the idea is to manage method dedicated Timers that are stored inside a cache. The key for retrieving a timer from the cache is the method signature (that also includes package and name of the class).

At the beginning, the cache is empty and when a method is profiled for the first time, a timer is instantiated and put in the cache by a cache loader.

The code of the new interceptor:
/**
 * An interceptor for profiling method executions. Starts a timer before method
 * execution and stops it after. Uses a cache for storing the different timers.
 */
@Profiled
@Interceptor
public class ProfiledMethodInterceptor {

    private static final Logger LOGGER = LoggerFactory.getLogger(ProfiledMethodInterceptor.class);
    /**
     * the cache for all timers. The key for an entry in the cache is the
     * signature of the method that is profiled. Max is 1000 timers.
     */
    private final LoadingCache<String, Timer> timersCache = CacheBuilder.newBuilder()
            .maximumSize(1000)
            .build(
            new CacheLoader<String, Timer>() {
                @Override
                public Timer load(String methodSignature) {
                    return Metrics.newTimer(ProfiledMethodInterceptor.class, methodSignature, TimeUnit.MILLISECONDS, TimeUnit.SECONDS);
                }
            });

    /**
     * gets the corresponding timer for the method being executed, starts it
     * before the execution and stops it after the method is proceeded.
     *
     * @param context the invocation context.
     * @return the object produced by the method execution.
     * @throws Exception if an error occurs.
     */
    @AroundInvoke
    public Object profile(InvocationContext context) throws Exception {

        // gets the corresponding timer
        String methodSignature = context.getMethod().toString();
        final Timer timer = timersCache.get(methodSignature);

        // starts it
        final TimerContext timerContext = timer.time();

        // executes the method that is profiled
        Object o = context.proceed();

        // stops the timer
        timerContext.stop();
        return o;
    }
}

With this interceptor you can now monitor several metrics like invocations per second, duration and percentiles directly via JMX, or by enabling  reporting in logs, CSV files or HTTP as explain there.

You need to update the beans.xml file to enable the new interceptor:
<?xml version="1.0" encoding="UTF-8"?>

    
        org.javabenchmark.ProfiledMethodInterceptor
    


Finally, the dependencies for Metrics and Guava:
        
        
            com.yammer.metrics
            metrics-core
            2.2.0
        
        
        
            com.google.guava
            guava
            13.0.1
        

No comments:

Post a Comment