Call a method in Spring mvc service cost too much time

Question

My English is not so good. Code first.

    @ResponseBody
    @RequestMapping(value = "testcall")
    public UnifiedResponse testMethodCall(
            HttpServletRequest request,
            HttpServletResponse response) {
        UnifiedResponse unifiedResponse = new UnifiedResponse();
        logger.info("t1:"+System.currentTimeMillis());
        Fun(0,1452,"abd",1);
        logger.info("t2:"+System.currentTimeMillis());
        userSignService.testcall();
        logger.info("t3:"+System.currentTimeMillis());

        return unifiedResponse;
    }


    String  Fun(int i,long l,String s,int ii){
        logger.info("f1:"+System.currentTimeMillis());
        return "";
    }

and log output :

 t1:1393816077311
 f1:1393816077312
 t2:1393816077312
 f2:1393816077345
 t3:1393816077410

testcall() is a method in a service, with neither parameter nor return value. just output the timestamp.

Service is implemented like this:

@Service
public class UserSignServiceImpl extends BaseServiceImpl implements IUserSignService {
 public void testcall() {
    logger.info("f1:"+System.currentTimeMillis());
 }

}

instantiated by annotation

@Autowired
IUserSignService userSignService;

This only happen on some of the servers. On others t3-t1 is less than 2ms.All servers use same version of JDK and Resin.

Why?

stack trace between caller and method:

UserSignServiceImpl.testcall() line: 448    
NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]  
NativeMethodAccessorImpl.invoke(Object, Object[]) line: 39  
DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 25  
Method.invoke(Object, Object...) line: 597  
AopUtils.invokeJoinpointUsingReflection(Object, Method, Object[]) line: 319 
ReflectiveMethodInvocation.invokeJoinpoint() line: 183  
ReflectiveMethodInvocation.proceed() line: 150  
TransactionInterceptor.invoke(MethodInvocation) line: 110   
ReflectiveMethodInvocation.proceed() line: 172  
ExposeInvocationInterceptor.invoke(MethodInvocation) line: 90   
ReflectiveMethodInvocation.proceed() line: 172  
JdkDynamicAopProxy.invoke(Object, Method, Object[]) line: 202   
$Proxy49.testcall() line: not available 
OtherController.testMethodCall(HttpServletRequest, HttpServletResponse) line: 6329  

Answer 1

The reason is interceptor. Once I remove it, t3-t2 down to 1ms. org.springframework.orm.hibernate3.HibernateTransactionManager All method in package com.xxx.service will trigger this manager.I don't know the internal mechanisms, but I guess may be like this: The server process faster has 12M L3 Cache in CPU, the slower one has not.The service methods is called everywhere ,makes it the most frequently used.The faster server might cache it, so process faster. I'm not sure.Is there some explanation else?