线上问题定位分析宝典-Arthas篇

1 Arthas介绍

Arthas 是一款线上监控诊断产品，通过全局视角实时查看应用 load、内存、gc、线程的状态信息，并能在不修改应用代码的情况下，对业务问题进行诊断，包括查看方法调用的出入参、异常，监测方法执行耗时，类加载信息等，大大提升线上问题排查效率。

Arthas 用户文档：https://arthas.aliyun.com/doc/

对于如何使用Arthas官方文档做得非常详细，本篇主要内容概要：

1. 对Arthas命令按作用对象进行了分类
2. 对于典型故障场景，分享如何使用Arthas查找问题原因并使用Arthas救火。
3. 分享如何使用arthas获取Spring context容器并获取项目中的bean。
4. 最后分享实例即将OOM时，如何使用Arthas清理无用的全局对象，以避免OOM。

 

2 常用命令归类

arthas有40多个工具命令，下面列出的是处理问题常用的工具

 

2.1 线程(thread)

thread命令局限性：

1. 不能一次打印全部线程的stack，对于waitting状态的异常线程需要逐一查看堆栈。解决办法是使用jdk的jstack命令。

2.2 方法相关

ognl表达式内置对象和变量：target、params、returnObj、throwExp、isThrow、#cost

2.3 类相关常用命令

2.4 其它常用命令

3 典型业务故障分析

1. cpu负载高问题如何定位原因？

2. 接口耗时飙升如何定位原因？

3. 接口异常如何定位数据不正确的原因？

3.1 CPU负载高问题定位

3.1.1 问题定位思路

在流量不大的情况下，cpu负载高可能是因为循环次数非常大甚至死循环

1. 找到耗CPU高的进程

2. 找到进程内耗CPU高的线程

3. 找到线程内耗CPU高的代码行

通常做法

#找到占CPU大的进程
top 
#找到占CPU高的线程
top -p 进程号 -H 
#将线程ID转换为16进制
printf "%x\n" tid 
jstack pid | grep 16进制tid #打印线程堆栈

3.1.2 Arthas如何定位？

#查看占用CPU比较大的前10个线程
thread -n 10 
#查看指定id号的线程堆栈，找到问题代码行
thread id 
#查看源码，如果没有源码，反编译指定方法
jad com.xx.yy.zz.Class1 method 1

 

3.1.3 跳出死循环

问题：在不能立马上线的情况下，如何立马解决死循环？

1. 如果循环内有sleep/wait/await等阻塞方法，可通过循环内watch某个方法，在ognl表达式中获取线程实例并执行interrupt方法

watch com.xx.arthas.Demo1 run '@java.lang.Thread@currentThread().interrupt()' -n 1

1. 使用ognl表达式修改对象属性值以满足循环终止条件

2. 使用ognl表达式修改对象属性值以便往循环外抛出异常

3. 没法终止线程，可通过循环内watch某个方法，在ognl表达式中使线程休眠让出CPU

watch com.xx.arthas.Demo1 run '@java.lang.Thread@sleep(20000)' -b &

3.2 接口耗时飙升问题定位

3.2.1 根因典型场景

1. CPU负载高（定位方法上面提过）

2. 网络流量大、延迟

3. 磁盘负载

4. 远程方法调用耗时

5. 数据库访问耗时

6. 粗粒度的线程同步块

7. 程序执行步骤多，时间复杂度高

8. 数据量大处理速度慢

9. 与高耗时的任务共用线程池资源

10. 连接池小或者连接对象放回连接池时间延迟

3.2.2 问题定位思路

1. 排除硬件环境因素，如CPU、磁盘、网络、内存。（top\free\dstat命令）

2. 排除数据库(mysql/redis/ES等)性能问题（数据库监控）

3. 排除第三方接口耗时

4. 排查内部接口耗时

5. 检查代码逻辑

痛点，上面排查过程，耗时也非常长，如果每步平均要2分钟，定位一个问题也要10分钟左右，如果有一个很快排除其它因素而定位到问题原因或者方向的工具就太好了，而使用arthas可以勉强做到。

3.2.3 Arthas使用

1. 启动arthas

2. 执行dashboard命令查看有无占CPU高的线程、内存、gc情况

3. 从问题方法开始，逐层从耗时高的方法节点使用trace命令，最终找到耗时高的外部接口或内部方法

#查看jvm实时状况
dashboard 
 
#追踪耗时100ms以上的请求，在方法中哪一步执行比较耗时
trace com.xx.Class1 method1 '#cost>100' 
 
#重复第一步逐层追踪，也可以用下面正则表达式同时追踪多个方法
trace -E com.xx.Class1|com.yy.Class2|...|Classn   method1|method2|...|methodn '#cost>100'

辅助命令：

stack: 查看问题方法的调用栈，用于回溯问题方法被调用的源头，定位方法参数的传输路径

