Analyzing Java Applications on the Fly with Arthas

October 31st, 2018 by

Arthas created by Alibaba is a tool that allows developers to connect to running Java applications without stopping them or suspending threads for debugging the application from the console.

It offers features like monitoring invocation statistics, searching for classes and methods in the classloaders, view method invocation details (like parameters), show the stack trace of a method invocation, monitor system metrics and others.

In the following examples I’m going to demonstrate some of these features applied to a running web application.

Arthas Dashboard

Arthas Dashboard

 

Installation

Using Linux/Mac/*nix….

curl -L https://alibaba.github.io/arthas/install.sh | sh

Wind*ws users visit Maven Central and visit the latest binary here, unzip the downloaded zip-file, change to the bin directory and call Arthas like this:

as.bat $PID

Examples of Usage

For the following examples I’ll be connecting Arthas to a running Spring Boot application take from my tutorial “Integrating Swagger into a Spring Boot RESTful Webservice with Springfox”.

Connecting to an Application

Having started Arthas, we’re now asked to connect to a running Java application – in this case, we’re choosing the Spring Boot application mentioned above:

Connection Arthas with Spring Boot app

Connection Arthas with Spring Boot app

Afterwards we notice the following entries in the output from our Spring Bot application:

Tue Oct 30 16:15:54 CET 2018 com.taobao.arthas.agent.ArthasClassloader@307e0d2f JM.Log:INFO Log root path: /home/soma/logs/
Tue Oct 30 16:15:54 CET 2018 com.taobao.arthas.agent.ArthasClassloader@307e0d2f JM.Log:INFO Set arthas log path: /home/soma/logs/arthas

If no running Java process is detected, Arthas will quit and display the following hint:

./as.sh
Arthas script version: 3.0.4
Error: no available java process to attach.
 
Usage:
./as.sh [-b [-f SCRIPT_FILE]] [debug] [--use-version VERSION] [--attach-only] [@IP:TELNET_PORT:HTTP_PORT]
[debug]         : start the agent in debug mode
           : the target Java Process ID
[IP]            : the target's IP
[TELNET_PORT]   : the target's PORT for telnet
[HTTP_PORT]     : the target's PORT for http
[-b]            : batch mode, which will disable interactive process selection.
[-f]            : specify the path to batch script file.
[--attach-only] : only attach the arthas agent to target jvm.
[--use-version] : use the specified arthas version to attach.
 
Example:
./as.sh
./as.sh @[IP]
./as.sh @[IP:PORT]
./as.sh debug
./as.sh -b
./as.sh -b -f /path/to/script
./as.sh --attach-only
./as.sh --use-version 2.0.20161221142407

Feature Overview

When typing in help, Arthas displays available commands.

For more details on each command, simply type help command.

$ help
 NAME         DESCRIPTION
 help         Display Arthas Help
 keymap       Display all the available keymap for the specified connection.
 sc           Search all the classes loaded by JVM
 sm           Search the method of classes loaded by JVM
 classloader  Show classloader info
 jad          Decompile class
 getstatic    Show the static field of a class
 monitor      Monitor method execution statistics, e.g. total/success/failure count, average rt, fail rate, etc.
 stack        Display the stack trace for the specified class and method
 thread       Display thread info, thread stack
 trace        Trace the execution time of specified method invocation.
 watch        Display the input/output parameter, return object, and thrown exception of specified method invocation
 tt           Time Tunnel
 jvm          Display the target JVM information
 dashboard    Overview of target jvm's thread, memory, gc, vm, tomcat info.
 dump         Dump class byte array from JVM
 options      View and change various Arthas options
 cls          Clear the screen
 reset        Reset all the enhanced classes
 version      Display Arthas version
 shutdown     Shut down Arthas server and exit the console
 session      Display current session information
 sysprop      Display, and change the system properties.
 redefine     Redefine classes. @see Instrumentation#redefineClasses(ClassDefinition...)

Search all the classes loaded by JVM

We’re searching for all loaded classes matching the pattern com.hascode.tutorial.*:

$ sc 'com.hascode.*'
com.hascode.tutorial.Application$FastClassBySpringCGLIB$2be61ff4
com.hascode.tutorial.Application
com.hascode.tutorial.CurrentDateController
com.hascode.tutorial.Application$EnhancerBySpringCGLIB$b7e53eca$FastClassBySpringCGLIB$5d6e31fa
com.hascode.tutorial.FormattedDate
com.hascode.tutorial.Application$EnhancerBySpringCGLIB$b7e53eca
Affect(row-cnt:6) cost in 8 ms.

Search the method of classes loaded by JVM

Searching for all methods in the class com.hascode.tutorial.CurrentDateController.

$ sm com.hascode.tutorial.CurrentDateController
com.hascode.tutorial.CurrentDateController->
com.hascode.tutorial.CurrentDateController->formatCurrentDate
Affect(row-cnt:2) cost in 7 ms.

Show classloader info

Displays the classloaders used by our application.

$ classloader
name                                       numberOfInstances  loadedCountTotal
sun.misc.Launcher$AppClassLoader           1                  3640
BootstrapClassLoader                       1                  2537
com.taobao.arthas.agent.ArthasClassloader  1                  1032
sun.reflect.DelegatingClassLoader          58                 58
sun.misc.Launcher$ExtClassLoader           1                  0
Affect(row-cnt:5) cost in 7 ms.

Decompile Class

We’re decompiling the class com.hascode.tutorial.CurrentDateController.

$ jad com.hascode.tutorial.CurrentDateController
 
ClassLoader:
+-sun.misc.Launcher$AppClassLoader@73d16e93
  +-sun.misc.Launcher$ExtClassLoader@3b1cd4e6                                                                                         
 
Location:
/data/project/spring-boot-swagger-tutorial/build/classes/main/                                                                        
 
/*
 * Decompiled with CFR 0_132.
 */
