Analyzing Java Applications on the Fly with Arthas
October 31st, 2018 by Micha KopsArthas 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
Contents
- 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
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 $PIDExamples 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
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: alibaba, arthas, capture, classloader, debugging, invocation, jvm, logs, monitoring, statistics, stats, threads, tools, tracing