Java线上诊断工具Arthas

Arthas 是Alibaba开源的Java诊断工具,深受开发者喜爱。Arthas支持JDK 6+,支持Linux/Mac/Winodws,采用命令行交互模式,同时提供丰富的 Tab 自动补全功能,进一步方便进行问题的定位和诊断。

Arthas下载

Arthas(阿尔萨斯)

工欲善其事 必先利其器 Arthas是Java线上诊断的神器

工具背景

Arthas 是Alibaba开源的Java线上诊断工具,支持JDK 6+,支持Linux/Mac/Winodws,采用命令行交互模式,同时提供丰富的 Tab 自动补全功能,进一步方便进行问题的定位和诊断。

想吐槽一下这个名字,作者是有多爱WOW...
官方文档:https://alibaba.github.io/arthas/index.html

应用场景

当你遇到以下类似问题而束手无策时,Arthas可以帮助你解决:

  • 这个类从哪个 jar 包加载的?为什么会报各种类相关的 Exception?
  • 我改的代码为什么没有执行到?难道是我没 commit?分支搞错了?
  • 遇到问题无法在线上 debug,难道只能通过加日志再重新发布吗?
  • 线上遇到某个用户的数据处理有问题,但线上同样无法 debug,线下无法重现!
  • 是否有一个全局视角来查看系统的运行状况?
  • 有什么办法可以监控到JVM的实时运行状态?

快速安装

wget https://alibaba.github.io/arthas/arthas-boot.jar
 
java -jar arthas-boot.jar

快速开始

选择应用java进程:

$ docker exec -it arthas-demo /bin/sh -c "java -jar /opt/arthas/arthas-boot.jar"
[INFO] arthas-boot version: 3.1.1
[INFO] Found existing java process, please choose one and hit RETURN.
* [1]: 6 /opt/arthas/arthas-demo.jar

输入1,再输入回车/enter。Arthas会attach到目标进程上,并输出日志:

[INFO] arthas home: /opt/arthas
[INFO] Try to attach process 6
[INFO] Attach process 6 success.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---.  ,------. m,--------.,--.  ,--.  ,---.   ,---.
 /  O   |  .--. ''--.  .--'|  '--'  | /  O   '   .-'
