上周组内同事反应某应用的一个对外交互的接口当天早晨开始调用总是超时(之前是好的),应用里也没有错误日志,但其他的一些接口又是确定可以工作的。
接到这个问题的第一反应,去看了下那个接口干了什么事情:
- 有没有调用第三方接口的地方
- 有没有死锁嫌疑代码
- 如果有和数据库交互,看下数据库有没有问题
- ……
代码静态分析下来,这个接口没有上面说的任何一种问题。
这样看来,不得不请出jvm工具来分析一下了,而现在的问题是应用无响应,很明显要dump出应用的栈信息来分析一下。
本文主要记录问题解决的过程而不是纯理论。理论dump jvm 栈信息相关的介绍参考 java 并发死锁产生原因与诊断
jdk 下载
我们的应用是通过docker 的容器里的,基础镜像为了精简,运行时只有jre没有jdk,所以,先下一个jdk(此处在官网找解压即用的jdk版本),并解压。
1 | docker exec -it <container id> /bin/bash |
查找进程id
找到应用的进程号1
ps -ef | grep <key word>
dump 栈信息
进入jdk的bin目录:1
./jstack -l <应用进程号> >> /tmp/xxx.txt
下载栈信息文件到pc
1 | sz /tmp/xxx.txt |
分析
栈文件中记录jvm当前(dump)时各个线程的状态(等待,运行…),打开栈文件后发现有很多线程是waiting状态(业务代码栈已忽略):1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19"http-nio-xxx-exec-3" #33 daemon prio=5 os_prio=0 tid=0x00007f95943d9800 nid=0x54 waiting on condition [0x00007f954a35a000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000fb7aed78> (a java.util.concurrent.locks.ReentrantLock$FairSync)
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$FairSync.lock(ReentrantLock.java:224)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:210)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
at ch.qos.logback.classic.Logger.info(Logger.java:579)
有n多个线程都是waiting状态(线程执行了wait方法,等待其他线程发送notify信号才能唤醒),此处是找到两个信息的:
- parking to wait for <0x00000000fb7aed78>,不止是我贴出来的这根线程在等待0x00000000fb7aed78,还有其他很多线程都在等待0x00000000fb7aed78, 这个表示线程在等待这个条件来唤醒自己。0x00000000fb7aed78>
- 从栈信息看,在应用层,线程是卡在日志输出上了。
现在基本可以推测出是io除了问题。
接着分析,这个0x00000000fb7aed78是个什么东西?全局搜索栈文件,发现有一个应用线程是runnable状态(业务代码栈已忽略):1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26"http-nio-xxx-exec-2" #32 daemon prio=5 os_prio=0 tid=0x00007f95943d8000 nid=0x53 runnable [0x00007f954a45b000]
java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:326)
at java.io.BufferedOutputStream.write(BufferedOutputStream.java:122)
- locked <0x00000000f8e176b8> (a java.io.BufferedOutputStream)
at java.io.PrintStream.write(PrintStream.java:480)
- locked <0x00000000f8d698b8> (a java.io.PrintStream)
at java.io.FilterOutputStream.write(FilterOutputStream.java:97)
at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:172)
at ch.qos.logback.core.joran.spi.ConsoleTarget$1.write(ConsoleTarget.java:37)
at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:131)
at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:187)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:212)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
at ch.qos.logback.classic.Logger.info(Logger.java:579)
……
Locked ownable synchronizers:
- <0x00000000f954c7f0> (a java.util.concurrent.ThreadPoolExecutor$Worker)
- <0x00000000fb7aed78> (a java.util.concurrent.locks.ReentrantLock$FairSync)
线程的runnable状态,表示线程cpu的时间片用完了,等待cpu时间片。
仔细看线程栈信息发现线程堆两个地址持有了两个锁:
- 0x00000000f954c7f0
- 0x00000000fb7aed78
其中0x00000000fb7aed78更是其他线程正在等待的地址:1
parking to wait for <0x00000000fb7aed78>
说明其他那些处于waiting状态的线程都在等待http-nio-xxx-exec-2线程的信号。而http-nio-xxx-exec-2在干什么呢?
如最后一条栈信息所示1
java.io.FileOutputStream.writeBytes
也是在做io操作。再往上层栈去看,就是在写日志。与其他线程一样,http-nio-xxx-exec-2的应用代码在写日志,底层即是做io操作,写之前这根线程获得了锁0x00000000fb7aed78,所以其他线程在等待他日志书写的结束。
此处的理论基础是线程栈分析,可以参考博客怎么分析线程栈
栈信息分析神器推荐
上面的分析过程其实有一个专业的网站可以帮忙做,就是FAST THREAD,只需要把栈文件上传,即有图形化的分析结果(强烈推荐,墙裂推荐,貌似要翻墙才能用)。fast thread的分析结果与我之前人肉分析的结果是一致的。
盖棺定论
基于上面的结论,分析了http-nio-xxx-exec-2的应用栈信息,上层业务代码栈可以看到是哪些些业务代码引起(上面的栈信息里为了刻意省略了业务代码栈部分,毕竟是公司内部代码),分析了下业务代码的io量,是在写日志,其实是不大的。
把分析结果和组里同事沟通了一下,有一个同事反应当天早晨他执行了一个docker log命令来拉取容器日志,而且没有加–tail限制行数,所以问题的元凶就找到了。(此处本该基于现场进一步确认是不是因为docker log那个进程占用了所有的io的,可是当时没想那么多… )
此处提一句,docker 的json-file日志引擎本身就是不推荐生产环境使用的。
问题解答
- 程序为什么无响应: os的io被占满了
- 为什么只有个别接口卡: 只有个别接口需要写日志,需要排队等待io资源
再加一句,分布式系统下,监控真的很重要,如果这台机器有io资源方面的监控预警,我们就能提前收到预警邮件,就能为我们排查问题提供重要的线索。
广告
我们部门研发的私有云产品就有监控&预警功能,可以大大的降低运维成本,像上面的案例,如果上了我们的平台,即使没有能力去分析这些也可以快速定位。
ps:为什么上面的案例没有监控的影子,因为这是我们开发环境,监控没配全…
此类问题本地调试办法
上面所说的是针对线上环境的栈分析手段(通过jstack),如果是本地有环境可以重现问题,那有更快捷的调试办法。
现在idea或eclipse都有类似的调试手段,下面简单已idea为例做一个演示。
比如有下面一段代码1
2
3public static void main(String args[]) throws InterruptedException {
TimeUnit.SECONDS.sleep(100);
}
这段代码模拟程序运行起来后卡住的效果我以debug模式启动,程序卡住不退出(假设我不知道程序里写了什么),下面要分析原因:
进入debug模式后,点击“暂停”按钮,如下图可见目前运行的所有线程,根据线程状态找出怀疑有问题的线程:
很明显那个sleep的线程有问题,选择此线程,展示栈列表:
找到应用代码栈,直接双击,直接定位到源代码。
当然这只是最简单的例子,如果因为加锁顺序不一致引起的死锁,或者资源问题引起的资源死锁,获取其他复杂的情况,排查过程还是要靠细心分析,此处只介绍工具使用。
ps:eclipse也有类似的功能,也是在debug模式,点击一个叫suspend的按钮去做类似的分析,具体不截图了,电脑里没eclipse。