RichClientGUI

I recently got a request from my one client: “Please add logging of the time it takes to do remote service calls, with minimal impact on the existing code.”

Now I immediately thought of the Proxy design pattern.

The existing code had quite a large number of business interfaces defined, with an implementation for each one that made use of RMI to call the remote objects. I’ll spare you the unnecessary details (JAAS, etc). It boiled down to basically every public method in each business interface implementation making use of an anonymous inner class with a simple public Object run() method to make the actual call to the remote object. A lot of code to change by hand, if logging and measurement of the time it took for remote calls were to be added.

A drastically reduced business interface might look like:

package com.richclientgui.blog.delegate;

public interface SoccerScoreService {
    public int getTeamScore(String teamName);
}

In order to re-enact the work of the JAAS Subject.doAs(…) code that is involved with the actual code, I created a MockSubject class for this example, which just calls the run() method of whatever Runnable gets passed to it:

import java.util.concurrent.Callable;

public class MockSubject {
    public static <T> T doAs(Callable<T> action) throws Exception {
        return action.call();
    }
}

We add a very basic mock implementation (no real remote calls happening here…):

import java.util.concurrent.Callable;

public class MockSoccerScoreServiceImpl implements SoccerScoreService {

    @Override
    public int getTeamScore(String teamName) {
        try {
                
            Integer result = MockSubject.doAs(
                                    new Callable<Integer>() {
                public Integer call() throws Exception {
                    System.out.print("Doing some work...");
                    try {
                         Thread.sleep(1000);
                    } catch (InterruptedException e) {
                         e.printStackTrace();
                    }
                    System.out.println("completed.");
                    return new Integer(50);
                }
             });
             return result.intValue();
                        
        } catch (Exception e) {
             //for this blog, I don't care about the 
             //exception handling...
             e.printStackTrace();
             return -1;
        }
    }
}

Now we can just create a simple class with a main method that calls getTeamScore(…) on an instance of MockSoccerScoreServiceImpl.

Now to add the logging…

Approach A: Use a Proxy
We can create a Proxy for the Callable, since all our calls to the server are done using Callable instances. This proxy class measures the time it takes to perform the call() method of the real Callable, and logs it to sysout.

import java.util.concurrent.Callable;

public class LoggingCallableProxy <T> implements Callable<T> {
        private final Callable<T> realCallable;
        
        public LoggingCallableProxy(Callable<T> realCallable){
                this.realCallable = realCallable;
        }
        
        @Override
        public T call() throws Exception {
                long time = System.currentTimeMillis();
                T result = realCallable.call();
                time = System.currentTimeMillis()-time;
                //find calling method, using call level of 3 
                //for this example
                final StackTraceElement stackTrace 
                        = Thread.currentThread().getStackTrace()[3];
                //using sysout for example, but of course 
                //use proper logging in real life
                System.out.println(
                                stackTrace.getClassName()+"."
                                +stackTrace.getMethodName()
                                +" took "+time+"ms to execute.");
                return result;
        }
}

Now comes the disadvantage of using a Proxy: we now have to change all the existing code to now create the instance of LoggingCallableProxy where the Callable was used up to now. This is not so bad if you have the source code, it is just a simple find&replace, so we can be pragmatic and live with it (I’ve always wanted to use the word “pragmatic” in a blog). Our MockSoccerScoreServiceImpl class changes to look like:

import java.util.concurrent.Callable;
import com.richclientgui.blog.proxy.LoggingCallableProxy;

public class MockSoccerScoreServiceImpl implements SoccerScoreService {

        @Override
        public int getTeamScore(String teamName) {
                try {
                
                    Integer result = MockSubject.doAs(
                           new LoggingCallableProxy<Integer>(
                               new Callable<Integer>() {
                         public Integer call() throws Exception {
                             System.out.print("Doing some work...");
                             try {
                                     Thread.sleep(1000);
                             } catch (InterruptedException e) {
                                     e.printStackTrace();
                             }
                             System.out.println("completed.");
                                     return new Integer(50);
                         }
                     }));
                     return result.intValue();
                        
                } catch (Exception e) {
                     //for this blog, I don't care about the 
                     //exception handling...
                     e.printStackTrace();
                     return -1;
                }
        }
}

Now we have logging of the time measurements, with minimal code impact.

However, that simple yet far-reaching find&replace operation one potentially hundreds of methods in a huge number of classes still worries me…

Approach B: use Aspects

Aspect-oriented programming (AOP) has been around for a while, and it allows us to weave in functionality without changing existing java classes. That is an extremely brief and potentially inaccurate summary, but it will suffice for this blog. Go read more about aspects and AspectJ.

First, we need to enable aspects on our project. Do this, you must:

1. Download the AspectJ Development Tools (AJDT) if you are using the Eclipse IDE (AspectJ also integrates with other IDEs).
2. Convert the project to an AspectJ project: Right-click on project, choose Configure -> Convert to AspectJ project
3. Now you are ready to start implementing aspects.

Second: change back the MockSoccerScoreServiceImpl class to now make use of the LoggingCallableProxy anymore.

Then we can implement our aspect:

import com.richclientgui.blog.delegate.MockSubject;

/**
 * This aspect will find all occurrences of the MockSubject.doAs(...)
 * method being called, and wrap that in code to log the time
 * measurements.
 */
public aspect TimeLoggerAspect  {

        // the pointcut defines what method calls to intercept
        // All calls to the MockSubject.doAs(...) method
        // (wildcards for return and param types)
        pointcut doingRemoteCalls() :
                call(* MockSubject.doAs(..));

        /* around() defines an advise that will be executed whenever
         * the doingRemoteCalls() pointcut is matched.
         * It measures the time that it takes to execute the actual
         * doAs(...)method at that point, and prints out the time,  
         * class and method calling the MockSubject.doAs(..) method
         */
        Object around() : doingRemoteCalls() {
                long time = System.currentTimeMillis();
                Object result = proceed();
                time = System.currentTimeMillis()-time;
                //find calling method
                final StackTraceElement stackTrace 
                        = Thread.currentThread().getStackTrace()[2]; 
                System.out.println(
                                stackTrace.getClassName()+"."
                                +stackTrace.getMethodName()+" took "
                                +time+"ms to execute.");
                return result;
        }
}

Now you can run your main/test class as an AspectJ application, by using the Run As -> AspectJ/Java Application menu option in Eclipse.
(Visit the AspectJ website to see how to run it from commandline or other IDEs.)

We added logging to the remote calls, without changing any existing code, by just adding one simple aspect. This is only the tip of the iceberg of what you can do with AOP.

Eclipse RCP tip:
For Eclipse RCP applications, you will need to add a dependency to the org.aspectj.runtime plug-in to your plug-in project in order to use AspectJ.