|  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.
|  | |  ||  |      |  |   |  |  |  ||  | |  |.-'    |
`--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'


wiki      https://alibaba.github.io/arthas
tutorials https://alibaba.github.io/arthas/arthas-tutorials
version   3.1.1
pid       6
time      2019-06-12 02:07:35

$

常用命令

Arthas的具备丰富的功能,并且支持Tab 自动补全,在此不一一列举,详见:https://alibaba.github.io/arthas/advanced-use.html

dashboard

查看当前系统的实时数据面板(Thread/Memory/GC/Runtime/Tomcat),按 ctrl+c 退出。

ID             NAME                                        GROUP                         PRIORITY       STATE          %CPU           TIME          INTERRUPTED    DAEMON
46             Timer-for-arthas-dashboard-0417c82e-1367-4c system                        10             RUNNABLE       100            0:0           false          true
10             AsyncAppender-Worker-arthas-cache.result.As system                        9              WAITING        0              0:0           false          true
8              Attach Listener                             system                        9              RUNNABLE       0              0:0           false          true
3              Finalizer                                   system                        8              WAITING        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
44             as-command-execute-daemon                   system                        10             TIMED_WAITING  0              0:0           false          true
12             job-timeout                                 system                        9              TIMED_WAITING  0              0:0           false          true
1              main                                        main                          5              TIMED_WAITING  0              0:45          false          false
13             nioEventLoopGroup-2-1                       system                        10             RUNNABLE       0              0:8           false          false
17             nioEventLoopGroup-2-2                       system                        10             RUNNABLE       0              0:8           false          false
33             nioEventLoopGroup-2-3                       system                        10             RUNNABLE       0              0:8           false          false
37             nioEventLoopGroup-2-4                       system                        10             RUNNABLE       0              0:7           false          false
14             nioEventLoopGroup-3-1                       system                        10             RUNNABLE       0              0:8           false          false
15             pool-1-thread-1                             system                        5              TIMED_WAITING  0              0:0           false          false
16             pool-2-thread-1                             system                        5              WAITING        0              0:0           false          false


Memory                                used         total        max         usage        GC
heap                                  56M          106M         441M        12.87%       gc.ps_scavenge.count                         23
ps_eden_space                         30M          65M          143M        21.67%       gc.ps_scavenge.time(ms)                      344
ps_survivor_space                     544K         1024K        1024K       53.13%       gc.ps_marksweep.count                        3
ps_old_gen                            25M          39M          331M        7.62%        gc.ps_marksweep.time(ms)                     215
nonheap                               32M          33M          -1          97.19%
code_cache                            7M           8M           240M        3.28%
metaspace                             22M          22M          -1          97.68%
compressed_class_space                2M           2M           1024M       0.24%
direct                                0K           0K           -           Infinity%
mapped                                0K           0K           -           NaN%


Runtime
os.name                                                                                  Linux
os.version                                                                               4.9.125-linuxkit
java.version                                                                             1.8.0_212
java.home                                                                                /usr/lib/jvm/java-1.8-openjdk/jre
systemload.average                                                                       0.11
processors                                                                               2
uptime                                                                                   185745s

thread

查看当前线程信息,查看线程的堆栈。

参数名称参数说明
id线程id
[n:]指定最忙的前N个线程并打印堆栈
[b]找出当前阻塞其他线程的线程
[i ]指定cpu占比统计的采样间隔,单位为毫秒

显示指定线程的运行堆栈

$ thread 1
"main" Id=1 TIMED_WAITING
    at java.lang.Thread.sleep(Native Method)
    at java.lang.Thread.sleep(Thread.java:340)
    at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
    at demo.MathGame.main(MathGame.java:17)

当前最忙的前N个线程并打印堆栈

$ thread -n 3
"as-command-execute-daemon" Id=48 cpuUsage=68% RUNNABLE
    at sun.management.ThreadImpl.dumpThreads0(Native Method)
    at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:448)
    at com.taobao.arthas.core.command.monitor200.ThreadCommand.processTopBusyThreads(ThreadCommand.java:133)
    at com.taobao.arthas.core.command.monitor200.ThreadCommand.process(ThreadCommand.java:79)
    at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.process(AnnotatedCommandImpl.java:82)
    at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl.access$100(AnnotatedCommandImpl.java:18)
    at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:111)
    at com.taobao.arthas.core.shell.command.impl.AnnotatedCommandImpl$ProcessHandler.handle(AnnotatedCommandImpl.java:108)
    at com.taobao.arthas.core.shell.system.impl.ProcessImpl$CommandProcessTask.run(ProcessImpl.java:370)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

    Number of locked synchronizers = 1
    - java.util.concurrent.ThreadPoolExecutor$Worker@503ca440


"nioEventLoopGroup-2-3" Id=33 cpuUsage=31% RUNNABLE (in native)
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    -  locked io.netty.channel.nio.SelectedSelectionKeySet@46d33dbd
    -  locked java.util.Collections$UnmodifiableSet@1672a7b2
    -  locked sun.nio.ch.EPollSelectorImpl@17c134d0
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
    at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:791)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:439)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:906)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)


"Reference Handler" Id=2 cpuUsage=0% WAITING on java.lang.ref.Reference$Lock@138fcfa0
    at java.lang.Object.wait(Native Method)
    -  waiting on java.lang.ref.Reference$Lock@138fcfa0
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

当前阻塞其他线程的线程

$ thread -b
"http-bio-8080-exec-4" Id=27 TIMED_WAITING
    at java.lang.Thread.sleep(Native Method)
    at test.arthas.TestThreadBlocking.doGet(TestThreadBlocking.java:22)
    -  locked java.lang.Object@725be470 <---- but blocks 4 other threads!
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:624)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at test.filter.TestDurexFilter.doFilter(TestDurexFilter.java:46)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)
    at com.taobao.tomcat.valves.ContextLoadFilterValve$FilterChainAdapter.doFilter(ContextLoadFilterValve.java:191)
    at com.taobao.eagleeye.EagleEyeFilter.doFilter(EagleEyeFilter.java:81)
    at com.taobao.tomcat.valves.ContextLoadFilterValve.invoke(ContextLoadFilterValve.java:150)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:429)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1085)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:318)
    -  locked org.apache.tomcat.util.net.SocketWrapper@7127ee12
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)
 
    Number of locked synchronizers = 1
    - java.util.concurrent.ThreadPoolExecutor$Worker@31a6493e

jvm

查看当前JVM信息。

$ jvm
 RUNTIME
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 MACHINE-NAME                                       6@4425d962807f
 JVM-START-TIME                                     2019-06-12 02:07:19
 MANAGEMENT-SPEC-VERSION                            1.2
 SPEC-NAME                                          Java Virtual Machine Specification
 SPEC-VENDOR                                        Oracle Corporation
 SPEC-VERSION                                       1.8
 VM-NAME                                            OpenJDK 64-Bit Server VM
 VM-VENDOR                                          IcedTea
 VM-VERSION                                         25.212-b04
 INPUT-ARGUMENTS                                    []
 CLASS-PATH                                         /opt/arthas/arthas-demo.jar
 BOOT-CLASS-PATH                                    /usr/lib/jvm/java-1.8-openjdk/jre/lib/resources.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib/rt.jar:/usr/lib/jvm/java-1.8-openjd
                                                    k/jre/lib/sunrsasign.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib/jsse.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib/jce.jar:/usr/li
                                                    b/jvm/java-1.8-openjdk/jre/lib/charsets.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib/jfr.jar:/usr/lib/jvm/java-1.8-openjdk/jre/c
                                                    lasses
 LIBRARY-PATH                                       /usr/lib/jvm/java-1.8-openjdk/jre/lib/amd64/server:/usr/lib/jvm/java-1.8-openjdk/jre/lib/amd64:/usr/lib/jvm/java-1.8-openjdk/
                                                    jre/../lib/amd64:/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 CLASS-LOADING
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 
 LOADED-CLASS-COUNT                                 3653
 TOTAL-LOADED-CLASS-COUNT                           3653
 UNLOADED-CLASS-COUNT                               0
 IS-VERBOSE                                         false

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 COMPILATION
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 
 NAME                                               HotSpot 64-Bit Tiered Compilers
 TOTAL-COMPILE-TIME                                 11209(ms)

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 GARBAGE-COLLECTORS
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 
 PS Scavenge                                        24/347(ms)
 [count/time]
 PS MarkSweep                                       3/215(ms)
 [count/time]

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 MEMORY-MANAGERS
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 
 CodeCacheManager                                   Code Cache

 Metaspace Manager                                  Metaspace
                                                    Compressed Class Space

 PS Scavenge                                        PS Eden Space
                                                    PS Survivor Space

 PS MarkSweep                                       PS Eden Space
                                                    PS Survivor Space
                                                    PS Old Gen


----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 MEMORY
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 
 HEAP-MEMORY-USAGE                                  124780544(119.00 MiB)/33554432(32.00 MiB)/462422016(441.00MiB)/52041680(49.63 MiB)
 [committed/init/max/used]
 NO-HEAP-MEMORY-USAGE                               35520512(33.88 MiB)/2555904(2.44 MiB)/-1(-1 B)/34438440(32.84 MiB)
 [committed/init/max/used]
 PENDING-FINALIZE-COUNT                             0

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 OPERATING-SYSTEM
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 OS                                                 Linux
 ARCH                                               amd64
 PROCESSORS-COUNT                                   2
 LOAD-AVERAGE                                       0.00341796875
 VERSION                                            4.9.125-linuxkit

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 THREAD
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 COUNT                                              15
 DAEMON-COUNT                                       7
 PEAK-COUNT                                         16
 STARTED-COUNT                                      46
 DEADLOCK-COUNT                                     0

----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 FILE-DESCRIPTOR
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 MAX-FILE-DESCRIPTOR-COUNT                          1048576
 OPEN-FILE-DESCRIPTOR-COUNT                         51

sysprop

查看当前JVM的系统属性(System Property)

查看全部系统属性

$ sysprop
 KEY                                 VALUE
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 
 java.runtime.name                   OpenJDK Runtime Environment
 sun.boot.library.path               /usr/lib/jvm/java-1.8-openjdk/jre/lib/amd64
 java.vm.version                     25.212-b04
 java.vm.vendor                      IcedTea
 java.vendor.url                     https://icedtea.classpath.org
 path.separator                      :
 java.vm.name                        OpenJDK 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.name          Java Virtual Machine Specification
 user.dir                            /
 java.runtime.version                1.8.0_212-b04
 JM.LOG.PATH                         /root/logs
 java.awt.graphicsenv                sun.awt.X11GraphicsEnvironment
 java.endorsed.dirs                  /usr/lib/jvm/java-1.8-openjdk/jre/lib/endorsed
 os.arch                             amd64
 java.io.tmpdir                      /tmp
 line.separator

 java.vm.specification.vendor        Oracle Corporation
 os.name                             Linux
 sun.jnu.encoding                    UTF-8
 java.library.path                   /usr/lib/jvm/java-1.8-openjdk/jre/lib/amd64/server:/usr/lib/jvm/java-1.8-openjdk/jre/lib/amd64:/usr/lib/jvm/java-1.8-openjdk/jre/../lib/amd6
                                     4:/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
 sun.nio.ch.bugLevel
 java.specification.name             Java Platform API Specification
 java.class.version                  52.0
 sun.management.compiler             HotSpot 64-Bit Tiered Compilers
 os.version                          4.9.125-linuxkit
 user.home                           /root
 user.timezone                       GMT
 java.awt.printerjob                 sun.print.PSPrinterJob
 file.encoding                       UTF-8
 java.specification.version          1.8
 user.name                           root
 java.class.path                     /opt/arthas/arthas-demo.jar
 java.vm.specification.version       1.8
 sun.arch.data.model                 64
 java.home                           /usr/lib/jvm/java-1.8-openjdk/jre
 sun.java.command                    /opt/arthas/arthas-demo.jar
 java.specification.vendor           Oracle Corporation
 user.language                       en
 awt.toolkit                         sun.awt.X11.XToolkit
 java.vm.info                        mixed mode
 java.version                        1.8.0_212
 java.ext.dirs                       /usr/lib/jvm/java-1.8-openjdk/jre/lib/ext:/usr/java/packages/lib/ext
 sun.boot.class.path                 /usr/lib/jvm/java-1.8-openjdk/jre/lib/resources.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib/rt.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib/sunrs
                                     asign.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib/jsse.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib/jce.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib
                                     /charsets.jar:/usr/lib/jvm/java-1.8-openjdk/jre/lib/jfr.jar:/usr/lib/jvm/java-1.8-openjdk/jre/classes
 java.vendor                         IcedTea
 file.separator                      /
 java.vendor.url.bug                 https://icedtea.classpath.org/bugzilla
 sun.cpu.endian                      little
 sun.io.unicode.encoding             UnicodeLittle
 sun.cpu.isalist

查看单个系统属性

$ sysprop java.version
java.version=1.8.0_212

sysenv

查看当前JVM的环境属性(System Environment Variables)

查看所有环境变量

$ sysenv
 KEY                                 VALUE
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 
 PATH                                /usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/lib/jvm/java-1.8-openjdk/jre/bin:/usr/lib/jvm/java-1.8-openjdk/bin
 JAVA_HOME                           /usr/lib/jvm/java-1.8-openjdk
 TERM                                xterm
 MIRROR_MAVEN_HOST                   http://maven.aliyun.com/repository/public
 MIRROR_ALPINE_HOST                  mirrors.aliyun.com
 LANG                                C.UTF-8
 ALPINE_HOST                         dl-cdn.alpinelinux.org
 HOSTNAME                            4425d962807f
 JAVA_ALPINE_VERSION                 8.212.04-r0
 LD_LIBRARY_PATH                     /usr/lib/jvm/java-1.8-openjdk/jre/lib/amd64/server:/usr/lib/jvm/java-1.8-openjdk/jre/lib/amd64:/usr/lib/jvm/java-1.8-openjdk/jre/../lib/amd6
                                     4
 PWD                                 /
 MAVEN_HOST                          http://repo1.maven.org/maven2
 JAVA_VERSION                        8u212
 HOME                                /root
 SHLVL                               1

查看单个环境变量

$ sysenv HOSTNAME
HOSTNAME=4425d962807f

monitor

方法执行监控,对匹配 class-pattern/method-pattern的类、方法的调用进行监控。

参数名称参数说明
class-pattern类名表达式匹配
method-pattern方法名表达式匹配
[E]开启正则表达式匹配,默认为通配符匹配
[c:]统计周期,默认值为120秒
$ monitor -c 5 demo.MathGame primeFactors
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 26 ms.
 timestamp            class          method        total  success  fail  avg-rt(ms)  fail-rate
-----------------------------------------------------------------------------------------------
 2019-06-14 06:17:39  demo.MathGame  primeFactors  5      2        3     0.09        60.00%

 timestamp            class          method        total  success  fail  avg-rt(ms)  fail-rate
-----------------------------------------------------------------------------------------------
 2019-06-14 06:17:44  demo.MathGame  primeFactors  5      3        2     0.03        40.00%

 timestamp            class          method        total  success  fail  avg-rt(ms)  fail-rate
-----------------------------------------------------------------------------------------------
 2019-06-14 06:17:49  demo.MathGame  primeFactors  5      2        3     0.17        60.00%

 timestamp            class          method        total  success  fail  avg-rt(ms)  fail-rate
-----------------------------------------------------------------------------------------------
 2019-06-14 06:17:54  demo.MathGame  primeFactors  5      2        3     0.17        60.00%

 timestamp            class          method        total  success  fail  avg-rt(ms)  fail-rate
-----------------------------------------------------------------------------------------------
 2019-06-14 06:17:59  demo.MathGame  primeFactors  5      2        3     0.12        60.00%

 timestamp            class          method        total  success  fail  avg-rt(ms)  fail-rate
-----------------------------------------------------------------------------------------------
 2019-06-14 06:18:04  demo.MathGame  primeFactors  5      3        2     0.60        40.00%
  • timestamp: 时间戳
  • class: Java类
  • method: 方法(构造方法、普通方法)
  • total: 调用次数
  • success: 成功次数
  • fail: 失败次数
  • rt: 平均RT
  • fail-rate: 失败率

watch

方法执行数据观测,让你能方便的观察到指定方法的调用情况。能观察到的范围为:返回值、抛出异常、入参,通过编写 OGNL 表达式进行对应变量的查看。

参数名称参数说明
class-pattern类名表达式匹配
method-pattern方法名表达式匹配
express观察表达式
condition-express条件表达式
[b]在方法调用之前观察
[e]在方法异常之后观察
[s]在方法返回之后观察
[f]在方法结束之后(正常返回和异常返回)观察,默认打开
[E]开启正则表达式匹配,默认为通配符匹配
[x:]指定输出结果的属性遍历深度,默认为 1

观察方法出参和返回值

$ watch demo.MathGame primeFactors "{params,returnObj}" -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 44 ms.
ts=2019-06-14 06:34:19; [cost=0.3721ms] result=@ArrayList[
    @Object[][
        @Integer[15013],
    ],
    @ArrayList[
        @Integer[15013],
    ],
]
ts=2019-06-14 06:34:20; [cost=0.1084ms] result=@ArrayList[
    @Object[][
        @Integer[-75392],
    ],
    null,
]

观察方法入参

$ watch demo.MathGame primeFactors "{params,returnObj}" -x 2 -b
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 52 ms.
ts=2019-06-14 06:35:07; [cost=0.0194ms] result=@ArrayList[
    @Object[][
        @Integer[31370],
    ],
    null,
]
ts=2019-06-14 06:35:08; [cost=0.0101ms] result=@ArrayList[
    @Object[][
        @Integer[-82029],
    ],
    null,
]

同时观察方法调用前和方法返回后

$ watch demo.MathGame primeFactors "{params,target,returnObj}" -x 2 -b -s -n 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 40 ms.
ts=2019-06-14 06:35:57; [cost=0.0334ms] result=@ArrayList[
    @Object[][
        @Integer[-136522],
    ],
    @MathGame[
        random=@Random[java.util.Random@533ddba],
        illegalArgumentCount=@Integer[94006],
    ],
    null,
]
ts=2019-06-14 06:35:58; [cost=0.0098ms] result=@ArrayList[
    @Object[][
        @Integer[-16431],
    ],
    @MathGame[
        random=@Random[java.util.Random@533ddba],
        illegalArgumentCount=@Integer[94007],
    ],
    null,
]

调整-x的值,观察具体的方法参数值

$ watch demo.MathGame primeFactors "{params,target}" -x 3
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 42 ms.
ts=2019-06-14 06:37:02; [cost=0.085ms] result=@ArrayList[
    @Object[][
        @Integer[151500],
    ],
    @MathGame[
        random=@Random[
            serialVersionUID=@Long[3905348978240129619],
            seed=@AtomicLong[99287665085135],
            multiplier=@Long[25214903917],
            addend=@Long[11],
            mask=@Long[281474976710655],
            DOUBLE_UNIT=@Double[1.1102230246251565E-16],
            BadBound=@String[bound must be positive],
            BadRange=@String[bound must be greater than origin],
            BadSize=@String[size must be non-negative],
            seedUniquifier=@AtomicLong[-3282039941672302964],
            nextNextGaussian=@Double[0.0],
            haveNextNextGaussian=@Boolean[false],
            serialPersistentFields=@ObjectStreamField[][isEmpty=false;size=3],
            unsafe=@Unsafe[sun.misc.Unsafe@3c9f287f],
            seedOffset=@Long[24],
        ],
        illegalArgumentCount=@Integer[94039],
    ],
]

观察异常信息的例子

$ watch demo.MathGame primeFactors "{params[0],throwExp}" -e -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 33 ms.
ts=2019-06-14 06:38:20; [cost=0.3491ms] result=@ArrayList[
    @Integer[-111033],
    java.lang.IllegalArgumentException: number is: -111033, need >= 2
        at demo.MathGame.primeFactors(MathGame.java:46)
        at demo.MathGame.run(MathGame.java:24)
        at demo.MathGame.main(MathGame.java:16)
,
]
ts=2019-06-14 06:38:21; [cost=0.0673ms] result=@ArrayList[
    @Integer[-150545],
    java.lang.IllegalArgumentException: number is: -150545, need >= 2
        at demo.MathGame.primeFactors(MathGame.java:46)
        at demo.MathGame.run(MathGame.java:24)
        at demo.MathGame.main(MathGame.java:16)
,
]

trace

方法内部调用路径,并输出方法路径上的每个节点上耗时,trace 命令能主动搜索 class-pattern/method-pattern 对应的方法调用路径,渲染和统计整个调用链路上的所有性能开销和追踪调用链路。

参数名称参数说明
class-pattern类名表达式匹配
method-pattern方法名表达式匹配
condition-express条件表达式
[j]跳过JDK方法
[E]开启正则表达式匹配,默认为通配符匹配
[n:]命令执行次数
#cost方法执行耗时
$ trace demo.MathGame run
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 44 ms.
`---ts=2019-06-14 06:42:24;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@70dea4e
    `---[0.6678ms] demo.MathGame:run()
        +---[0.0248ms] java.util.Random:nextInt() #23
        +---[0.1465ms] demo.MathGame:primeFactors() #24
        `---[0.1904ms] demo.MathGame:print() #25

