0

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
LaurentG
  • 11,128
  • 9
  • 51
  • 66
user3373353
  • 1
  • 1
  • Where did `userSignService` even come from? – Makoto Mar 03 '14 at 03:33
  • public interface IUserSignService ; implement like :@Service public class UserSignServiceImpl extends BaseServiceImpl implements IUserSignService – user3373353 Mar 03 '14 at 03:59
  • Fair enough, but I don't see where it's declared or instantiated. Without that, there's no reasonable way we can answer this question. – Makoto Mar 03 '14 at 04:00
  • @Autowired IUserSignService userSignService; – user3373353 Mar 03 '14 at 04:02
  • Please get a stacktrace from the `testcall()` method and post it here, probably spring does something inbetween that causes the slow. – ced-b Mar 03 '14 at 04:07
  • I append stacktrace at the end of the question .It seems the framework do lot of things,but I can't change that. – user3373353 Mar 03 '14 at 04:20
  • It works fine on some servers.So I think there might be something wrong about the environment,like java or resin config – user3373353 Mar 03 '14 at 04:27
  • Where is `f2:` in sysout? – Keerthivasan Mar 03 '14 at 07:17
  • are you sure you have same application version deployed to all servers? – Francisco Spaeth Mar 03 '14 at 07:19
  • 1
    Maybe the disk of the slow server is slower than on the other ones. Remove all the logging calls (except the last one, which would display the total time), and see if it makes a difference. – JB Nizet Mar 03 '14 at 07:24
  • How much time is `much`? 312 - 410 (considering impressions) means less than 100 milliseconds for a call that does IO (log may be written to the disk as well as the console) and God knows what else (those intermediate spring Proxies, AOP and reflection). Is it really affecting your application? Also, have the VM been properly warmed up? (If you just deployed on those servers it may take longer to execute on the first runs). – Anthony Accioly Mar 03 '14 at 07:30
  • Normally, it takes less than 2ms.This is a interface to provide data for mobile client.Usually there are many method will be called during one request, and now the response time is more than 2 seconds.It only takes 70-90ms on other servers. – user3373353 Mar 03 '14 at 08:44
  • IO is not likely the reason, I add the log after feel the response is slower – user3373353 Mar 03 '14 at 09:39

1 Answers1

0

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?

user3373353
  • 1
  • 1