package com.hascode.tutorial;
 
import com.hascode.tutorial.FormattedDate;
import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
import java.time.temporal.TemporalAccessor;
import java.util.concurrent.atomic.AtomicLong;
import org.springframework.web.bind.annotation.PathVariable;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;
 
@RestController
public class CurrentDateController {
    private final AtomicLong counter = new AtomicLong();
 
    @RequestMapping(value={"/currentdate/{pattern}"})
    public FormattedDate formatCurrentDate(@PathVariable String pattern) {
        DateTimeFormatter fmt = DateTimeFormatter.ofPattern(pattern);
        return new FormattedDate(this.counter.incrementAndGet(), pattern, fmt.format(LocalDateTime.now()));
    }
}
 
Affect(row-cnt:1) cost in 503 ms.

Monitor method execution statistics

In the following example we’re monitoring method execution statistics for the CurrentDateController’s formatCurrentDate method.

Available parameters are shown with help monitor

$ help monitor
 USAGE:
   monitor [-c ] [-h] [-n ] [-E] class-pattern method-pattern                                                           
 
 SUMMARY:
   Monitor method execution statistics, e.g. total/success/failure count, average rt, fail rate, etc.                                 
 
 Examples:
   monitor org.apache.commons.lang.StringUtils isBlank
   monitor org.apache.commons.lang.StringUtils isBlank -c 5
   monitor -E org\.apache\.commons\.lang\.StringUtils isBlank                                                                         
 
 WIKI:
   https://alibaba.github.io/arthas/monitor                                                                                           
 
 OPTIONS:
 -c, --cycle                           The monitor interval (in seconds), 60 seconds by default
 -h, --help                                   this help
 -n, --limits                          Threshold of execution times
 -E, --regex                                  Enable regular expression to match (wildcard matching by default)
                               Path and classname of Pattern Matching
                              Method of Pattern Matching

So to monitor the method with a monitor interval of 5 seconds, an execution time treshold of 10, we’re using the following command:

$ monitor -c 5 -n 10 com.hascode.tutorial.CurrentDateController formatCurrentDate
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 33 ms.
 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------
 2018-10-30 15:32:08  com.hascode.tutorial.CurrentDateController  formatCurrentDate  18     18       0     0.23        0.00%          
 
 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------
 2018-10-30 15:32:13  com.hascode.tutorial.CurrentDateController  formatCurrentDate  22     22       0     0.20        0.00%          
 
 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------
 2018-10-30 15:32:18  com.hascode.tutorial.CurrentDateController  formatCurrentDate  22     22       0     0.22        0.00%          
 
 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------
 2018-10-30 15:32:23  com.hascode.tutorial.CurrentDateController  formatCurrentDate  11     11       0     0.20        0.00%          
 
 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------
 2018-10-30 15:32:28  com.hascode.tutorial.CurrentDateController  formatCurrentDate  8      8        0     0.26        0.00%          
 
 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------
 2018-10-30 15:32:33  com.hascode.tutorial.CurrentDateController  formatCurrentDate  8      8        0     0.16        0.00%          
 
 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------
 2018-10-30 15:32:38  com.hascode.tutorial.CurrentDateController  formatCurrentDate  14     14       0     0.19        0.00%          
 
 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------
 2018-10-30 15:32:43  com.hascode.tutorial.CurrentDateController  formatCurrentDate  17     17       0     0.17        0.00%          
 
 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------
 2018-10-30 15:32:48  com.hascode.tutorial.CurrentDateController  formatCurrentDate  9      9        0     0.18        0.00%          
 
 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------
 2018-10-30 15:32:53  com.hascode.tutorial.CurrentDateController  formatCurrentDate  19     19       0     0.20        0.00%          
 
