Spiria logo.

How to clock elapsed execution time between method calls in Java with a home-made annotation

January 25, 2017.
This question comes back regularly, but now we may have the beginning of an answer!

Using annotations is indeed possible, thanks to java.lang.reflect.Proxy. All you need to do is to overload the Invoke method and encapsulate the original method inside it.

So you’ll need:

  • An annotation interface (called Clocking in our example),
  • An interface for the object to clock (called Examples in our example),
  • An InvocationHandler to implement the methods for the clocked object (called ExamplesInvocationHandler in our example),
  • An entry point for the code (guess its name!:-)

So let’s start with the easy part, the annotation:

package main;
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface Clocking {
    
}

Nothing too complicated, it targets the methods through the @Target annotation and is handled at the runtime through the @Retention annotation.

Once again, the interface for our object, Examples, is very simple:

package main;

public interface Examples {
    @Clocking
    void thisIsAMethod();
    
    void thisIsAnotherMethod(String something);
    
    @Clocking
    void thisIsALongRunningMethod();
}

And here is the call manager for our object, ExamplesInvocationHandler:

package main;

import java.lang.reflect.InvocationHandler;
import java.lang.reflect.Method;
import java.time.Duration;
import java.time.Instant;

public class ExamplesInvocationHandler implements InvocationHandler {
    // ******************************
    // Fields
    // ******************************
    private Examples examples = new ExamplesImpl();
    
    // ******************************
    // Public methods
    // ******************************
    @Override
    public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
        // If the annotation is not present, just redirect the method call to its origin...
        if(!method.isAnnotationPresent(Clocking.class)) {
            return method.invoke(examples, args);
        }
        
        // ... otherwise log the execution time of it.
        Instant start = Instant.now();
        Object returnObj = method.invoke(examples, args);
        Instant end = Instant.now();
        
        // TODO: This is for demonstration purpose only and should use the application's logging system.
        System.out.println("Method " + method.getName() + " executed in " + Duration.between(end, start) + ".");
        
        return returnObj;
    }
    
    // ******************************
    // Inner classes
    // ******************************
    private static class ExamplesImpl implements Examples {
        @Override
        public void thisIsAMethod() {
            System.out.println("thisIsAMethod called!");
        }

        @Override
        public void thisIsAnotherMethod(String something) {
            System.out.println("thisIsAnotherMethod called!");
        }
        
        @Override
        public void thisIsALongRunningMethod() {
            try {
                Thread.sleep(5000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            
            System.out.println("thisIsALongRunningMethod called!");
        }
    }
}

The call manager must implement InvocationHandler in order to overload the Invoke method. To do so, we will check the presence of our Clocking annotation via reflection. If the annotation is not present, just return the call to the initial method; otherwise, do the same thing but make sure you encapsulate the call with our clocking tools. In this case, we’ve used Java 8’s Instant object, but system.nano or currenttime can also do the trick in previous versions.

Obviously, you have to implement the interface methods, via the internal class ExamplesImpl.

And now we can test the whole thing with our last object, Main:

package main;
import java.lang.reflect.Proxy;

public class Main {
    public static void main(String[] args) {
        Examples examples = (Examples) Proxy.newProxyInstance(Examples.class.getClassLoader(), new Class[]{Examples.class}, new ExamplesInvocationHandler());
        
        examples.thisIsAMethod();
        examples.thisIsAnotherMethod("");
        examples.thisIsALongRunningMethod();
    }
}

The trick is to instantiate Examples with the Proxy object (cf. java.lang.reflect.Proxy) and then to call its methods. If they are annotated, we’ll get console outputs. In this case, we should get the following result:

thisIsAMethod called!
Method thisIsAMethod executed in PT0S.
thisIsAnotherMethod called!
thisIsALongRunningMethod called!
Method thisIsALongRunningMethod executed in PT-5.001S.

Now, the challenge is to make this easy to use with existing objects, and to develop the idea into a generic solution (maybe using a Factory?)... But that’s another article!

Nixie Tube Clock. Photo Hiroyuki Takeda, 2010. Licence CC BY-ND 2.0.