【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个线程并打印堆栈;

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 203,772评论 6 477
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,458评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 150,610评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,640评论 1 276
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,657评论 5 365
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,590评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,962评论 3 395
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,631评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,870评论 1 297
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,611评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,704评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,386评论 4 319
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,969评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,944评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,179评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 44,742评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,440评论 2 342

推荐阅读更多精彩内容