Command execution times exceed limit: 10, so command will exit. You can set it with -n option.

Display the stack trace for the specified class and method

We’re displaying the stack trace for com.hascode.tutorial.CurrentDateController.

$ stack com.hascode.tutorial.CurrentDateController
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:2) cost in 32 ms.
ts=2018-10-30 15:35:01;thread_name=http-nio-8080-exec-7;id=2a;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@565a8af8
    @sun.reflect.GeneratedMethodAccessor31.invoke()
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:221)
        at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:137)
        at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:110)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:776)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:705)
        at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)  [..]

Display thread info, thread stack

Just as the title says..

$ thread
Threads Total: 32, NEW: 0, RUNNABLE: 14, BLOCKED: 0, WAITING: 14, TIMED_WAITING: 4, TERMINATED: 0
ID         NAME                              GROUP                 PRIORITY   STATE      %CPU        TIME       INTERRUPTE DAEMON
58         as-command-execute-daemon         system                10         RUNNABLE   90          0:0        false      true
30         nioEventLoopGroup-2-2             system                10         RUNNABLE   9           0:0        false      false
23         AsyncAppender-Worker-arthas-cache system                9          WAITING    0           0:0        false      true
21         Attach Listener                   system                9          RUNNABLE   0           0:0        false      true
14         ContainerBackgroundProcessor[Stan main                  5          TIMED_WAIT 0           0:0        false      true
20         DestroyJavaVM                     main                  5          RUNNABLE   0           0:2        false      false
3          Finalizer                         system                8          WAITING    0           0:0        false      true
16         NioBlockingSelector.BlockPoller-1 main                  5          RUNNABLE   0           0:0        false      true
2          Reference Handler                 system                10         WAITING    0           0:0        false      true
4          Signal Dispatcher                 system                9          RUNNABLE   0           0:0        false      true
15         container-0                       main                  5          TIMED_WAIT 0           0:0        false      false
19         http-nio-8080-Acceptor-0          main                  5          RUNNABLE   0           0:0        false      true
17         http-nio-8080-ClientPoller-0      main                  5          RUNNABLE   0           0:0        false      true
18         http-nio-8080-ClientPoller-1      main                  5          RUNNABLE   0           0:0        false      true
36         http-nio-8080-exec-1              main                  5          WAITING    0           0:0        false      true
46         http-nio-8080-exec-10             main                  5          WAITING    0           0:0        false      true
37         http-nio-8080-exec-2              main                  5          WAITING    0           0:0        false      true
38         http-nio-8080-exec-3              main                  5          WAITING    0           0:0        false      true
39         http-nio-8080-exec-4              main                  5          WAITING    0           0:0        false      true
40         http-nio-8080-exec-5              main                  5          WAITING    0           0:0        false      true
41         http-nio-8080-exec-6              main                  5          WAITING    0           0:0        false      true
42         http-nio-8080-exec-7              main                  5          WAITING    0           0:0        false      true
43         http-nio-8080-exec-8              main                  5          WAITING    0           0:0        false      true
45         http-nio-8080-exec-9              main                  5          WAITING    0           0:0        false      true
25         job-timeout                       system                9          TIMED_WAIT 0           0:0        false      true
26         nioEventLoopGroup-2-1             system                10         RUNNABLE   0           0:0        false      false
33         nioEventLoopGroup-2-3             system                10         RUNNABLE   0           0:0        false      false
48         nioEventLoopGroup-2-4             system                10         RUNNABLE   0           0:0        false      false
52         nioEventLoopGroup-2-5             system                10         RUNNABLE   0           0:0        false      false
27         nioEventLoopGroup-3-1             system                10         RUNNABLE   0           0:0        false      false
28         pool-1-thread-1                   system                5          TIMED_WAIT 0           0:0        false      false
29         pool-2-thread-1                   system                5          WAITING    0           0:0        false      false
Affect(row-cnt:0) cost in 119 ms.

Trace the execution time of specified method invocations

We’re tracing the exection time of the com.hascode.tutorial.CurrentDateController’s formatCurrentDate method.

$ trace com.hascode.tutorial.CurrentDateController formatCurrentDate
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 35 ms.
`---ts=2018-10-30 15:37:34;thread_name=http-nio-8080-exec-8;id=2b;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@565a8af8
    `---[0.463018ms] com.hascode.tutorial.CurrentDateController:formatCurrentDate()
        +---[0.08954ms] java.time.format.DateTimeFormatter:ofPattern()
        +---[0.008516ms] java.util.concurrent.atomic.AtomicLong:incrementAndGet()
        +---[0.069382ms] java.time.LocalDateTime:now()
        +---[0.02449ms] java.time.format.DateTimeFormatter:format()
        `---[0.058308ms] com.hascode.tutorial.FormattedDate:()

Display parameters, return objects, and thrown exceptions for method invocations

We’re watching the first parameter com.hascode.tutorial.CurrentDateController’s formatCurrentDate method.

$ watch com.hascode.tutorial.CurrentDateController formatCurrentDate params[0]
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 37 ms.
ts=2018-10-30 15:38:40;result=@String[yyyy-MM]

Time Tunnel

We’re capturing timings for com.hascode.tutorial.CurrentDateController’s formatCurrentDate method.

$ tt -t com.hascode.tutorial.CurrentDateController formatCurrentDate
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 39 ms.
 INDEX   TIMESTAMP            COST(ms)  IS-RET   IS-EXP  OBJECT          CLASS                          METHOD
--------------------------------------------------------------------------------------------------------------------------------------
 1000    2018-10-30 15:40:13  0.448587  true     false   0x599e8629      CurrentDateController          formatCurrentDate
 1001    2018-10-30 15:40:15  1.544891  true     false   0x599e8629      CurrentDateController          formatCurrentDate
 1002    2018-10-30 15:40:15  0.192611  true     false   0x599e8629      CurrentDateController          formatCurrentDate
 1003    2018-10-30 15:40:16  0.254755  true     false   0x599e8629      CurrentDateController          formatCurrentDate
 1004    2018-10-30 15:40:17  0.279749  true     false   0x599e8629      CurrentDateController          formatCurrentDate
$ tt -l com.hascode.tutorial.CurrentDateController formatCurrentDate
 INDEX   TIMESTAMP            COST(ms)  IS-RET   IS-EXP  OBJECT          CLASS                          METHOD
--------------------------------------------------------------------------------------------------------------------------------------
 1000    2018-10-30 15:40:13  0.448587  true     false   0x599e8629      CurrentDateController          formatCurrentDate
 1001    2018-10-30 15:40:15  1.544891  true     false   0x599e8629      CurrentDateController          formatCurrentDate
 1002    2018-10-30 15:40:15  0.192611  true     false   0x599e8629      CurrentDateController          formatCurrentDate
 1003    2018-10-30 15:40:16  0.254755  true     false   0x599e8629      CurrentDateController          formatCurrentDate
 1004    2018-10-30 15:40:17  0.279749  true     false   0x599e8629      CurrentDateController          formatCurrentDate
Affect(row-cnt:5) cost in 2 ms.

Dump class byte array from JVM

We’re dumping the class com.hascode.tutorial.CurrentDateController:

$ dump com.hascode.tutorial.CurrentDateController
 HASHCODE  CLASSLOADER                                    LOCATION
 73d16e93  +-sun.misc.Launcher$AppClassLoader@73d16e93    /home/soma/logs/arthas/classdump/sun.misc.Launcher$AppClassLoader-73d16e93/
             +-sun.misc.Launcher$ExtClassLoader@3b1cd4e6  com/hascode/tutorial/CurrentDateController.class
Affect(row-cnt:1) cost in 32 ms.

Reading and Setting System Properties

We’re first reading the properties:

$ sysprop
 KEY                        VALUE
--------------------------------------------------------------------------------------------------------------------------------------
 java.runtime.name          Java(TM) SE Runtime Environment
 sun.boot.library.path      /usr/lib/jvm/jdk1.8.0_151/jre/lib/amd64
 java.vm.version            25.151-b12
 java.vm.vendor             Oracle Corporation
 java.vendor.url            http://java.oracle.com/
 path.separator             :
 java.vm.name               Java HotSpot(TM) 64-Bit Server VM
 file.encoding.pkg          sun.io
 user.country               US
 sun.java.launcher          SUN_STANDARD
 sun.os.patch.level         unknown
 java.vm.specification.nam  Java Virtual Machine Specification
 e
 user.dir                   /data/project/spring-boot-swagger-tutorial
 PID                        18043
 [..]

Then we’re changing the property production.mode to true:

$ sysprop production.mode true
Successfully changed the system property.
production.mode=true

Resources

Debugging and Troubleshooting Java

For more detailed information about tools and methods for analyzing Java applications, please feel free to visit my snippet list here: http://app.hascode.com/forensic/

Tags: , , , , , , , , , , , , ,

Search
Categories