从Sell线上线程数告警问题解决的过程谈ThreadDump分析的思路

概述

本文通过定位线上一台机器的线程数异常的定位过程为例，主要展示分析定位同类问题的过程和思路，同时展示个人比较顺手的一些工具，包括阿里的一些内部平台。问题/故障分析的案例往往没有通用性，但是问题分析的思路往往趋同，可以供大家学习和借鉴。

问题描述

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免登录相关配置略去

1. 通过ps -ef|grep java,获取目标进程(jboss/tomcat)的PID
2. 通过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

1. 复制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包，问题顺利重现，本机的线程数不停的上涨。

问题根因分析

这个问题出现的根本原因如下

1. 9099端口被占用，线上重启应用时，原应用未完全关闭导致9099端口被占用
2. keycenter应用在启动多次尝试时与Netty3.6版本不兼容

对应的应对措施

1. 应用服务器重启时请尽量确认原有应用已完全关闭
2. 查看应用是否对Netty3.6版本有依赖，如果有需要需要keycenter应用兼容3.6版本

总结

1. 选择合适的观察对象，观察指标，如本文中线程数量告警则查看线程个数，如出现cpu使用率较高则需要查看locked,deadlock相关线程
2. 熟练掌握shell命令和相关工具，包括通常的vi,ps,top;java相关的jstak,jmap;ThreadDump HeadDump分析工具;内部网站AliMonitor,ZProfiler等
3. 分析问题的思路和流程也很重要，一些关键步骤切记不能遗漏，比如问题重现
4. 解决问题的过程中一定要细心，不能急躁，坚信问题一定能解决，但是解决问题的过程也是极其枯燥的，不会是一蹴而就的，与大家共勉 。