一次因线程池使用不当造成生产事故的排查记录与思考

美好的一天从bug结束

某日当我点开熟悉的界面，一个又一个请求失败的提示赫然出现在屏幕上，不会是昨晚上线的代码有问题吧？

吓得我急忙按F12查看了响应——“exception”:“java.lang.OutOfMemoryError”,“message”:“unable to create new native thread”

出现了内存溢出的情况，无法创建更多的本地线程。

监控中显端倪

接着查看了实例的监控大盘，发现每个实例的JVM线程数量都处于9000+的规模，且还有上涨的趋势。

这是其中一个实例的线程数量监控图：

10.17日出现下降，并不是由于GC，而是由于上线，所以会降到0。

当前服务一共有8个实例，临时的方案是从负载均衡中摘除1个节点，用作排查使用，其他实例则按照顺序进行原地重建。

dump线程日志
登录上这个容器，使用

ps -ef|grep java

来查询到java应用的进程号，得到了1127

接着使用

jstack 1127 > thread.log

来导出进程内所有线程的状态数据，其中一部分的日志如图所示：

这两个线程，名称都是"pool-xxx-thread-xxx"的形式。

从Executors类中的静态内部类DefaultThreadFactory源码可知，默认线程工厂给线程池中的线程的取名规则就是这样的格式。

我们可以使用

grep -c "pool-" thread.log

来统计被线程池管理的线程总数，得到8336个，而一共才9000多个。

看来这次事故和线程池脱不了关系了

接着使用

grep java.lang.Thread.State thread.log | awk '{print $2$3$4$5}' | sort | uniq -c

按线程状态分组统计，得到这样的结果

40    RUNNABLE
5     TIMED_WAITING(onobjectmonitor)
63    TIMED_WAITING(parking)
12    TIMED_WAITING(sleeping)
73    WAITING(onobjectmonitor)
8100  WAITING(parking)

** RUNNABLE**
代表线程已经执行了start方法，但还没有获得CPU时间片，得到时间片后，才会变成RUNNING的状态。

**TIMED_WAITING(onobjectmonitor)与WAITING(onobjectmonitor) **

当线程获取监视器锁之后（一般是进入了synchronized方法），又调用了对象的wait或wait(time)方法࿰