In this recipe, we will learn how to add the logging of execution time metrics to any method of a class, without littering the actual method with logging code. Java has used Aspect Oriented Programming (AOP) for many years now to add aspects (or common features) to functions, without having the functions to know that the code was there. It is behavior that looks and smells like it should have a structure, but you can't find a way to express this structure in code with traditional object-oriented techniques.
Metrics is one common aspect that is often added to the code to figure out where the bottleneck is that is keeping you awake at night. Let's look at a typical example:
def createCustomer() { long start = System.currentTimeMillis() ... // Slow operation long spentTime = System.currentTimeMillis() - start log.debug("Execution time: ${spentTime}ms.") }
Imagine repeating such code in hundreds or thousands of methods and you will quickly realize that there should be something better than copy/paste.
It turns out that there is, and it's called invokeMethod
. The invokeMethod
is one of the little things that make Groovy the favorite programming language among magicians.
Consider the following Groovy code:
class Test { def invokeMethod(String name, args) { println "called invokeMethod $name $args" } def test() { println 'in test' } } def t = new Test() t.test() t.bogus('testing!', 1, 2, 3)
This code prints out the following text when run in groovyConsole
:
in test called invokeMethod bogus [testing!, 1, 2, 3]
The first call goes to the test method, as expected. The second call, instead of resulting in a MissingMethodException
, as the bogus
method is not declared on the class, gets routed through the invokeMethod
method. invokeMethod
is a method of the GroovyObject
class.
We will use invokeMethod
along with a marker interface to intercept the calls to the methods of a class and dynamically add logging to each method.
This recipe requires a Gradle build script to compile and execute the code. We have already met Gradle in the Integrating Groovy into the build process using Gradle recipe in Chapter 2, Using Groovy Ecosystem. So, hopefully, you should be comfortable with this build tool.
In a new folder, add a file named build.gradle
with the following code content:
apply plugin: 'groovy' repositories { mavenCentral() } dependencies { compile localGroovy() compile 'ch.qos.logback:logback-classic:1.0.11' compile 'org.slf4j:slf4j-api:1.7.4' }
The build script references the Logback
library, a very popular Java logging framework.
To complete the build setup, create the following folder structure in the same folder where the build file is:
src/main/groovy/org/groovy/cookbook/intercept
src/test/groovy/org/groovy/cookbook/intercept
Let's start by writing a superclass, which hold our logging code:
PerformanceLogger
and place it in the src/main/groovy/org/groovy/cookbook/intercept
folder:package org.groovy.cookbook.intercept import groovy.util.logging.Slf4j import org.codehaus.groovy.runtime.InvokerHelper @Slf4j class PerformanceLogger implements GroovyInterceptable { def invokeMethod(String name, Object args) { long start = System.currentTimeMillis() def metaClass = InvokerHelper.getMetaClass(this) def result = metaClass.invokeMethod(this, name, args) long spentTime = System.currentTimeMillis() - start log.debug("Execution time for method ${name}: " + "${spentTime}ms.") result } }
PerformanceLogger
class to apply the performance logging to each method of a class. Create a new SlowClass
class having the following code:package org.groovy.cookbook.intercept class SlowClass extends PerformanceLogger { void test(String a) { Thread.sleep(rnd()) } /* return a value between 1000 and 5000 */ static rnd() { Math.abs(new Random().nextInt() % 5000 + 1000) } }
src/test/groovy/org/groovy/cookbook/intercept
folder named TestIntercept
:package org.groovy.cookbook.intercept import org.junit.* class TestIntercept { @Test void methodIsIntercepted() { SlowClass sc = new SlowClass() (1..3).each { sc.test('hello') } } }
gradle -i test
yields the following output:... 12:58:22.199 [Test worker] DEBUG o.g.c.intercept.PerformanceLogger - Execution time for method test: 2130 ms. 12:58:23.995 [Test worker] DEBUG o.g.c.intercept.PerformanceLogger - Execution time for method test: 1790 ms. 12:58:26.644 [Test worker] DEBUG o.g.c.intercept.PerformanceLogger - Execution time for method test: 2648 ms. ...
The test method sleeps for a random amount of milliseconds, and the execution time is clearly visible in the log.
In order for the PerformanceLogger
class to intercept calls, it has to implement GroovyInterceptable
and override the invokeMethod
method. GroovyInterceptable
is an interface that signals to the runtime that all the methods of a class extending the interface should be intercepted by invokeMethod
. The code should be easy to follow; we simply wrap the actual method call with an unsophisticated calculation of time spent executing the method. The dynamic invocation takes places in these two code lines:
def metaClass = InvokerHelper.getMetaClass(this) def result = metaClass.invokeMethod(this, name, args)
The InvokerHelper
class is a static helper resembling a Swiss Army knife for metaprogramming. It exposes numerous methods for working dynamically with a class. In this case, we use it to access the metaClass
class of the intercepted object and subsequently call the original method on the wrapped class.
Note how the logging aspect is applied by using the @Slf4j
annotation, which essentially removes a lot of boilerplate code (see the Adding automatic logging to Groovy classes recipe in Chapter 3, Using Groovy Language Features). The annotation requires some dependencies that can be added via @Grab
, or better by a build script (such as Gradle or Maven).
Using GroovyInterceptable
is a very simple way to decorate any method with code that is executed before and after the actual method execution, but it has some limitations. If a class already extends another class, we can't have the same class extending our GroovyInterceptable
class. Furthermore, the solution only works on Groovy objects and not on arbitrary Java objects.
A more sophisticated and flexible way to apply an interceptor to any class (Groovy or Java) is by using the groovy.lang.ProxyMetaClass
class. The class name may sound a bit threatening, but it's not very complicated to use.
Let's start from our original SlowClass
and remove the extends PerformanceLogger
bit so that the class is now free from any link to the original interceptor.
Add a new interceptor class:
package org.groovy.cookbook.intercept import groovy.util.logging.Slf4j @Slf4j class PerformanceInterceptor implements Interceptor { private Long start = 0 Object beforeInvoke(Object object, String methodName, Object[] arguments) { start = System.currentTimeMillis() null } boolean doInvoke() { true } Object afterInvoke(Object object, String methodName, Object[] arguments, Object result) { long spentTime = System.currentTimeMillis() - start log.debug("Execution time for method ${methodName}: " + "${spentTime}ms. ") result } }
The new interceptor's code is quite similar to the old one. The difference is that the class now implements the groovy.lang.Interceptor
interface, which adds three methods that have to be supplied. The interception is now split in two separate methods: beforeInvoke
and afterInvoke
. The logic behind the performance logging stays the same.
Finally, we write a unit test that uses the proxy to invoke the class:
@Test void methodIsInterceptedByUsingProxy() { useInterceptor(InterceptedClass, PerformanceInterceptor) { def ic = new InterceptedClass() ic.test('a') ic.test('b') ic.test('c') } } def useInterceptor = { Class theClass, Class theInterceptor, Closure theCode -> def proxy = ProxyMetaClass.getInstance(theClass) def interceptor = theInterceptor.newInstance() proxy.interceptor = interceptor proxy.use(theCode) }
The test method uses a useInterceptor
closure that puts together all the pieces. The closure creates a proxy out of the original intercepted class and assigns the interceptor to the proxy.
Running the test yields the following output:
... 13:45:18.857 [Test worker] DEBUG o.g.c.i.PerformanceInterceptor - Execution time for method test: 5521 ms. 13:45:23.265 [Test worker] DEBUG o.g.c.i.PerformanceInterceptor - Execution time for method test: 4408 ms. 13:45:24.717 [Test worker] DEBUG o.g.c.i.PerformanceInterceptor - Execution time for method test: 1451 ms. ...
As mentioned before, the proxy-based interceptor can also be applied to the Java classes.