stack

输出当前方法被调用的调用路径,很多时候我们都知道一个方法被执行,但这个方法被执行的路径非常多,或者你根本就不知道这个方法是从那里被执行了,此时你需要的是 stack 命令。

参数名称参数说明
class-pattern类名表达式匹配
method-pattern方法名表达式匹配
condition-express条件表达式
[E]开启正则表达式匹配,默认为通配符匹配
[n:]命令执行次数
$ stack demo.MathGame primeFactors
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 48 ms.
ts=2019-06-14 06:48:00;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@70dea4e
    @demo.MathGame.run()
        at demo.MathGame.main(MathGame.java:16)

tt

方法执行数据的时空隧道,记录下指定方法每次调用的入参和返回信息,并能对这些不同的时间下调用进行观测。

参数名称参数说明
-t方法的每次执行情况
-n [n]需要记录的次数
condition-express条件表达式
-l对现有记录进行检索
-s [express]对现有记录进行筛选
-i [index]查看调用信息
-p重做一次调用
--replay-times指定调用次数
--replay-interval指定调用间隔(单位ms, 默认1000ms)

记录调用

$ tt -t demo.MathGame primeFactors
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 48 ms.
 INDEX      TIMESTAMP                   COST(ms)     IS-RET     IS-EXP      OBJECT              CLASS                                     METHOD
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 
 1038       2019-06-14 07:13:02         0.4279       true       false       0x5197848c          MathGame                                  primeFactors
 1039       2019-06-14 07:13:03         16.4051      true       false       0x5197848c          MathGame                                  primeFactors
 1040       2019-06-14 07:13:04         0.067        true       false       0x5197848c          MathGame                                  primeFactors
 1041       2019-06-14 07:13:05         0.0933       true       false       0x5197848c          MathGame                                  primeFactors
 1042       2019-06-14 07:13:06         0.5713       true       false       0x5197848c          MathGame                                  primeFactors
  • INDEX: 时间片段记录编号,每一个编号代表着一次调用,后续tt还有很多命令都是基于此编号指定记录操作,非常重要。
  • TIMESTAMP: 方法执行的本机时间,记录了这个时间片段所发生的本机时间
  • COST(ms): 方法执行的耗时
  • IS-RET: 方法是否以正常返回的形式结束
  • IS-EXP: 方法是否以抛异常的形式结束
  • OBJECT: 执行对象的hashCode(),注意,曾经有人误认为是对象在JVM中的内存地址,但很遗憾他不是。但他能帮助你简单的标记当前执行方法的类实体
  • CLASS: 执行的类名
  • METHOD: 执行的方法名

