Call Log Duration Problem In EJB3 Through Interceptor

[Sudeesh Naidu]

Hi,

In my project we have a requirement to log/record total execution time of each and every method. And I am trying with Interceptors

I tried with @AroundInvoke like below, but it completes just before start of any business method and it gives me Total Execution Time Of getMessage Is 0 ms.

Ideally It should say "Total Execution Time Of getMessage Is 2000 MS." Please help me if you have any solution/suggestion on this. Thank You!

Also included the code for you reference.

//Interceptor Class

public class CommonInterceptot {
	@AroundInvoke
	public Object callLog(InvocationContext ctx) throws Exception {
		String methodName = ctx.getMethod().getName();
		long startTime = System.currentTimeMillis();
		long totalTime = System.currentTimeMillis() - startTime;
		System.out.println("::::::::::::::Total Execution Time Of" + methodName
				+ " Is " + totalTime + "MS");
		return ctx.proceed();
	}
}

//EJB Bean
@Stateless
@Interceptors(value = CommonInterceptot.class)
public class SampleEJB implements SampleEJBRemote, SampleEJBLocal {

	public String getMessage() {
//		long startTime = System.currentTimeMillis();
		try {
			Thread.sleep(2000L);
		} catch (InterruptedException e) {
			e.printStackTrace();
		}
		return "Hello, Welcome to SampleEJB...............";
	}
}

[Jaikiran Pai]

public class CommonInterceptot {  
    @AroundInvoke  
    public Object callLog(InvocationContext ctx) throws Exception {  
        String methodName = ctx.getMethod().getName();  
        long startTime = System.currentTimeMillis();  
        long totalTime = System.currentTimeMillis() - startTime;  
        System.out.println("::::::::::::::Total Execution Time Of" + methodName  
                + " Is " + totalTime + "MS");  
        return ctx.proceed();  
    }  
}  

The implementation of that interceptor is incorrect. Remember that the code execution is passed onto the next interceptor (in the chain) or the final target method when you invoke ctx.proceed from the current interceptor. So until the ctx.proceed() is called, the control is still in the current interceptor. So based on this fact, where do you think the total time should be calculated in that method?

[Sudeesh Naidu]

Hello Jaikiran,

I got the problem. Thanks for sharing the concept & Thanks for your reply.