Using CXF Interceptors to measure WebService or REST Service time

Let's say I have this simple service:

@WebService
public interface Hello {
     
      String sayHello();

      String sayGoodbye();

}

I want to know how often and how long sayHello() is executed compared to sayGoodbye(). I could add:

@WebService
public interface Hello { 
      
      @Profiled(tag = "sayHello")
      String sayHello();

      @Profiled(tag = "sayGoodbye")
      String sayGoodbye();

}

In this fashion, I would use Perf4Js @Profiled annotation and it would log messages telling me each time a sayHello() or sayGoodbye() method was called. However, that's not enough. I've just cut out the time of one of the most important parts of WebServices, XML processing.

Enter the CXF Interceptor, assuming of course that I was using CXF, I can write a custom interceptor by extending AbstractPhaseInterceptor<Message>, a fairly generic extension that would apply to JAXWS and JAXRS services. The new in interceptor would start a new Perf4j StopWatch (log4j or slf4j implementation if you please) and the new out interceptor would stop the StopWatch which would force the log record.  With the interceptor, I can also control the phase at which the interceptor is invoked.

Now my service would look like this:

@org.apache.cxf.interceptor.InInterceptors (interceptors = "net.halverson.interceptor.TimerInInterceptor" ) 
@org.apache.cxf.interceptor.OutInterceptors (interceptors = "net.halverson.interceptor.TimerOutInterceptor" ) 
@WebService 
public interface Hello { 
     
      String sayHello(); 

      String sayGoodbye(); 
}

But how do I know whether sayHello() or sayGoodbye() was called.  I suspect I could access the Message object in the interceptor and find out, but maybe I want more control than that.  That Message object is hanging around while my service is called and I can even place some of my own objects in it, however,  my service implementation does not have access to the Message object and I doubt I would ever want it to.

How then can I update the StopWatch with a 'tag' or 'message' for Perf4j to log?  A ThreadLocal will do.  Remember how we started the StopWatch in the in interceptor and stopped it in the out interceptor, we can use a ThreadLocal to place the StopWatch into that thread variable state and access the object across the thread without having to pass the object along the method calls in the stack.

Something like this:

public class ServiceTimer {

      private static final ThreadLocal<Slf4JStopWatch> stopWatch = new ThreadLocal<Slf4JStopWatch>() { 
              @Override
              public Slf4JStopWatch initialValue() {
                    return new Slf4JStopWatch();
              }

};

      // execute in the in interceptor, ServiceTimer.getStopWatch().start();
      // execute in the out interceptor, ServiceTimer.getStopWatch().stop();
      public static SLF4JStopWatch getStopWatch() {
            return stopWatch.get();
      }
      
      // for clean up in the out interceptor
      public static void removeWatch() {
            stopWatch.remove();
      }
}

Then in the service implementation of Hello interface:

@Service

public class HelloImpl implements Hello {

      public String sayHello() {
            ServiceTimer.getStopWatch().setTag("sayHello");

            return "Hello!";
      }

      public String sayGoodbye() {
            ServiceTimer.getStopWatch().setTag("sayGoodbye").setMessage("blah!");

            return "Goodbye!";
      }

}


In the end you'll get a two log records like this after the service is executed:

2013-07-27 10:45:45,328 INFO (http-8181-1) (TimingLogger) start[1374939945321] time[7] tag[sayGoodbye] message[blah!]
2013-07-27 10:46:03,565 INFO (http-8181-1) (TimingLogger) start[1374939963562] time[2] tag[sayHello]


See full code example here:
Github