对记录进行检索

$ tt -l
 INDEX      TIMESTAMP                   COST(ms)     IS-RET     IS-EXP      OBJECT              CLASS                                     METHOD
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 1038       2019-06-14 07:13:02         0.4279       true       false       0x5197848c          MathGame                                  primeFactors
 1039       2019-06-14 07:13:03         16.4051      true       false       0x5197848c          MathGame                                  primeFactors
 1040       2019-06-14 07:13:04         0.067        true       false       0x5197848c          MathGame                                  primeFactors
 1041       2019-06-14 07:13:05         0.0933       true       false       0x5197848c          MathGame                                  primeFactors
 1042       2019-06-14 07:13:06         0.5713       true       false       0x5197848c          MathGame                                  primeFactors

对记录进行筛选

$ tt -s 'method.name=="primeFactors"'
 INDEX      TIMESTAMP                   COST(ms)     IS-RET     IS-EXP      OBJECT              CLASS                                     METHOD
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 1038       2019-06-14 07:13:02         0.4279       true       false       0x5197848c          MathGame                                  primeFactors
 1039       2019-06-14 07:13:03         16.4051      true       false       0x5197848c          MathGame                                  primeFactors
 1040       2019-06-14 07:13:04         0.067        true       false       0x5197848c          MathGame                                  primeFactors
 1041       2019-06-14 07:13:05         0.0933       true       false       0x5197848c          MathGame                                  primeFactors
 1042       2019-06-14 07:13:06         0.5713       true       false       0x5197848c          MathGame                                  primeFactors

