一次应用启动卡死问题排查记录

“卡死”,说的比较口语化,换个视角就有思路了:卡死就是线程阻塞了。

说一下背景,项目都是 Java 应用,容器是 tomcat,应用发布就是 tomcat shutdown,然后 tomcat start,一般看启动日志 catalina.out 能看到启动时 spring ApplicationContext 启动过程中的各种日志,中间件的加载也会输出日志。所以启动卡死,看到的现象就是:打印了几行日志,就不往下继续打印了,应用一直处于不可用状态,直到发布超时。

从线程角度考虑,此时就是线程阻塞住了,就需要知道各个线程是在做什么,找出可疑的线程,顺藤摸瓜,看它在干什么。

一个实例

一直卡住,马上现场定位, 执行ps -ef | grep java 找出 tomcat 进程的 pid,然后执行 jstack [pid],因为 tomcat 是应用程序以 nobody 的身份启动的,所以提示权限不足,联系运维开通权限之后以 root 身份执行即可。

tomcat 发布启动的时候卡住,那就是主线程阻塞了,直接定位到以下线程堆栈:

"main" prio=10 tid=0x00007f99e0012800 nid=0x5246 waiting on condition [0x00007f99e74c5000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000e5a16058> (a java.util.concurrent.CountDownLatch$Sync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:994)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1303)
        at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:236)
        at com.xyz.client.http.domain.PollFuture.get(PollFuture.java:54)
        at com.xyz.client.http.PollWorker.get(PollWorker.java:107)
        - locked <0x00000000e2901da8> (a com.xyz.client.http.PollWorker)
        at com.xyz.client.http.ProjectManager.load(ProjectManager.java:200)

可以看到线程此刻处于 waiting 状态,在等待什么呢?waiting on condition [0x00007f99e74c5000] 条件等待,继续看堆栈,跟 CountDownLatch 有关,继续往栈下层看,com.xyz.client.http.domain.PollFuture.get 就是内部中间件的代码了,证明在 get 的时候阻塞在了 CountDownLatch.await()方法上了。

到这一步,基本可以拿着堆栈找中间件相关的同事定位了,一般还可以找到此时中间件相关的一些日志,注意 ERROR级别的日志,帮助他们更快找到问题。

作为思考,想想为什么阻塞在 await 了?了解 CountDownLatch 的原理就可以想到,一定是某个地方没有执行 latch.countDown() 操作,或者执行的次数不够。看 PollFuture 相关的代码,有如下声明,this.latch = new CountDownLatch(1); 这就更好定位了,证明 countdown 一次没执行成功,搜索执行 countdown 操作的地方,只有一处,如下:

    public void setResult(Object result) {
        this.result = result;
            if(result == null) {
                // no changes
                return;
            }
           // do something
        latch.countDown();
    }

于是可以知道,这里 result == null 成立,往上层继续排查就是了。

最终定位下来,某个极端条件下,setResult() 前一步的请求出错,返回 error 信息,于是处理出来的 result 为空。

另一个例子

上面的例子是启动完全阻塞,永远不会继续。这个例子的现象是 tomcat 启动超时,表现就是断断续续输出日志,部分机器启动能成功,部分不成功,其实也不是完全不会启动,只是超过了timeout = 50000ms的启动超时时长,发布系统就提示启动失败。

一样的思路,重新发布超时的机器,然后登录上去,jstack [pid] 输出若干线程信息,但是只看到有些线程 waiting ,多执行几次命令,又发现有时会继续执行。

联系架构的同事,也是一样的操作,执行若干次命令之后,观察几次输出的差异,看到有个线程会 sleep,这个线程此时的动作是:去远程拿一批服务注册项信息。顺着堆栈信息进一步定位发现,这个是 RPC 框架调用内部另一个组件的接口拿注册项信息,该接口的处理是:获取超时就 sleep 3s,然后再获取,重试 n 次。多番定位之后,升级组件解决问题。

由此可以看出,定位线程阻塞问题,一次输出甚至多次输出可能还不够,对引入的组件代码不熟悉,可能也无法确认问题。熟悉代码的人大致知道哪些地方,哪些后台线程可能阻塞。还有赖于平时多积累,遇到问题多请教。

总结

记得两年前,同事遇到过一次定时任务发布的时候启动卡死的问题,当时直觉可能跟线程死锁有关,不过我们都没有想到怎么入手排查。当时所有排查问题的思路都局限于“看代码”、设置断点、加日志,差别无非是,测试环境可以调试,就靠断点,生产环境要求严格、不能影响服务,所以只能靠日志和代码,总的来说,都局限在自己维护的业务代码中,进了断点,什么都好说,这类不知道怎么加断点的问题,就束手无策。

从线程阻塞类问题可以认识到,有时候要从整个运行时体系去考虑,甚至要从部署结构考虑,转换视角能发现更多问题,也会有更多方法。

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

推荐阅读更多精彩内容

  • 从三月份找实习到现在,面了一些公司,挂了不少,但最终还是拿到小米、百度、阿里、京东、新浪、CVTE、乐视家的研发岗...
    时芥蓝阅读 42,154评论 11 349
  • 一、多线程 说明下线程的状态 java中的线程一共有 5 种状态。 NEW:这种情况指的是,通过 New 关键字创...
    Java旅行者阅读 4,644评论 0 44
  • 爱上他这件事只有自己知道,苦涩也要自己承受。不知道怎么向别人描述这段单恋,即使是最了解我的人。我爱上有婚约的人,爱...
    最佳损友王小鱼儿阅读 298评论 0 0
  • 文/小暮 我们都渴望着外面精彩的世界,因为精彩的生活里总有很多惊喜和意外,谁也不想每天重复单调无聊的生活。 可有时...
    岁月小暮阅读 571评论 0 1
  • 参考上课所讲的内容电商案例,结合自主寻找的和自己经营产品相关的内容,组织一篇上题中的产品的推广文章,字数不限,但需...
    cb6028db333e阅读 153评论 0 0