cover_image

线上问题排查利器Arthas

李建迎 新东方技术
2020年09月14日 02:33
前言

作为一名开发,最头疼最担心的莫过于生产环境出问题了。生产无小事,一出问题,轻则影响用户体验,造成客诉,重则造成公司资损,后果严重。

当然,上线前如何充分测试,线上出问题之后如何快速止血这些不在本文介绍范围之内,本文主要介绍如何快速定位问题。线上问题复杂多样,CPU飙升、RT突增、内存不足、性能下降等等,如何才能在最短时间内定位到问题呢?下面就来安利这款线上问题定位神器:Arthas。


简介

Arthas是一款阿里开源的Java诊断工具,对业务代码无侵入,功能强悍,安装简单,上手快,深受Java开发者喜爱。文档见:https://arthas.aliyun.com/doc

不过纸上得来终觉浅,本文就通过几个场景,结合自己写的简单demo,让大家一起领略下Arthas的魅力。


场景一

项目A上线完成,功能一切正常,观察半小时后准备打卡下班,刚下楼,报警短信来了,一看是CPU报警,CPU使用率300%,心凉了半截,火速跑回工位……

其实如果是代码问题,利用Linux和JVM的原生命令,也可以定位,具体方式见:https://blog.csdn.net/qq_22978533/article/details/80459407。博主用了一篇文章的篇幅来介绍如何定位,那如果是交给Arthas来做呢?一行命令!下面通过一个demo来看一下。

死循环往一个map里面put数据,造成CPU飙升:

static void testCPU(){
while (true){
for(int i=0;i<10000;i++){
HOLDER.put(i,i);
}
HOLDER.clear();
}
}

Arthas定位:

[arthas@27969]$ thread -n 3
"main" Id=1 cpuUsage=99% RUNNABLE
at java.util.concurrent.ConcurrentHashMap.clear(ConcurrentHashMap.java:1206)
at com.ljy.test.arthas.demo.CPUDemo.testCPU(CPUDemo.java:27)
at com.ljy.test.arthas.demo.CPUDemo.main(CPUDemo.java:55)

可以直接定位到出问题的类及代码行,是不是很简单?接下来再看一个因为死锁造成的CPU飚高问题:

static void testDeadLock(){
new Thread(()->{
LOCK1.lock();
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
e.printStackTrace();
}
LOCK2.lock();
}).start();

new Thread(()->{
LOCK2.lock();
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
e.printStackTrace();
}
LOCK1.lock();
}).start();
}

同样,一行命令找到死锁位置:

 [arthas@28004]$ thread -b
"Thread-0" Id=11 WAITING on java.util.concurrent.locks.ReentrantLock$NonfairSync@4bcf34d owned by "Thread-1" Id=12
at sun.misc.Unsafe.park(Native Method)
- waiting on java.util.concurrent.locks.ReentrantLock$NonfairSync@4bcf34d
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
at com.ljy.test.arthas.demo.CPUDemo.lambda$testDeadLock$0(CPUDemo.java:39)
at com.ljy.test.arthas.demo.CPUDemo$$Lambda$1/769287236.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)

Number of locked synchronizers = 1
- java.util.concurrent.locks.ReentrantLock$NonfairSync@6b008751 <---- but blocks 1 other threads!


场景二

小A花了一周的时间,终于把一个大需求开发完了,并且在本机上测试通过,长长的出了一口气,吹起口哨,准备部署到测试环境提测,多么美好的一天。提交代码,打包部署,几分钟后,部署完成,测一下刚才没问题的功能点吧,然后,嗯?找不到类?找不到方法?明明刚测过的啊,我是谁?我在那?……

通常这种情况,我们都会想到可能是代码分支的问题,有可能部署了错误的分支,也有可能你刚提交完代码,同事也在同一个分支上提交了代码,影响了之前的功能,除此之外,下面一些情况应该也是很多开发同学遇到过的:

• 项目应用了很多第三方jar包,这些jar包里面有一些类命或者方法名是重复的,引用的jar包跟实际需要引用的jar包不一致。例如StringUtils

• jar包版本冲突问题

• 因为手速太快,类名或者方法名少/多打了一个字母,肉眼排查过程痛不欲生

这类怎么确定呢?来看Arthas的sc-d(Search Class)、sm(Search Method)、jad(Java Decompile)三连击快速定位问题。

想知道一个类有没有真正的加载到jvm中,可以用sc命令,效果如下:

[arthas@30314]$ sc com.ljy.test.util.DemoUtils
com.ljy.test.util.DemoUtils
Affect(row-cnt:1) cost in 6 ms.

[arthas@30314]$
sc com.ljy.test.util.DemoUtil
Affect(row-cnt:0) cost in 5 ms.

悄悄的告诉你,arthas是支持正则表达式的,对于像我这种不爱记包名的懒人,无疑是个好消息,对于上面的例子,用下面的方式也是一样的效果:

