概述
本文通过定位线上一台机器的线程数异常的定位过程为例,主要展示分析定位同类问题的过程和思路,同时展示个人比较顺手的一些工具,包括阿里的一些内部平台。问题/故障分析的案例往往没有通用性,但是问题分析的思路往往趋同,可以供大家学习和借鉴。
问题描述
2015年5月4日,@欧仲找我帮忙能否定位下线程告警,告警情况如下:
机器名 | 监控项 | 服务状态 | 采集状态 | 持续时间 | 采集时间 |
---|---|---|---|---|---|
sell010179070126.s.et2 | thread_java | warning | 开启 | 5天15小时51分22秒 | 2015-05-04 13:47:40 |
sell010179093166.s.et2 | thread_java | warning | 开启 | 5天4小时29分9秒 | 2015-05-04 13:47:52 |
sell010178232103.s.et2 | thread_java | warning | 开启 | 5天15小时53分28秒 | 2015-05-04 13:47:33 |
sell010179070129.s.et2 | thread_java | warning | 开启 | 5天16小时5分32秒 | 2015-05-04 13:47:30 |
通过Alimonitor网站上告警详情的查看,如下:
问题分析
目标机器分组
可以将后续需要观察和分析的机器分为三组,分组条件为线程数:
- 正常组-线程数500左右,选取一台机器sell010178072163.n.et2
- 异常组1(4台)-线程数700左右,选取两台机器sell010179070126.s.et2、sell010178232103.s.et2_20150505
- 异常组2(1台)-线程数1000左右,目标机器为sell010179093166.s.et2
由于机器名太长不容易记忆,在整个分析过程中容易造成混淆,下面对选取的目标机器取相关的别名
机器别名 | 机器名 | 组名 |
---|---|---|
normal | sell010178072163.n.et2 | 正常组 |
exp1 | sell010179093166.s.et2 | 异常组2 |
exp2 | sell010179070126.s.et2 | 异常组1 |
exp3 | sell010178232103.s.et2 | 异常组1 |
ThreadDump抓取
以其中一台机器(exp1)为例,演示如何抓取ThreadDump,SSH免登录相关配置略去
- 通过ps -ef|grep java,获取目标进程(jboss/tomcat)的PID
- 通过jstack命令生成ThreadDump文件,文件名有一定的规范{host.alias}_td__{host.name}__{yyyyMMdd}_{HHmm}.txt
$sudo -u admin /opt/taobao/java/bin/jstack 25566 >exp1_td_sell010179093166.s.et2_20150508_1443.txt
- 复制ThreadDump文件到本机
#scp ${host.name}:${threaddump.path}
$ scp sell010179093166.s.et2:/home/yunchi.wx/exp1_td_sell010179093166.s.et2_20150508_1443.txt ./Downloads/
ThreadDump分析
这里使用IBM的jca工具来分析ThreadDump,该工具使用起来比较方便,同时也推荐一下ZProfiler平台,可以在线分析ThreadDump、HeapDump等,选取从目标机器上抓取的dump文件
通常情况下做故障分析时我们需要关心Deadlock、Blocked相关线程,不过本次故障主要是线程数量问题,所以对目标机器的线程数目以状态维度进行对比:
机器别名 | Total | Runnable | Waiting on condition | Object.wait() | Blocked |
---|---|---|---|---|---|
normal | 388 | 58 | 211 | 117 | 2 |
exp1 | 924 | 558 | 211 | 152 | 3 |
exp2 | 629 | 72 | 213 | 342 | 2 |
exp3 | 611 | 55 | 210 | 343 | 3 |
其中黑体数字偏离正常值范围,比如exp2的Object.wait()线程数为342
通过数据对比发现,exp1主机上Runnable的线程偏多(5xx/5x),exp2、exp3上Object.wait()状态的线程偏多(3xx/1xx),这时需要查看对应ThreadDump中相应状态的线程,以exp1上的Runnable线程为例
对相关机器上的异常线程与正常机器线程对比数据如下
Thread Name | normal | exp1 | exp2 | exp3 | Description |
---|---|---|---|---|---|
New I/O server boss | 1 | 55 | 1 | 1 | Netty主线程 |
New I/O worker | 9 | 456 | 24 | 9 | Netty worker线程 |
http-0.0.0.0-7001 | 32 | 65 | 256 | 256 | Http线程池线程 |
其中黑体部分表示同类线程数目偏离正常值范围,比如exp1的server boss线程数为55
问题定位
Http线程堆栈
exp2和exp3主机存在http线程比较多的场景,查看线程堆栈没有什么问题
"http-0.0.0.0-7001-36" daemon prio=10 tid=0x00007f633e206000 nid=0x234f8 in Object.wait() [0x00000000587bc000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000007613d1188> (a org.apache.tomcat.util.net.AprEndpoint$Worker)
at java.lang.Object.wait(Object.java:485)
at org.apache.tomcat.util.net.AprEndpoint$Worker.await(AprEndpoint.java:1464)
- locked <0x00000007613d1188> (a org.apache.tomcat.util.net.AprEndpoint$Worker)
at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1489)
at java.lang.Thread.run(Thread.java:662)
分析产生故障的时间点,从Alimonitor网站查询线程增长的时间点,经过相关的定位可以发现在2015-4-28 21:30到2015-4-28 22:30之间,见下图,见图上线程数有一个陡降的过程,通常情况下是因为应用重启
为了进一步确认该进程启动的精确时间,可以使用如下命令,因为通常情况下通过ps只能看到启动日期
$ps -p PID -o lstart
Http线程总数满足web服务器配置的250总数,线程池在达到MaxThreads后不会回收,导致线程一直被占用,此时需要分析相关的流量情况,但是由于主机上的Nginx相关日志不存在4月份备份,Alimonitor相关QPS统计只有小时粒度数据,无法分析,暂时搁置该问题
Netty线程堆栈分析
"New I/O server boss #513" prio=10 tid=0x00007f64c11c5800 nid=0x3f64b runnable [0x0000000076aa8000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
- locked <0x0000000758ff66d0> (a sun.nio.ch.Util$2)
- locked <0x0000000758ff66e8> (a java.util.Collections$UnmodifiableSet)
- locked <0x0000000758959bd8> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84)
at org.jboss.netty.channel.socket.nio.NioServerBoss.select(NioServerBoss.java:163)
at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:206)
at org.jboss.netty.channel.socket.nio.NioServerBoss.run(NioServerBoss.java:42)
at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
通过与normal,exp2,exp3这三台机器上的netty线程对比,发现exp1这台机器上的server boss线程为55个,worker线程为456个,明显不正常,此时通过应用日志查看是否有异常,首先通过上面提供的方法查看应用启动时间为2015-04-29 09:17:03,通过在sell.log.2015-04-29重查找该时间段的netty字符串得到如下日志:
ERROR keystore.KeyStoreImpl - We have tried 53 times to init keystore,Exception in KeyStoreImpl.initKeyStore(),with keyNameList:[taobao_prikey, taobao_pubkey, alipay_pubkey],KeySubscbIdList:[] still exist
org.jboss.netty.channel.ChannelException: Failed to bind to: 0.0.0.0/0.0.0.0:9099
at org.jboss.netty.bootstrap.ServerBootstrap.bind(ServerBootstrap.java:272)
at com.taobao.common.keycenter.monitor.MonitorDaemon.start(MonitorDaemon.java:63)
at com.taobao.common.keycenter.monitor.MonitorMain.startMonitor(MonitorMain.java:46)
at com.taobao.common.keycenter.keystore.KeyStoreImpl.syncAndReportByStartUp(KeyStoreImpl.java:145)
at com.taobao.common.keycenter.keystore.KeyStoreImpl.initKeyStore(KeyStoreImpl.java:83)
at com.taobao.common.keycenter.keystore.KeyStoreImpl$1.run(KeyStoreImpl.java:60)
at java.lang.Thread.run(Thread.java:662)
Caused by: java.net.BindException: Address already in use
除以以外未找到与Netty有关系的异常日志,初步怀疑与keycenter应用相关,于是联系keycenter(Aone应用管理)的开发责任人@岩析同学,沟通结果为暂未处理过如上的问题。
问题重现
模拟错误日志场景
问题/故障分析中一个很重要也不可缺少的步骤就是重现,因为分析出来的原因很可能不是根因,我们做出的一些修改并没有解决问题,从而导致线上的二次故障,所以我们需要在测试机器或本机模拟出线上相同的故障场景,针对上面的错误日志,很容易想到可以模拟9099端口占用的场景,通过如下的代码
ServerSocket serverSocket = new ServerSocket(9099);
serverSocket.accept();
sell.log日志中也如期出现下面的日志,此时好像感觉到胜利的曙光就在眼前
ERROR keystore.KeyStoreImpl - We have tried 0 times to init keystore,Exception in KeyStoreImpl.initKeyStore(),with keyNameList:[taobao_prikey, taobao_pubkey, alipay_pubkey],KeySubscbIdList:[] still exist
org.jboss.netty.channel.ChannelException: Failed to bind to: 0.0.0.0/0.0.0.0:9099
at org.jboss.netty.bootstrap.ServerBootstrap.bind(ServerBootstrap.java:306)
at com.taobao.common.keycenter.monitor.MonitorDaemon.start(MonitorDaemon.java:63)
at com.taobao.common.keycenter.monitor.MonitorMain.startMonitor(MonitorMain.java:46)
at com.taobao.common.keycenter.keystore.KeyStoreImpl.syncAndReportByStartUp(KeyStoreImpl.java:145)
at com.taobao.common.keycenter.keystore.KeyStoreImpl.initKeyStore(KeyStoreImpl.java:83)
at com.taobao.common.keycenter.keystore.KeyStoreImpl$1.run(KeyStoreImpl.java:60)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.net.BindException: Address already in use
这时对本机的sell应用做ThreadDump,但是分析后却发现没有线程数很多的状况,查看后发现server boss线程只有0个,worker线程也只有1个,到这里问题定位又陷入了僵局,可能会面临线上问题在本机无法重现的尴尬,或者怀疑这个问题只是一个偶发问题。
线上问题再现
5月7号晚上18:00左右@欧仲在做日常发布的时候,又发现了exp1这台机器线程告警的问题,这次线程数超过了1w个,而且线程数还在不停的增长。于是又做了上面的ThreadDump分析和sell.log查看,得到下面的数据
故障时间 | 重试次数 | Netty线程总数 |
---|---|---|
2015-4-29 | 53 | 500 |
2015-5-7 | 1600 | 14500 |
分析两次故障的数据呈线性增长关系,根据经验可以判断出是keycenter应用端口被占用导致的问题,此时仍回到了要在测试机/本机重现问题的步骤。
本机问题重现
再无法重现问题的情况下,重新查看日志后发现这样一个问题
线上
at org.jboss.netty.bootstrap.ServerBootstrap.bind(ServerBootstrap.java:272)
本机
at org.jboss.netty.bootstrap.ServerBootstrap.bind(ServerBootstrap.java:306)
两个环境上的代码位置居然不一样(ServerBootstrap.java:272 VS ServerBootstrap.java:306),通过在本机查看netty源码时发现sell工程下有两个版本的netty包:netty-3.2.1.Final.jar和netty-3.6.3.Final.jar,通过查看代码发现线上问题时生效的是3.6.3版本,于是在本机暂时删除3.2.1版本的jar包,问题顺利重现,本机的线程数不停的上涨。
问题根因分析
这个问题出现的根本原因如下
- 9099端口被占用,线上重启应用时,原应用未完全关闭导致9099端口被占用
- keycenter应用在启动多次尝试时与Netty3.6版本不兼容
对应的应对措施
- 应用服务器重启时请尽量确认原有应用已完全关闭
- 查看应用是否对Netty3.6版本有依赖,如果有需要需要keycenter应用兼容3.6版本
总结
- 选择合适的观察对象,观察指标,如本文中线程数量告警则查看线程个数,如出现cpu使用率较高则需要查看locked,deadlock相关线程
- 熟练掌握shell命令和相关工具,包括通常的vi,ps,top;java相关的jstak,jmap;ThreadDump HeadDump分析工具;内部网站AliMonitor,ZProfiler等
- 分析问题的思路和流程也很重要,一些关键步骤切记不能遗漏,比如问题重现
- 解决问题的过程中一定要细心,不能急躁,坚信问题一定能解决,但是解决问题的过程也是极其枯燥的,不会是一蹴而就的,与大家共勉 。