watch: 查看问题方法执行的参数、返回值，用于定位数据量大造成方法处理时间长、网络传输慢

jad: 反编译源代码查看代码逻辑

 

技巧：

trace的过程借助源代码分析进行，避免不必要的trace操作，以免耽误更多时间

 

3.1.4 内部接口耗时飙升

典型原因

1. 数据量大，造成循环次数过多

2. 粗粒度的线程同步块，锁竞争

3. wait/sleep等阻塞方法时间长

问题分析思路

1. 查看方法入参和调用者对象信息

2. 查看代码源码

Arthas使用

以上原因都可以用下面命令排查

#查看jvm实时状况
dashboard 
#追踪耗时100ms以上的请求，在方法中哪一步执行比较耗时
trace com.xx.Class1 method1 '#cost>100' 
#重复第一步逐层追踪，也可以用下面正则表达式同时追踪多个方法
trace -E com.xx.Class1|com.yy.Class2|...|Classn   method1|method2|...|methodn '#cost>100'

3.1.6 Mysql查询超时

典型原因

1. SQL中没有使用索引

2. 请求数据量大

3. 连接池连接获取延迟

分析思路

1. 查看SQL

2. 查看mysql返回数据量大小

3. 连接获取耗时高时查看连接池信息

4. 连接获取耗时高时查看追踪方法耗时点

Arthas使用

#查看SQL
watch java.sql.Statement execute* '{params, target}' -x 3 '#cost>50'
 
#追踪耗时超过20ms时，获取连接的执行步骤中哪一步耗时高
trace javax.sql.DataSource getConnection '#cost>20' 

 

3.3 流程逻辑异常分析

3.3.1 不能定位到抛出异常的代码点在哪里

原因：没有异常栈信息，不能定位问题

Arthas使用

trace com.xx.Class1 method1

1. 通过trace命令就可以看到方法内部执行了哪些行的代码

2. 结合源代码查看哪一步没有执行，那么异常就在上一步中抛出

3. 找到异常点，分析异常原因

 

3.3.2 异常原因定位

异常发生，堆栈也有。如果找不到异常点，看上一节。由于参数不正确造成异常，那么如何找到造成参数不正确的原因呢？

典型原因

1. 源头传入的参数就不正确

2. 方法在执行流程中更改了数据

3. 全局状态在某个异常时被更改，而异常点不明且不能复现。正常流程获取不到正确的状态而抛异常。

4. jar包冲突

5. jar包版本问题

Arthas使用

#查看源头方法参数
watch com.xx.Class1 method1 params -x 3 
#查看哪个地方修改了方法
stack com.xx.Class2 setMethod2 
sc -d com.xx.Class1

4 其他场景技巧

4.1 获取SpingContext

获取方法

1. 从dubbo中获取

ognl '#c = @org.apache.dubbo.config.spring.extension.SpringExtensionFactory@CONTEXTS.iterator().next(),#c.getBean("beanName")' -c 6bb489f8 

1. Spring mvc使用tt命令获取(需要触发一条http请求)

tt -t org.springframework.web.servlet.DispatcherServlet doService -n 1
tt -i 1000 -w '#c=target.webApplicationContext, #c.getBean("beanName")'

适用场景

1. 查看某个bean是否被正确初始化，比如查看参数是否正确

2. 想要手动触发某个bean的方法来处理线上问题

3. 想要复现线上问题

4.2 查看异常调用栈

无异常堆栈时，如何查看调用堆栈？

watch demo.MathGame primeFactors "{params, throwExp, @java.lang.Thread@currentThread().getStackTrace()}"  -x 2 -e

 

4.3 调整日志级别

logger -n com.xx -l info -c 6bb489f8

注意，

  1. 建议指定-c参数，即类加载器的hash值

  2. 生产上修改日志级别后，别忘了调整回来

4.4 OOM

典型原因

1. jvm内存设置太小

2. 创建对象的速度大于垃圾回收的速度

3. 代码问题，有大量本应该释放引用的对象没被释放，这样的对象随着时间的增长而增长，而GC不掉，最终OOM。

处理方式

针对第3个问题，dump出jvm内存数据进行分析，找到那些无用的对象的持有者，比如是一个静态Map实例，可使用ognl表达式清除map中的数据，以便可以GC掉，如

ognl '@com.xx.Class1@staticMap.clear()'

也可以用watch命令在后台按照一定条件清理，如

watch com.xx.Class1 method '@com.xx.Class1@staticMap.size()>1000&& @com.xx.Class1@staticMap.clear()' &

5. 总结

1. mc、redefine：mc组合rdefine可以对代码进行热更新，不满足生产运行管理规范要求。
2. JVM内存不足，arthas挂上去可能导致系统崩溃；
3. 用完Arthas一定要执行stop清除arthas在应用中加载的类和对象，session掉了也要重新连接后stop；