Web service request exection time calculation

Question

I have a working SOAP web service implemented with CXF in Java. What would be a good way to calculate method execution on a server side?

What I've done for now is I used interceptors. I've defined public static long start in my InInterceptor(Phase.RECEIVE). And in my OutInterceptor(Phase.SEND) I calculate response time like this :

    @Override
    public void handleMessage(Message arg0) {
        long stop = System.currentTimeMillis();
        long executionTime = stop - RequestStartInterceptor.start;
        System.out.println("execution time was ~" + executionTime + " ms");
    }

Is there a better way to do this? I was reading about execution of method trough proxy, but I have no clue how to do that.

Question update :

I've googled a bit more a find my way arround the second way using the proxy i.e :

@Aspect
public class MyServiceProfiler {



     @Pointcut("execution(* gov.noaa.nhc.*.*(..))")
         public void myServiceMethods() { }

         @Around("myServiceMethods()")
         public Object profile(ProceedingJoinPoint pjp) throws Throwable {
                 long start = System.currentTimeMillis();
                 System.out.println("Going to call the method.");
                 Object output = pjp.proceed();
                 System.out.println("Method execution completed.");
                 long elapsedTime = System.currentTimeMillis() - start;
                 System.out.println("Method execution time: " + elapsedTime + " milliseconds.");
                 return output;
         }
    }

Based on comments to this question so far, using interceptors is better than using proxy. I'm looking to slow down the webservice as least as possible (this will certainly slow it down) and at the same time get a precise performance measurement.

Answer 1

I wouldn't recommend your first approach of using InInterceptor and OutInterceptor - the reason is there is no clean way to store the starttime - the approach that you have token to store it in a static variable will not work in a threaded environment.

Your second approach of using AOP is very good, however it will not give the time spent in the CXF stack, it will only provide the time once the call comes to your service tier.

I feel the best approach will be using a servlet filter, you can do this:

public void doFilter(ServletRequest request,  ServletResponse response, FilterChain chain) throws IOException, ServletException {
    long start = System.currentTimeMillis();   
    chain.doFilter(request, response);
    long elapsedTime = System.currentTimeMillis() - start;
    System.out.println("Method execution time: " + elapsedTime + " milliseconds.");
}

and provide the mapping at the same uri where you have provided the mapping for CXFServlet.

This should be much more cleaner. If you want something even more granular, you can mix this approach with your AOP approach to find the overall response time and then break it down into the individual service method times.

<servlet>
    <servlet-name>CXFServlet</servlet-name>
    <servlet-class>org.apache.cxf.transport.servlet.CXFServlet</servlet-class>
</servlet>

<servlet-mapping>
    <servlet-name>CXFServlet</servlet-name>
    <url-pattern>/webservices/*</url-pattern>
</servlet-mapping> 
<filter-mapping>
    <filter-name>ExecTimeFilter</filter-name>
    <url-pattern>/webservices/*</url-pattern>
    <dispatcher>REQUEST</dispatcher>
</filter-mapping>

Answer 2

Based on matts' answer I worked out following. The key is that in OutgoingInterceptor you need get incoming message and obtain starting timestamp from that.

public class IncomingInterceptor extends AbstractPhaseInterceptor<Message> {

    public IncomingInterceptor() {
        super(Phase.RECEIVE);
    }

    @Override
    public void handleMessage(Message msg) throws Fault {
        long startTime = System.currentTimeMillis();
        msg.put("my.timing.start", startTime);
    }
}


public class OutgoingInterceptor extends AbstractPhaseInterceptor<Message> {
    Logger log = LoggerFactory.getLogger(AbstractPhaseInterceptor.class);
    public OutgoingInterceptor() {
        super(Phase.SEND);
    }

    @Override
    public void handleMessage(Message msg) throws Fault {
        Long startTime = (Long)msg.getExchange().getInMessage().remove("my.timing.start");
        if (startTime != null) {
            long executionTime = System.currentTimeMillis() - startTime;
            log.info("execution time was ~" + executionTime + " ms");
        } else {
            log.info("timer not found");
        }
    }       
}