Analyzing Java Applications on the Fly with Arthas

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.

Figure 1. 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:

Figure 2. Connection Arthas with Spring Boot app

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

Tue Oct 3016:15:54 CET 2018 com.taobao.arthas.agent.ArthasClassloader@307e0d2f JM.Log:INFO Log root path: /home/soma/logs/
Tue Oct 3016: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 in8 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 in7 ms.

Show classloader info

Displays the classloaders used by our application.

$ classloader
name                                       numberOfInstances  loadedCountTotal
sun.misc.Launcher$AppClassLoader13640
BootstrapClassLoader                       12537
com.taobao.arthas.agent.ArthasClassloader  11032
sun.reflect.DelegatingClassLoader          5858
sun.misc.Launcher$ExtClassLoader10
Affect(row-cnt:5) cost in7 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 in503 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 -c5
   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 -c5-n10 com.hascode.tutorial.CurrentDateController formatCurrentDate
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in33 ms.
 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------2018-10-3015:32:08  com.hascode.tutorial.CurrentDateController  formatCurrentDate  181800.230.00%

 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------2018-10-3015:32:13  com.hascode.tutorial.CurrentDateController  formatCurrentDate  222200.200.00%

 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------2018-10-3015:32:18  com.hascode.tutorial.CurrentDateController  formatCurrentDate  222200.220.00%

 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------2018-10-3015:32:23  com.hascode.tutorial.CurrentDateController  formatCurrentDate  111100.200.00%

 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------2018-10-3015:32:28  com.hascode.tutorial.CurrentDateController  formatCurrentDate  8800.260.00%

 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------2018-10-3015:32:33  com.hascode.tutorial.CurrentDateController  formatCurrentDate  8800.160.00%

 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------2018-10-3015:32:38  com.hascode.tutorial.CurrentDateController  formatCurrentDate  141400.190.00%

 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------2018-10-3015:32:43  com.hascode.tutorial.CurrentDateController  formatCurrentDate  171700.170.00%

 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------2018-10-3015:32:48  com.hascode.tutorial.CurrentDateController  formatCurrentDate  9900.180.00%

 timestamp            class                                       method             total  success  fail  avg-rt(ms)  fail-rate
---------------------------------------------------------------------------------------------------------------------------------2018-10-3015:32:53  com.hascode.tutorial.CurrentDateController  formatCurrentDate  191900.200.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 in32 ms.
ts=2018-10-3015: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   900:0falsetrue30         nioEventLoopGroup-2-2             system                10         RUNNABLE   90:0falsefalse23         AsyncAppender-Worker-arthas-cache system                9          WAITING    00:0falsetrue21         Attach Listener                   system                9          RUNNABLE   00:0falsetrue14         ContainerBackgroundProcessor[Stan main                  5          TIMED_WAIT 00:0falsetrue20         DestroyJavaVM                     main                  5          RUNNABLE   00:2falsefalse3          Finalizer                         system                8          WAITING    00:0falsetrue16         NioBlockingSelector.BlockPoller-1 main                  5          RUNNABLE   00:0falsetrue2          Reference Handler                 system                10         WAITING    00:0falsetrue4          Signal Dispatcher                 system                9          RUNNABLE   00:0falsetrue15         container-0                       main                  5          TIMED_WAIT 00:0falsefalse19         http-nio-8080-Acceptor-0          main                  5          RUNNABLE   00:0falsetrue17         http-nio-8080-ClientPoller-0      main                  5          RUNNABLE   00:0falsetrue18         http-nio-8080-ClientPoller-1      main                  5          RUNNABLE   00:0falsetrue36         http-nio-8080-exec-1              main                  5          WAITING    00:0falsetrue46         http-nio-8080-exec-10             main                  5          WAITING    00:0falsetrue37         http-nio-8080-exec-2              main                  5          WAITING    00:0falsetrue38         http-nio-8080-exec-3              main                  5          WAITING    00:0falsetrue39         http-nio-8080-exec-4              main                  5          WAITING    00:0falsetrue40         http-nio-8080-exec-5              main                  5          WAITING    00:0falsetrue41         http-nio-8080-exec-6              main                  5          WAITING    00:0falsetrue42         http-nio-8080-exec-7              main                  5          WAITING    00:0falsetrue43         http-nio-8080-exec-8              main                  5          WAITING    00:0falsetrue45         http-nio-8080-exec-9              main                  5          WAITING    00:0falsetrue25         job-timeout                       system                9          TIMED_WAIT 00:0falsetrue26         nioEventLoopGroup-2-1             system                10         RUNNABLE   00:0falsefalse33         nioEventLoopGroup-2-3             system                10         RUNNABLE   00:0falsefalse48         nioEventLoopGroup-2-4             system                10         RUNNABLE   00:0falsefalse52         nioEventLoopGroup-2-5             system                10         RUNNABLE   00:0falsefalse27         nioEventLoopGroup-3-1             system                10         RUNNABLE   00:0falsefalse28         pool-1-thread-1                   system                5          TIMED_WAIT 00:0falsefalse29         pool-2-thread-1                   system                5          WAITING    00:0falsefalse
Affect(row-cnt:0) cost in119 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 in35 ms.
`---ts=2018-10-3015: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 in37 ms.
ts=2018-10-3015: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 in39 ms.
 INDEX   TIMESTAMP            COST(ms)  IS-RET   IS-EXP  OBJECT          CLASS                          METHOD
--------------------------------------------------------------------------------------------------------------------------------------10002018-10-3015:40:130.448587truefalse   0x599e8629      CurrentDateController          formatCurrentDate
 10012018-10-3015:40:151.544891truefalse   0x599e8629      CurrentDateController          formatCurrentDate
 10022018-10-3015:40:150.192611truefalse   0x599e8629      CurrentDateController          formatCurrentDate
 10032018-10-3015:40:160.254755truefalse   0x599e8629      CurrentDateController          formatCurrentDate
 10042018-10-3015:40:170.279749truefalse   0x599e8629      CurrentDateController          formatCurrentDate
$ tt -l com.hascode.tutorial.CurrentDateController formatCurrentDate
 INDEX   TIMESTAMP            COST(ms)  IS-RET   IS-EXP  OBJECT          CLASS                          METHOD
--------------------------------------------------------------------------------------------------------------------------------------10002018-10-3015:40:130.448587truefalse   0x599e8629      CurrentDateController          formatCurrentDate
 10012018-10-3015:40:151.544891truefalse   0x599e8629      CurrentDateController          formatCurrentDate
 10022018-10-3015:40:150.192611truefalse   0x599e8629      CurrentDateController          formatCurrentDate
 10032018-10-3015:40:160.254755truefalse   0x599e8629      CurrentDateController          formatCurrentDate
 10042018-10-3015:40:170.279749truefalse   0x599e8629      CurrentDateController          formatCurrentDate
Affect(row-cnt:5) cost in2 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 in32 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/

Installation#

Examples of Usage#

Connecting to an Application#

Feature Overview#

Search all the classes loaded by JVM#

Search the method of classes loaded by JVM#

Show classloader info#

Decompile Class#

Monitor method execution statistics#

Display the stack trace for the specified class and method#

Display thread info, thread stack#

Trace the execution time of specified method invocations#

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

Time Tunnel#

Dump class byte array from JVM#

Reading and Setting System Properties#

Resources#

Debugging and Troubleshooting Java#