查看调用信息

$ tt -i 1038
 INDEX          1038
 GMT-CREATE     2019-06-14 07:13:02
 COST(ms)       0.4279
 OBJECT         0x5197848c
 CLASS          demo.MathGame
 METHOD         primeFactors
 IS-RETURN      true
 IS-EXCEPTION   false
 PARAMETERS[0]  @Integer[190307]
 RETURN-OBJ     @ArrayList[
                    @Integer[13],
                    @Integer[14639],
                ]

重做一次调用

$ tt -i 1038 -p
 RE-INDEX       1038
 GMT-REPLAY     2019-06-14 07:22:58
 OBJECT         0x5197848c
 CLASS          demo.MathGame
 METHOD         primeFactors
 PARAMETERS[0]  @Integer[190307]
 IS-RETURN      true
 IS-EXCEPTION   false
 COST(ms)       0.414
 RETURN-OBJ     @ArrayList[
                    @Integer[13],
                    @Integer[14639],
                ]
Time fragment[1038] successfully replayed 1 times.

jad/mc/redefine

  • jad(反编译指定已加载类的源码)
  • mc(Memory Compiler/内存编译器,编译.java文件生成.class)
  • redefine (加载外部的.class文件,redefine jvm已加载的类)

组合使用这三个命令可以实现线上热更新代码!

