锐客网

  1. 首页 > it技术 > >

线上问题排查神器入门——Arthas

作者：threedayman
来源：恒生LIGHT云社区
Arthas 是什么
Arthas是一款阿里巴巴开源的 Java 线上诊断工具。Arthas支持JDK 6+，支持Linux/Mac/Windows，采用命令行交互模式，同时提供丰富的 Tab 自动补全功能，进一步方便进行问题的定位和诊断。
官网地址：https://arthas.aliyun.com/doc/
github地址：https://github.com/alibaba/arthas
Arthas能干什么 大家有没有在生产 或者测试环境中遇到下列问题。
  • 这个类从哪个 jar 包加载的？为什么会报各种类相关的 Exception？
  • 我改的代码为什么没有执行到？难道是我没 commit？分支搞错了？
  • 遇到问题无法在线上 debug，难道只能通过加日志再重新发布吗？
  • 线上遇到某个用户的数据处理有问题，但线上同样无法 debug，线下无法重现！
  • 是否有一个全局视角来查看系统的运行状况？
  • 有什么办法可以监控到JVM的实时运行状态？
  • 怎么快速定位应用的热点，生成火焰图？
  • 怎样直接从JVM内查找某个类的实例？
  • 怎样定位慢调用方法。
在官网上说Arthas能帮忙处理以上问题，并没有写明怎么处理，下面我们通过介绍几个命令来介绍下，以上问题通过Arthas怎么去定位处理。
Arthas快速入门 下载Arthas
curl -O https://arthas.aliyun.com/arthas-boot.jar

运行Arthas
java -jar arthas-boot.jar

运行该命令后 会显示java 进程，选择需要排查的进程。
我们运行以下测试代码来看看arthas的使用
package com.example.arthas; public class ArthasTest {public static void main(String[] args) throws InterruptedException { while(true){ put("test"); } }private static String put(String name) throws InterruptedException { Thread.sleep(1000L); System.out.println(name); return "hello "+name; } }

