Java: Is it possible to automatically add log statements to methods ?

Question

Most of the methods in my application are written like this:

public void m() {
    long t1 = System.currentTimeMillis();
    log.info("begin - m()");

    /* method body */

    long t2 = System.currentTimeMillis();
    log.info("end - m(), took " + (t2 - t1) + "ms.");
}

I wish I could simply annotate my method and have the log statements be automagically generated instead:

@Log("executionTime")
public void m() {
    /* method body */
}

Any ideas on how to proceed with this approach ? Is there any known solution ?

Someone suggested AOP for this. The problem is that with AspectJ or Spring AOP I would have to describe all the methods which ammounts to as much code as the log calls in the method itself.

Answer 1

CGLIB let you modify method code at runtime

Answer 2

As has been suggested to you, AOP fits well to serve this requirement. Not sure what you meant by "having to describe all methods". From what I know there are ways to use wildcards to specify methods to which aspects apply, which could ease your work of "describing"..this is true at least in the case of Spring AOP..not sure about others.

And yes, CGLIB suggested by Maurice is another good candidate for your consideration. Never used it though.

Answer 3

Perf4j supports getting timing information for methods using annotations. See here in their developer guide.

Answer 4

Comment out the logging or profiling calls with a unique search term:

void myfunc() {

  //log-call-123: try { long log_t1 = System.currentTimeMillis();        
  //log-call-123: log.info("begin - myfunc()"); {

  ...
  normal method code
  ...

  //log-call-123: } } finally { long log_t2 = System.currentTimeMillis();         
  //log-call-123: log.info("end - myfunc(), took " + (log_t2 - log_t1) + "ms."); }

}

When you search and replace:

Search for: "//log-call-123:"

Replace with: "/* log-call-123 */"

Do the reverse search and replace when you want to turn off extra logging or profiling calls.

Answer 5

AspectJ and Spring AOP support something like:

execution(* com.company.project..*.*(..))

which will cover all methods in all sub-packages of project. So no need to define all methods one by one.

Answer 6

AspectJ has the concept of a join point, which is like a wildcard that can specify any methods that match that wildcard (you can specify particular methods in a class or any class that matches the wildcard). Then you can create an aspect which contains before advice and after advice, which are methods that run before and after the method matched by the join point. You can generate your log methods this way.

Answer 7

You should use an aspect to this requirement. This requirement is a crosscuting concern (a concern that "cuts" between many classes).

To capture the methods that you want match you should create a pointcut that matches one or more join points. A join point is something that can be executed on your code (a method for example).

Look at this simple examples about tracing and logging and at this link about wildcards and pointcuts.

Answer 8

While this is not an actual practical answer to your question just yet (some good answers have been with respect to AOP), I believe the concept of ARM in Java 7 should be a viable option for implementing something like this on a small scale.

You could define a utility logging class and a factory to produce that class, something like the following:

public class TimerFactory
{
    private static final Logger log = ...; // Obtain however

    static class Timer implements Disposable<RuntimeException>
    {
        private final long startTime;
        private final String name;

        private Timer(String name)
        {
           this.name = name;
           startTime= System.currentTimeMillis();
           log.info("begin - " + name);
        }

        public void close()
        {
           final long t2 = System.currentTimeMillis();
           log.info("end - " + name + ", took " + (t2 - t1) + "ms.");
        }
    }

    public static Timer getTimer(String name)
    {
       return new Timer(name);
    }
}

Now with that boilerplate out of the way (essentially an encapsulation of your logging behaviour), it could be called as follows:

public void m() {
   try (TimerFactory.getTimer("m()")) {

      /* method body */

   }
}

The first log method would be called at the entrance to the try block, and the start time recorded. When the try block was exited, the resource (the Timer in this case) would automatically be "closed", which would cause the final time to be calculated and logged. Note as well that because this is a try block, the end logging will happen regardless of whether an exception is thrown or not. Your original code should probably use a try-finally block to ensure that the logging is actually completed.

Obviously this still requires you to put some logging code at each site, so is not really a replacement for clever pointcuts and AOP, even once Java 7 is released. However, if you find yourself dropping the logging in every now and then into perhaps a handful of methods, this pattern is a good way to abstract out the logging concerns and allow you to reuse it with the minimum of boilerplate.