[arthas@30314]$ sc *DemoUtils
com.ljy.test.util.DemoUtils
Affect(row-cnt:1) cost in 9 ms.

同样这个参数,加上一个-d选项,就是排查定位jar包问题的利器,可以直接定位到是从哪个jar包加载进来的:

[arthas@30651]$ sc -d org.apache.commons.lang3.StringUtils
class-info org.apache.commons.lang3.StringUtils
code-source /xxx/repository/org/apache/commons/commons-lang3/3.10/commons-lang3-3.10.jar

smsc是类似的,只需要在sc的基础上,在后面加上需要查找的方法名即可,这里不再赘述。

接下来就是定位线上环境中,运行效果与预期不符的问题了,也就是证明正在跑的代码,是“我认为应该”跑的代码,用jad命令,直接展示效果:

[arthas@30651]$ jad *DemoUtils

ClassLoader:
+-sun.misc.Launcher$AppClassLoader@18b4aac2
+-sun.misc.Launcher$ExtClassLoader@6344b56e

Location:
/Users/lijianying/sourcecodes/daily_test/target/classes/

/*
* Decompiled with CFR.
*/
package com.ljy.test.util;

import java.io.IOException;
import org.apache.commons.lang3.StringUtils;

public class DemoUtils {
void methodA() {
}

void methodB() {
}

void methodc() {
}
}

类加载器、类所在位置、类的内容一目了然,线上跑的就是这些代码,如果与预期不符,就检查一下自己改动的代码是否跟反编译出来的代码一致,快速定位到分支冲突。


场景三

一个项目B上线完成,小组组织团建,大家正在吃着火锅唱着歌,突然客服妹子来电话了,说一个客户投诉好几次了,下单失败,重试多次都不行,请尽快解决。瞬间感觉酒杯里的酒都不香了……好在客诉只有一个用户,没有大面积故障,应该是这个用户触发了某个BUG。放下酒杯,拿出电脑,连上WIFI开始排查问题。

这类问题还是比较棘手的,常规排查方法有三种,如果问题可以在测试环境或者本地复现,可以debug还好一些,但是通常测试数据跟线上还是有区别的,该方法不一定能奏效。另一种办法就是线上debug,不过该方法存在如下问题:一来线上环境一般是数台机器,不能确定有问题的请求打到哪台机器上,效率较低,二来会阻塞其他正常请求,因此强烈建议不要在生产环境使用线上Debug方式排查问题。再有一种方法,就是修改代码,在可能出问题的地方加日志,重新发布一台线上机器定位问题,定位到之后再改代码重新上线,无疑也是效率低下的。

下面介绍一下Arthas提供的强大的观察类在运行时情况的命令:watch,该命令可以实时观察方法的出入参以及异常情况,而且可以支持OGNL表达式,方便根据出问题的参数精准的定位问题。用以下demo模拟上述场景,即只在特殊情况下触发问题:

public class TroubleShootDemo {
private static final String[] ARR = new String[]{"a","b","c","d","e"};

/**
* 模拟特定参数的时候才会触发的逻辑
* @param param
* @return
*/

private static String invoke(String param){
if("a".equals(param)){
return "success";
}
return "failed";
}

public static void main(String[] args) throws InterruptedException {
while (true){
//模拟小概率出现
int index = RandomUtils.nextInt(0,1000);
if(index<5){
invoke(ARR[index]);
}
Thread.sleep(1);
}
}
}

我们先来看一下正常观察出入参的用法:

[arthas@31318]$ watch *TroubleShootDemo invoke "{params,returnObj}" -x 2
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 32 ms, listenerId: 2
ts=2020-08-18 17:23:14; [cost=0.224202ms] result=@ArrayList[
@Object[][
@String[b],
],
@String[failed],
]
ts=2020-08-18 17:23:15; [cost=0.142852ms] result=@ArrayList[
@Object[][
@String[c],
],
@String[failed],
]
ts=2020-08-18 17:23:15; [cost=0.127154ms] result=@ArrayList[
@Object[][
@String[d],
],
@String[failed],
]
ts=2020-08-18 17:23:15; [cost=0.132717ms] result=@ArrayList[
@Object[][
@String[a],
],
@String[success],
]

可以很清楚的看到TroubleShootDemo类的invoke方法,每次调用的出入参情况,其中 -x 2 表示展示出入参的层次为2层。当然生产环境下直接这么用是不行的,请求量大,刷新太快,需要用OGNL表达式对制定参数做过滤,方便更精准的定位问题:

[arthas@1318]$ watch *TroubleShootDemo invoke "{params,returnObj}" 'params[0]=="a"' -x 2
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 32 ms, listenerId: 3
ts=2020-08-18 18:41:04; [cost=0.078229ms] result=@ArrayList[
@Object[][
@String[a],
],
@String[success],
]
ts=2020-08-18 18:41:06; [cost=0.115137ms] result=@ArrayList[
@Object[][
@String[a],
],
@String[success],
]