选择我们测试代码运行的进程[3]22756
[INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER. * [1]: 1200 org.jetbrains.jps.cmdline.Launcher [2]: 9120 [3]: 22756 com.example.arthas.ArthasTest

这个类从哪个 jar 包加载的？为什么会报各种类相关的 Exception？**
通过sc命令查找类是哪个jar包加载的
[arthas@22756]$ sc -d com.example.arthas.ArthasTest class-infocom.example.arthas.ArthasTest code-source/D:/ideaproject/jsoupservice/target/classes/ namecom.example.arthas.ArthasTest isInterfacefalse isAnnotationfalse isEnumfalse isAnonymousClassfalse isArrayfalse isLocalClassfalse isMemberClassfalse isPrimitivefalse isSyntheticfalse simple-nameArthasTest modifierpublic annotation interfaces super-class+-java.lang.Object class-loader+-sun.misc.Launcher$AppClassLoader@18b4aac2 +-sun.misc.Launcher$ExtClassLoader@593cfc78 classLoaderHash18b4aac2Affect(row-cnt:1) cost in 77 ms.

其中code-source 信息表明类加载路径，如果是jar包中加载出来的 会显示jar包信息，如下
code-sourcefile:/home/trade/u3/u3-mnager/u-mnager-1.jar!/BOOT-INF/lib/uc-do-1.0-SNAPSHOT.jar!/

对于依赖冲突这类问题，我们可以通过该命令来进行排查。
我改的代码为什么没有执行到？难道是我没 commit？分支搞错了？
我们通过jad命令来反编译查看源码信息
[arthas@22756]$ jad com.example.arthas.ArthasTestClassLoader: +-sun.misc.Launcher$AppClassLoader@18b4aac2 +-sun.misc.Launcher$ExtClassLoader@593cfc78Location: /D:/ideaproject/jsoupservice/target/classes//* * Decompiled with CFR. */ package com.example.arthas; public class ArthasTest { public static void main(String[] args) throws InterruptedException { while (true) { /* 7*/ArthasTest.put("test"); } }private static String put(String name) throws InterruptedException { /*12*/Thread.sleep(1000L); /*13*/System.out.println(name); return "hello " + name; } }Affect(row-cnt:1) cost in 164 ms.

通过查看反编译代码确认是否运行的是提交后的代码。
遇到问题无法在线上 debug，难道只能通过加日志再重新发布吗？
watch 观察方法执行的入参和返回值
[arthas@22756]$ watch com.example.arthas.ArthasTest put '{params,returnObj}' -x 2 -n2 Press Q or Ctrl+C to abort. Affect(class count: 1 , method count: 1) cost in 12 ms, listenerId: 3 method=com.example.arthas.ArthasTest.put location=AtExit ts=2021-08-04 17:07:19; [cost=3.10595639883E7ms] result=@ArrayList[ @Object[][ @String[test], ], @String[hello test], ] method=com.example.arthas.ArthasTest.put location=AtExit ts=2021-08-04 17:07:20; [cost=1009.9733ms] result=@ArrayList[ @Object[][ @String[test], ], @String[hello test], ]

-x 输出结果属性遍历深度
-n 执行次数
retransform 加载外部的 .class文件，retransform jvm已加载的类.
结合jad、mc命令，通过jad反编译，通过编辑器修改源码,加入相关日志。mc命令来内存编译修改过的代码。
用retransform命令加载新的字节码。通过热加载将日志语句添加进去。
jad --source-only com.example.arthas.ArthasTest > D:/ArthasTest.java mc d:/ArthasTest.java -d d: retransform d:/com/example/arthas/ArthasTest.class

线上遇到某个用户的数据处理有问题，但线上同样无法 debug，线下无法重现！
此问题也可通过上面 watch 方法去观测线上 相关调用出入参。可以根据已知的调查结果给watch 方法加上对应的条件参数，以过滤掉不需要观测的请求。watch命令文档。
是否有一个全局视角来查看系统的运行状况？
dashboard实时数据面板命令,可以查看到线程、内存、系统参数等信息，具体的参数解释可以参考 dashboard文档
[arthas@17396]$ dashboard -n 1 IDNAMEGROUPPRIORITYSTATE%CPUDELTA_TIM TIMEINTERRUPT DAEMON -1C1 CompilerThread3--1-0.00.0000:0.437falsetrue -1C2 CompilerThread2--1-0.00.0000:0.375falsetrue 1mainmain5TIMED_WA 0.00.0000:0.328falsefalse -1C2 CompilerThread0--1-0.00.0000:0.312falsetrue -1C2 CompilerThread1--1-0.00.0000:0.281falsetrue 23arthas-NettyHttpTelnetBootstr system5RUNNABLE 0.00.0000:0.234falsetrue 5Attach Listenersystem5RUNNABLE 0.00.0000:0.031falsetrue -1GC task thread#7 (ParallelGC) --1-0.00.0000:0.031falsetrue -1GC task thread#6 (ParallelGC) --1-0.00.0000:0.031falsetrue -1GC task thread#0 (ParallelGC) --1-0.00.0000:0.031falsetrue -1GC task thread#1 (ParallelGC) --1-0.00.0000:0.031falsetrue -1VM Thread--1-0.00.0000:0.031falsetrue -1GC task thread#2 (ParallelGC) --1-0.00.0000:0.031falsetrue -1GC task thread#3 (ParallelGC) --1-0.00.0000:0.031falsetrue -1GC task thread#5 (ParallelGC) --1-0.00.0000:0.031falsetrue -1GC task thread#4 (ParallelGC) --1-0.00.0000:0.031falsetrue 16arthas-NettyHttpTelnetBootstr system5RUNNABLE 0.00.0000:0.015falsetrue 6Monitor Ctrl-Breakmain5RUNNABLE 0.00.0000:0.015falsetrue 2Reference Handlersystem10WAITING0.00.0000:0.000falsetrue 3Finalizersystem8WAITING0.00.0000:0.000falsetrue 4Signal Dispatchersystem9RUNNABLE 0.00.0000:0.000falsetrue 13arthas-timersystem5WAITING0.00.0000:0.000falsetrue 17arthas-NettyWebsocketTtyBoots system5RUNNABLE 0.00.0000:0.000falsetrue 18arthas-NettyWebsocketTtyBoots system5RUNNABLE 0.00.0000:0.000falsetrue MemoryusedtotalmaxusageGC heap26M165M3591M0.75%gc.ps_scavenge.count2 ps_eden_space8M63M1325M0.67%gc.ps_scavenge.time(ms)16 ps_survivor_space0K10752K10752K0.00%gc.ps_marksweep.count1 ps_old_gen17M91M2693M0.67%gc.ps_marksweep.time(ms)41 nonheap29M30M-197.08% code_cache6M6M240M2.57% metaspace20M21M-197.06% compressed_class_space2M2M1024M0.25% direct0K0K-0.00% mapped0K0K-0.00% Runtime os.nameWindows 10 os.version10.0 java.version1.8.0_291 java.homeC:\Program Files\Java\jdk1.8.0_291\jre systemload.average-1.00 processors8 timestamp/uptimeFri Aug 06 09:43:41 GMT+08:00 2021/326s

classloader 查看类加载器和其加载类数量.
[arthas@17396]$ classloader namenumberOfInstancesloadedCountTotal BootstrapClassLoader12782 com.taobao.arthas.agent.ArthasClassloader11373 sun.misc.Launcher$ExtClassLoader160 sun.reflect.DelegatingClassLoader1515 sun.misc.Launcher$AppClassLoader17 Affect(row-cnt:5) cost in 3 ms.

有什么办法可以监控到JVM的实时运行状态？
通过jvm 命令可以查看到jvm的实时运行状态。其中包含了机器信息、编译器信息、垃圾回收器、类加载信息、内存管理、线程相关信息、文件描述符相关信息。jvm命令文档
[arthas@17396]$ jvm RUNTIME ----------------------------------------------------------------------------------------------------------------------- MACHINE-NAME17396@WINDOWS-D2B420I JVM-START-TIME2021-08-06 09:38:14 MANAGEMENT-SPEC-VERSION1.2 SPEC-NAMEJava Virtual Machine Specification SPEC-VENDOROracle Corporation SPEC-VERSION1.8 VM-NAMEJava HotSpot(TM) 64-Bit Server VM VM-VENDOROracle Corporation VM-VERSION25.291-b10 INPUT-ARGUMENTS-javaagent:D:\JetBrains\IntelliJ IDEA 2021.1\lib\idea_rt.jar=61057:D:\JetBrains\Int elliJ IDEA 2021.1\bin -Dfile.encoding=UTF-8 CLASS-PATHC:\Program Files\Java\jdk1.8.0_291\jre\lib\charsets.jar; C:\Program Files\Java\jdk1. 8.0_291\jre\lib\deploy.jar; C:\Program ea_rt.jar BOOT-CLASS-PATHC:\Program Files\Java\jdk1.8.0_291\jre\lib\resources.jar; C:\Program Files\Java\jdk1 .8.0_291\jre\lib\rt.jar; C:\Program ----------------------------------------------------------------------------------------------------------------------- CLASS-LOADING ----------------------------------------------------------------------------------------------------------------------- LOADED-CLASS-COUNT3914 TOTAL-LOADED-CLASS-COUNT3914 UNLOADED-CLASS-COUNT0 IS-VERBOSEfalse----------------------------------------------------------------------------------------------------------------------- COMPILATION ----------------------------------------------------------------------------------------------------------------------- NAMEHotSpot 64-Bit Tiered Compilers TOTAL-COMPILE-TIME1317 [time (ms)]----------------------------------------------------------------------------------------------------------------------- GARBAGE-COLLECTORS ----------------------------------------------------------------------------------------------------------------------- PS Scavengename : PS Scavenge [count/time (ms)]collectionCount : 2 collectionTime : 16 PS MarkSweepname : PS MarkSweep [count/time (ms)]collectionCount : 1 collectionTime : 41----------------------------------------------------------------------------------------------------------------------- MEMORY-MANAGERS ----------------------------------------------------------------------------------------------------------------------- CodeCacheManagerCode Cache Metaspace ManagerMetaspace Compressed Class Space PS ScavengePS Eden Space PS Survivor Space PS MarkSweepPS Eden Space PS Survivor Space PS Old Gen----------------------------------------------------------------------------------------------------------------------- MEMORY ----------------------------------------------------------------------------------------------------------------------- HEAP-MEMORY-USAGEinit : 266338304(254.0 MiB) [memory in bytes]used : 29895120(28.5 MiB) committed : 173015040(165.0 MiB) max : 3765960704(3.5 GiB) NO-HEAP-MEMORY-USAGEinit : 2555904(2.4 MiB) [memory in bytes]used : 31363048(29.9 MiB) committed : 32161792(30.7 MiB) max : -1(-1 B) PENDING-FINALIZE-COUNT0----------------------------------------------------------------------------------------------------------------------- OPERATING-SYSTEM ----------------------------------------------------------------------------------------------------------------------- OSWindows 10 ARCHamd64 PROCESSORS-COUNT8 LOAD-AVERAGE-1.0 VERSION10.0----------------------------------------------------------------------------------------------------------------------- THREAD ----------------------------------------------------------------------------------------------------------------------- COUNT15 DAEMON-COUNT14 PEAK-COUNT16 STARTED-COUNT21 DEADLOCK-COUNT0----------------------------------------------------------------------------------------------------------------------- FILE-DESCRIPTOR ----------------------------------------------------------------------------------------------------------------------- MAX-FILE-DESCRIPTOR-COUNT-1 OPEN-FILE-DESCRIPTOR-COUNT-1

怎么快速定位应用的热点，生成火焰图？
profiler 命令支持生成应用热点的火焰图。本质上是通过不断的采样，然后把收集到的采样结果生成火焰图(该命令只支持linux/mac)。
$ profiler start Started [cpu] profiling $ profiler status [cpu] profiling is running for 4 seconds $ profiler stop profiler output file: /tmp/demo/arthas-output/20191125-135546.svg OK

默认情况下，arthas使用3658端口，则可以打开： http://localhost:3658/arthas-output/ 查看到 arthas-output目录下面的profiler结果：
线上问题排查神器入门——Arthas
文章图片

点击可以查看具体的结果：
线上问题排查神器入门——Arthas
文章图片

怎样直接从JVM内查找某个类的实例？
vmtool 利用 JVMTI接口，实现查询内存对象，强制GC等功能。
[arthas@17396]$ vmtool -action getInstances --className java.lang.String --limit 10 @String[][ @String[sun/nio/ch/FileDispatcherImpl], @String[sun/nio/ch/FileDispatcherImpl], @String[sun/nio/ch/FileDispatcher], @String[sun/nio/ch/FileDispatcher], @String[sun/nio/ch/FileDispatcher], @String[direct], @String[sun/nio/ch/FileChannelImpl$Unmapper], @String[sun/nio/ch/FileChannelImpl$Unmapper], @String[sun/nio/ch/FileChannelImpl$Unmapper], @String[sun/nio/ch/FileDispatcherImpl], ]

通过 --limit参数，可以限制返回值数量，避免获取超大数据时对JVM造成压力。默认值是10。
怎样定位慢调用方法。
trace 展示方法内部调用路径，并输出方法路径上的每个节点上耗时
[arthas@18584]$ trace com.example.arthas.ArthasTest bridge Press Q or Ctrl+C to abort. Affect(class count: 1 , method count: 1) cost in 137 ms, listenerId: 1 `---ts=2021-08-06 10:30:11; thread_name=main; id=1; is_daemon=false; priority=5; TCCL=sun.misc.Launcher$AppClassLoader@18b4aac2 `---[1011.4579ms] com.example.arthas.ArthasTest:bridge() `---[1009.9123ms] com.example.arthas.ArthasTest:put() #13`---ts=2021-08-06 10:30:12; thread_name=main; id=1; is_daemon=false; priority=5; TCCL=sun.misc.Launcher$AppClassLoader@18b4aac2 `---[1002.9228ms] com.example.arthas.ArthasTest:bridge() `---[1002.8016ms] com.example.arthas.ArthasTest:put() #13

从以上信息钟可以看到 bridge方法调用1011.4579ms 其中1009.9123ms是在调用put方法，那我们重点就可以对put方法进行分析，如有必要也可以对put方法进行trace命令追踪。
以上结合了自己的理解，使用arthas命令排查之前提出的问题，arthas提供了丰富的命令功能，想要了解更多的使用方式，请参考命令列表
参考文档
【线上问题排查神器入门——Arthas】Arthas用户文档

    推荐阅读


    上一篇：「Spring认证」Spring环境设置

    下一篇：利用Python判断你的密码难度等级