Step1 jad命令反编译到磁盘文件

jad --source-only demo.MathGame > /tmp/MathGame.java

Step2 使用文本编辑器修改代码

vi /tmp/MathGame.java
    public static void print(int number, List<Integer> primeFactors) {
        StringBuffer sb = new StringBuffer("" + number + "=");
        Iterator<Integer> iterator = primeFactors.iterator();
        while (iterator.hasNext()) {
            int factor = iterator.next();
            sb.append(factor).append('*');
        }
        if (sb.charAt(sb.length() - 1) == '*') {
            sb.deleteCharAt(sb.length() - 1);
        }
        System.out.println("MyTest.......");
    }

Step3 mc命令来内存编译修改过的代码

$ mc /tmp/MathGame.java -d /tmp
Memory compiler output:
/tmp/demo/MathGame.class

Step4 用redefine命令加载新的字节码

$ redefine /tmp/demo/MathGame.class
redefine success, size: 1

现在看一下程序日志

illegalArgumentCount:96218, number is: -169877, need >= 2
illegalArgumentCount:96219, number is: -57731, need >= 2
MyTest.......
illegalArgumentCount:96220, number is: -207843, need >= 2
illegalArgumentCount:96221, number is: -193695, need >= 2
MyTest.......
illegalArgumentCount:96222, number is: -19514, need >= 2
illegalArgumentCount:96223, number is: -199441, need >= 2
illegalArgumentCount:96224, number is: -110791, need >= 2
MyTest.......
illegalArgumentCount:96225, number is: -116154, need >= 2
MyTest.......
MyTest.......
MyTest.......
MyTest.......
MyTest.......
MyTest.......

果然神器~~~

发表评论