Online tracking class method execution time consuming

Keywords: Programming github Java Apache Linux

The online environment is mostly Linux, sometimes the code execution is slow, but you can't locate where it's slow, or it's more difficult to locate. This article introduces a way to facilitate your problem location.    

First of all, let's talk about a tool: Arthas, which is mainly an open-source tool of Alibaba. For details, please click Arthas: an open source java diagnostic tool of Alibaba Check it out. The official website is: https://alibaba.github.io/arthas/trace.html

 

Mainly trace through the trace command provided by this tool.

For specific download, installation and usage, please refer to the above link.

After downloading and installing, directly enter the following command:

Connecting to arthas server... current timestamp is 1541128186
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
  ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.                           
 /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'                          
|  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.                          
|  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |                         
`--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'                          
                                                                                

wiki: https://alibaba.github.io/arthas
version: 3.0.4
pid: 51807
timestamp: 1541128186384

$ 
$ trace
The argument 'class-pattern' is required
$ trace -h
 USAGE:                                                                                                                                                                                       
   trace [-h] [-j] [-n <value>] [-p <value>] [-E] class-pattern method-pattern [condition-express]                                                                                            
                                                                                                                                                                                              
 SUMMARY:                                                                                                                                                                                     
   Trace the execution time of specified method invocation.                                                                                                                                   
   The express may be one of the following expression (evaluated dynamically):                                                                                                                
           target : the object                                                                                                                                                                
            clazz : the object's class                                                                                                                                                        
           method : the constructor or method                                                                                                                                                 
     params[0..n] : the parameters of method                                                                                                                                                  
        returnObj : the returned object of method                                                                                                                                             
         throwExp : the throw exception of method                                                                                                                                             
         isReturn : the method ended by return                                                                                                                                                
          isThrow : the method ended by throwing exception                                                                                                                                    
            #cost : the execution time in ms of method invocation                                                                                                                             
 EXAMPLES:                                                                                                                                                                                    
   trace -E org\\.apache\\.commons\\.lang\\.StringUtils isBlank                                                                                                                               
   trace org.apache.commons.lang.StringUtils isBlank                                                                                                                                          
   trace *StringUtils isBlank                                                                                                                                                                 
   trace *StringUtils isBlank params[0].length==1                                                                                                                                             
   trace *StringUtils isBlank '#cost>100'                                                                                                                                                     
                                                                                                                                                                                              
 WIKI:                                                                                                                                                                                        
   https://alibaba.github.io/arthas/trace                                                                                                                                                     
                                                                                                                                                                                              
 OPTIONS:                                                                                                                                                                                     
 -h, --help                                                     this help                                                                                                                     
 -j, --jdkMethodSkip                                            skip jdk method trace                                                                                                         
 -n, --limits <value>                                           Threshold of execution times                                                                                                  
 -p, --path <value>                                             path tracing pattern                                                                                                          
 -E, --regex                                                    Enable regular expression to match (wildcard matching by default)                                                             
 <class-pattern>                                                Class name pattern, use either '.' or '/' as separator                                                                        
 <method-pattern>                                               Method name pattern                                                                                                           
 <condition-express>                                            Conditional expression in ognl style, for example:                                                                            
                                                                  TRUE  : 1==1                                                                                                                
                                                                  TRUE  : true                                                                                                                
                                                                  FALSE : false                                                                                                               
                                                                  TRUE  : 'params.length>=0'                                                                                                  
                                                                  FALSE : 1==2                                                                                                                
                                                                                                                                                                                              

$ 

The above is the help information of the command, how to use it. I'll make a simple Demo here to demonstrate it.

For example, if I want to track the time consumption of each call in one of my classes and classes, I need to type in the command (some package names are hidden for demonstration):

$ trace com.TestAction testMethodName params.length=1

Press Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 303 ms.
$ trace com.TestAction testMethodName
Press Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 391 ms.
`---ts=2018-11-02 11:14:19;thread_name=http-nio-8383-exec-138;id=b5;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.WebappClassLoader@4c12c6ec
    `---[10.091747ms] com.TestAction$$EnhancerBySpringCGLIB$$4d4515a6:scanQr()
        `---[9.739745ms] org.springframework.cglib.proxy.MethodInterceptor:intercept()
            `---[6.161854ms] com.TestAction:testMethodName()
                +---[0.082935ms] com.ActionResultMap:<init>()
                +---[0.026972ms] javax.servlet.http.HttpServletRequest:getHeader()
                +---[min=0.001465ms,max=0.003437ms,total=0.011679ms,count=6] java.lang.StringBuilder:<init>()
                +---[min=0.001385ms,max=0.003889ms,total=0.02629ms,count=14] java.lang.StringBuilder:append()


.....
.....
.....

The above is the output result information. Main last line printed information:

min=0.001385ms,max=0.003889ms,total=0.02629ms,count=14

Briefly:

In StringBuilder.append(), call:

The minimum time of ﹣ is 0.001385ms;

The maximum time consumption is 0.003889ms;

After calling 14, the total time is 0.02629ms

 

What a powerful tool ~ ~ ~ thanks to Alibaba technical staff for open source.

Posted by parkej60 on Wed, 11 Dec 2019 10:04:30 -0800