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

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");
        }
    }       
}

Answer 2

calculate method execution on a server side?

Using Interceptors you are measuring CXF as well!
I mean Interceptors are used to pre/post process a message in relation to your application logic.
Using the Interceptor your measurements include parts of the CXF chain of flow.
If this is what you want then ok.
But if you want to measure your method execution you should put the timing interval in relation to your method.

Answer 3

I think interceptors can put arbitrary data in the Message object, so you can store the start time there and later get it back out to compute the time elapsed.

// in your receive interceptor
@Override
public void handleMessage(Message message) {
    long startTime = System.currentTimeMillis();
    message.put("my.timing.start", startTime);
}

.

// in your send interceptor
@Override
public void handleMessage(Message message) {
    Long startTime = message.remove("my.timing.start");
    if (startTime != null) {
        long executionTime = System.currentTimeMillis() - startTime;
        System.out.println("execution time was ~" + executionTime + " ms");
    }
}

CXF stores some of its own data in the message map, but most of its keys start with org.apache.cxf or javax.xml.ws, so you can just make your map key unique by using the fully-qualified class name of one of your interceptors.

Answer 4

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>