【Arthas】定位高并发问题
一个web服务，压测会报大量500错误，且稳定复现。我们已经定位到是登录拦截器LoginFilter的问题
安装arthas
首先要先把arthas打到镜像里，这里公司内网可以使用离线安装方式，下载完整安装包arthas-packaging-3.6.9-bin.zip。解压后放在arthas目录下，对应的dockerfile如下
FROM xx:xx
COPY arthas/ /arthas
RUN cd /arthas && ./install-local.sh
dashboard
image.png
可看占用CPU的主要是tomcat的http服务，这里压测已经开始出现500fail了，截图如下:
image.png
这里我们随便找一个thread id，使用thread {id}命令查看线程运行栈，多运行几次找到LoginFilter相关的调用栈：
image.png
这样就可以轻松知道要重点排查那些方法了。接下来我们先看LoginFilter是否会抛异常
watch xx.LoginFilter doFilter 'throwExp' -e -x 3
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 248 ms, listenerId: 2
method=xx.LoginFilter.doFilter location=AtExceptionExit
ts=2023-05-24 14:07:54; [cost=9.044077ms] result=java.lang.NullPointerException
这里看到报空指针了，但是没有异常栈，没法分析，接着在调用栈往上找，发现AuthorizeDealBeanImpl.isValid报出异常：java.lang.NullPointerException: Cannot invoke “java.util.Map.getOrDefault(Object, Object)” because the return value of “xx.UserInfo.getDept()” is null
至此问题已经定位了，接下来就要对照源码了
问题定位
核心代码：
List<UserInfo> userInfos = this.cache.get(token + ":USER", UserInfo.class, permission.getUserInfoUrl(), permission.getIsRisk());
if (!CollectionUtils.isEmpty(userInfos)) {
UserInfo userInfo = (UserInfo)userInfos.get(0);
if (userInfo != null && !StringUtils.isEmpty(userInfo.getId())) {
// xxx
loginUserInfo.setDepartmentName(userInfo.getDept().getOrDefault("name", " ").toString());
// xxx
}
}
我们看到是userinfo.getDept()报出的空指针，接下来重点来了，我们再用watch方法观察cache.get的返回值，但是这此我们要加上一些比较巧妙的过滤条件：
watch xxx.LocalUserRoleCacheImpl get '{params[0],params[2],target.url,returnObj[0]}' "params[1].getName().contains('UserInfo') && returnObj[0].getDept()==null" -x 3
得到结果如下：
image.png
这里我们发现get方法返回的对象属性都是空的，为什么会出现这种情况呢，这种应该是不可能出现的，因为缓存数据是正常的。我们再来看下LocalUserRoleCaheImpl.get的代码
public List<T> get(K key, Class<T> clz, String url, Boolean isRisk) {
this.url = url;
try {
String result = this.loadCache(key);
return JSONObject.parseArray(result, clz);
} catch (Exception var6) {
log.error(var6.getMessage(), var6);
return null;
}
}
原来是get方法里设置了url这个类属性，然后loadCache方法里会利用这个url类属性去远端请求数据，至此一切真像大白，回看上面我们watch的变量：param[2]是get方法的url入参，而target.url是类的url属性，这两者会出现不一致的情况！
定位死锁
模拟死锁场景
public class Deadlock {
private static Object obj1 = new Object();
private static Object obj2 = new Object();
public static void main(String[] args) {
new Thread(() -> {
System.out.println("线程1执行");
synchronized (obj1) {
try {
TimeUnit.SECONDS.sleep(1);
} catch (InterruptedException e) {
e.printStackTrace();
}
synchronized (obj2) {
}
}
}, "t1").start();
new Thread(() -> {
System.out.println("线程2执行");
synchronized (obj2) {
synchronized (obj1) {
}
}
}, "t2").start();
System.out.println("执行完毕");
}
}
通过thread命令定位
1，直接使用”thread“命令，输出线程统计信息。其中：BLOCKED 表示目前阻塞的线程数。
[arthas@11596]$ thread
Threads Total: 26, NEW: 0, RUNNABLE: 8, BLOCKED: 2, WAITING: 4, TIMED_WAITING: 2, TERMINATED: 0, Internal threads: 10
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIM TIME INTERRUPT DAEMON
2 Reference Handler system 10 WAITING 0.0 0.000 0:0.000 false true
3 Finalizer system 8 WAITING 0.0 0.000 0:0.000 false true
4 Signal Dispatcher system 9 RUNNABLE 0.0 0.000 0:0.000 false true
5 Attach Listener system 5 RUNNABLE 0.0 0.000 0:0.031 false true
14 arthas-timer system 5 WAITING 0.0 0.000 0:0.015 false true
17 arthas-NettyHttpTelnetBootstr system 5 RUNNABLE 0.0 0.000 0:0.015 false true
18 arthas-NettyWebsocketTtyBoots system 5 RUNNABLE 0.0 0.000 0:0.015 false true
19 arthas-NettyWebsocketTtyBoots system 5 RUNNABLE 0.0 0.000 0:0.015 false true
20 arthas-shell-server system 5 TIMED_WA 0.0 0.000 0:0.000 false true
21 arthas-session-manager system 5 TIMED_WA 0.0 0.000 0:0.000 false true
22 arthas-UserStat system 5 WAITING 0.0 0.000 0:0.000 false true
24 arthas-NettyHttpTelnetBootstr system 5 RUNNABLE 0.0 0.000 0:0.109 false true
25 arthas-command-execute system 5 RUNNABLE 0.0 0.000 0:0.015 false true
10 t1 main 5 BLOCKED 0.0 0.000 0:0.000 false false
11 t2 main 5 BLOCKED 0.0 0.000 0:0.000 false false
12 DestroyJavaVM main 5 RUNNABLE 0.0 0.000 0:0.156 false false
2，执行“thread -b”命令，找出当前阻塞其他线程的线程，即造成死锁的罪魁祸首
[arthas@11596]$ thread -b
"t1" Id=10 BLOCKED on java.lang.Object@26dee7d7 owned by "t2" Id=11
at test.Deadlock.lambda$main$0(Deadlock.java:24)
- blocked on java.lang.Object@26dee7d7
- locked java.lang.Object@13a631ce <---- but blocks 1 other threads!
at test.Deadlock$$Lambda$1/250421012.run(Unknown Source)
at java.lang.Thread.run(Thread.java:748)
注：上面这个命令直接输出了 造成死锁的线程ID，和具体的代码位置，以及当前线程一共阻塞的线程数量：“<—- but blocks 1 other threads!“。
3，其他线程命令：
thread –all, 显示所有的线程；
thread id, 显示指定线程的运行堆栈；
thread –state：查看指定状态的线程，如：thread –state BLOCKED；
thread -n 3：展示当前最忙的前N个线程并打印堆栈；