这样就能清楚的看到指定参数的请求,出入参及异常时候的真实状况,可以快速判断是不是该方法造成的线上问题。


场景四

一个项目C上线了半年多了,支撑了大量的业务,运行一直很稳定,没出过任何线上事故,可是最近几周,随着这个项目的日益火爆,里面几个接口的请求速度越来越慢,高峰期有时候的响应速度都快达到2秒,这样下去再过几天就要出大事了,得赶紧排查一下为毛慢了这么多。
可是从哪里下手呢?是新上线的改动造成的么?还是请求量大了导致fullGC增多?或者是数据量太大了数据库扛不住了?又或者是代码里面调用的第三方服务出了问题?顿时陷入了沉思……

这应该算是性能优化的范畴了,Arthas提供了trace这个强大的命令,能够迅速的定位到影响性能的元凶。以下demo模拟了业务代码中多个方法调用,其中一个方法调用耗时较长:

public class ArthasDemo {

void methodA() throws InterruptedException {
Thread.sleep(20);
}

void methodB() throws InterruptedException {
Thread.sleep(50);
}

void methodC() throws InterruptedException {
Thread.sleep(1000);
}

void invoke() throws InterruptedException {
methodB();
methodC();
methodA();
}
}

trace之后,可以直接定位到每个方法的耗时,其中耗时较长的方法会红色标注,这样一眼就定位到到底是哪个方法在“拖后腿”,之后就可以进行有针对性的优化,以提升性能。

[arthas@1638]$ trace *ArthasDemo invoke
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 50 ms, listenerId: 2
`---ts=2020-08-18 19:44:36;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@18b4aac2
`---[1079.223985ms] com.ljy.test.util.ArthasDemo:invoke()
+---[52.155584ms] com.ljy.test.util.ArthasDemo:methodB() #25
+---[1002.240458ms] com.ljy.test.util.ArthasDemo:methodC() #26
`---[21.386992ms] com.ljy.test.util.ArthasDemo:methodA() #27

该命令也是支持OGNL表达式的,比如我们想只查看耗时超过10ms的方法:

[arthas@1692]$ trace com.ljy.test.util.ArthasDemo invoke #cost>10
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 90 ms, listenerId: 2
`---ts=2020-08-18 19:53:19;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@18b4aac2
`---[1082.629181ms] com.ljy.test.util.ArthasDemo:invoke()
+---[54.860407ms] com.ljy.test.util.ArthasDemo:methodB() #23
+---[1003.365012ms] com.ljy.test.util.ArthasDemo:methodC() #24
`---[23.094037ms] com.ljy.test.util.ArthasDemo:methodA() #25


场景五

公司筹备了半年的一场大促还有10分钟就要开始了,就在这时发现了一行代码BUG,有几率影响到最关键的秒杀活动,几十上百台机器,想修改代码再发布已经来不及了,整个项目组都急的像热锅上的蚂蚁……

这时候就需要祭出Arthas的黑科技redefine,它可以直接替换掉运行时JVM中某个class文件,可谓是给飞驰的赛车换轮胎,下面通过demo来演示一下效果:

public class RedefineDemo {
void method(){
System.out.println("before");
}
}

public class Test {
public static void main(String[] args) throws IOException {
RedefineDemo demo = new RedefineDemo();
demo.method();
System.in.read();
demo.method();
}
}

我们先运行Test中的main方法,打印出的是“before”,System.in.read()将线程挂起,但是jvm不退出。然后我们修改RedefineDemo中的method,改为打印“after”,之后编译该类,得到RedefineDemo.class文件,之后使用redefine命令,将编译得到的class文件,替换掉之前的文件。

[arthas@1849]$ redefine /Users/lijianying/sourcecodes/daily_test/src/main/java/com/ljy/test/arthas/demo/RedefineDemo.class
redefine success, size: 1, classes:
com.ljy.test.arthas.demo.RedefineDemo

接下来就是见证奇迹的时刻了,我们在控制台敲下回车,同样的方法调用,jvm没有停止的前提下,控制台打印出了"after"(这就意味着可以在线上服务不重启的情况下,替换某个类的执行逻辑):

然后开头提到的问题就可以解决了,编写脚本,批量替换掉线上服务器有问题的类文件即可。当然,本demo只是为了掩饰Arthas的强悍,这种方法是极其危险的,替换掉的类不能被恢复,并且存在替换失败的可能。因此,不到万不得已,尽量不要使用该命令。


结语

本文主要介绍了在遇到不同线上问题的时候,如何使用Arthas快速的定位问题,可以简单了解Arthas在CPU问题、代码版本冲突问题、方法实时运行问题、性能优化问题等几个场景的作用,当然文中的demo都是为了展示用法临时写的,真正线上问题可能复杂的多,不过Arthas的合理运用肯定会让诸位在排查问题的时候事半功倍。希望本文能帮助到各位开发小伙伴,后续如果遇到真实的线上案例,也会继续分享给大家。


图片


继续滑动看下一个
新东方技术
向上滑动看下一个