记一次敖丙Dubbo线程池事故排查

前言

duubo在互联网技术中是中的非常广泛的，从我实习到现在我所在的公司，都是使用的dubbo做rpc框架，所以这也导致了我们需要更加深入的去了解这门技术，因为我们的遇到的问题无时无刻都会存在，本次我就跟大家讲讲我的一次线上dubbo线程池耗尽的事故排查思路。

我写过dubbo系列的文章，大家看完这章后想了解更多dubbo细节可以查看往起文章：

Dubbo

• 高性能NIO框架-Netty
• Netty常见面试题总结
• 敖丙RPC的超时设置，一不小心搞了线上事故
• 敖丙找出Dubbo源码BUG，三歪夸了我一天
• Dubbo基础
• Dubbo的服务暴露过程
• Dubbo的服务引用过程
• Dubbo服务调用过程
• Dubbo的SPI机制是啥?
• Dubbo集群容错负载均衡
• Dubbo面试题
• RPC实践
• Netty

问题

在一天早上突然手机收到公司服务告警短信，线程池耗尽了?在去公司的路上首先回想的就是最近公司有活动?流量突增?大早上就有人在发布系统?还是某歪趁我不在又点坏了我的系统?

怀着种种思考在公司的群里看着同步信息，以上种种可能都被反驳!!!

以下就是当时的告警信息：

1. RejectedExecutionException:Thread pool is EXHAUSTED （线程池耗尽了）! Thread Name: DubboServerHandler-xx.xx.xxx:2201, Pool Size: 300 (active: 283, core: 300, max: 300, largest: 300) 

Q：这个问题怎么出现的呢?是不是我们扩大线程池就能解决问题呢?dubbo里面线程池默认实现是什么呢?

A：我们在排查问题的时候一定要有一种必须查出因果关系的思想才能对自己有一定的提升，凭借着这种思想我们一步一步向下揭开谜底。

带着问题，接下来我们去查看dubbo的代码配置，了解dubbo底层实现，只有了解底层实现我们才能更加准确的发现问题，处理问题，提升自己......

首先我们看下我们代码配置：

1. <dubbo:protocol name="dubbo" port="${service.protocol.dubbo.port}" threads="${service.protocol.dubbo.threads}" register="${service.protocol.dubbo.register}" /> 

从抛出的异常上我们已经设置的线程池的大小为300了

• 这里我说明一个点，不是线程池配置的越大就越好，这个是授我们系统层面，以及配置JVM参数相关的。一般我们都是默认配置200 大致可以从这几方面去做考虑：
• 1.JVM参数：-Xms 初始堆大小 -Xmx 最大堆大小 -Xss 每个线程栈大小2.系统层面1.系统最大可创建的线程 2.公式线：程数量 = (机器本身可用内存 - (JVM分配的堆内存+JVM元数据区)) / Xss的值

言归正传我们开始看下撸点源码，这里我们以 2.7.19的版本为例

我们可以看到ThreadPool接口是个扩展点，然后默认实现是fixed，然后里面有个getExecutor方法，被@Adaptive注解修饰。

在dubbo中ThreadPool有4个实现类

1.CachedThreadPool 缓存线程池，超过keepAliveTime时间删除，使用的时候再创建

2.FixedThreadPool 固定线程数量线程池，一旦建立，一直持有。

3.LimitedThreadPool 可伸缩线程池，线程只增长不收缩。

4.EagerThreadPool 当core线程数忙的时候，创建新线程，而不是将任务放入阻塞队列。这个使用自己队列TaskQueue。

这里我们就直接看默认实现FixedThreadPool

异常处理机制

从代码中我们可以发现：

dubbo线程池采用jdk的ThreadPoolExecutor，默认threads数为200，并且默认采用了SynchronousQueue队列，而如果用户配置的队列长度大于0时，则会采用LinkedBlockingQueue队列。

如果某个线程因为执行异常而结束，那么线程池会添加一个新的线程。

所以由于dubbo默认采用了直接提交的SynchronousQueue工作队列，所以，所有的task会直接提交给线程池中的某一worker线程，如果没有可用线程，那么会拒绝任务的处理然后抛出我们当前现在遇到的问题

以下说明下我们创建一个线程池的必要参数 ：

• corePoolSize - 池中所保存的线程数，包括空闲线程。
• maximumPoolSize-池中允许的最大线程数。
• keepAliveTime - 当线程数大于核心时，此为终止前多余的空闲线程等待新任务的最长时间。
• unit - keepAliveTime 参数的时间单位。
• workQueue - 执行前用于保持任务的队列。此队列仅保持由 execute方法提交的 Runnable任务。
• threadFactory - 执行程序创建新线程时使用的工厂。
• handler 由于超出线程范围和队列容量而使执行被阻塞时所使用的处理程序。ThreadPoolExecutor是Executors类的底层实现。

好，看了这么多源码，从上面我们已经了解这个异常来的来源了，那是什么原因导致我遇到的这次的线程池耗尽呢?

排查思路

第一阶段：

由于10.33.xx.xxx这台机器出现线程池耗尽的时候，伴随出现了一次时间比较久的ygc;所以怀疑是因为ygc时间较长，导致了机器资源紧张，从而拖垮了线程池;

1. 2021-03-26T10:14:45.476+0800: 64922.846: [GC (Allocation Failure) 2021-02-24T11:17:45.477+0800: 64922.847: [ParNew: 1708298K->39822K(1887488K), 3.9215459 secs] 4189242K->2521094K(5033216K), 3.9225545 secs] [Times: user=12.77 sys=0.00, real=3.92 secs] 

所以就一直在思考什么原因导致YGC时间这么长：

这里给大家简单说明下为什么IO高会导致GC时间长

1.JVM GC需要通过发起系统调用write()，来记录GC行为。

2.write()调用可以被后台磁盘IO所阻塞。

3.记录GC日志属于JVM停顿的一部分，因此write()调用的时间也会被计算在JVM STW的停顿时间内。

通过GC日志可以看到新生代在进行垃圾回收的时候停顿时间是在3.92s;对于新生代空间在1.8G左右的显然是不正常的;ParNew收集器的工作过程中会出现以下步骤：

(1)标记-标记出来活着的对象 ----> (2) 将对象从eden区复制到survior区 -----> (3)清理eden区

理论上来说第三步的时间是一定的，那可能时间会比较久的要么在第一步，要么在第二步

如果是第一步标记时间过长，就意味着本次GC之前，eden区存在大量的小对象(因为eden区大小是一定的)，量级应该是正常的对象数量的数十倍

如果是第二步时间过长的话，那么存在以下可能：

1.标记完之后，eden区还有大量的对象(表现是回收之后新生代的对象占用内存仍然很大)，这个从gclog可以排除(回收之后新生代的大小还有39M)

2.标记完之后仍然有大量碎片化的小对象存在

3.YGC出发了fullGC，但是我们没有查看到有关日志

此时以上的情况都指向一种可能，那就是新生代存在大量的碎片化的小对象;

为了验证这个论据，那就只有一种办法就是去分析一下堆快照，但是我们那个时候刚好机器被重起，无法查明原因

在我们无法验证的时候，第二台机器出现了同样的问题，准备再次jump日志的时候，回过头来看了一下GC日志，发现GC正常。所以推翻阶段一结论

这里给大家介绍一些我们常用的服务器命令：

top : 这是最常用的，也是展示信息最全的，可以看到负载，内存，cpu等很多东西

比如使用top常见分析步奏：

1.top -Hp命令，查看具体是哪个线程占用率较高 2.使用printf命令查看这个线程的16进制 3.使用jstack命令查看当前线程正在执行的方法

使用jmap查看内存情况，并分析是否存在内存泄露。

jmap -heap 3331：查看java 堆(heap)使用情况

jmap -histo 3331：查看堆内存(histogram)中的对象数量及大小

jmap -histo:live 3331：JVM会先触发gc，然后再统计信息

jmap -dump:format=b,file=heapDump 3331：将内存使用的详细情况输出到文件

当然还有很多其他的命令比如 jstack,jinfo，uptime 等等很多命令。。。

开启阶段二的排查：

第二次出现异常的机器伴随着各种redis查询超时，从而导致所有的查询 都走到了DB，从而导致数据库压力大增，慢SQl告警等等。

所以又再次去查询什么原因导致我们的redis查询超时呢?

第一步肯定都是去查看redis服务的各项性能指标是不是出现异常，结果也没有很大的变化，那么问题肯定是在服务器本身.

查看本身指标发现：

那就是在报警时间段，cpu，cpu_iowait, 指标会飙升，磁盘IO则呈现不间断锯齿状，其余指标基本不存在波动

但是什么原因引起的CPU波动呢?cpu波动跟线程池耗尽之间又有什么因果关系呢?

因此似乎得到了答案磁盘IO较高，导致cpu_iowait变高，cpu等IO，瞬间分配不到时间片，rt就会抖动。

最后我们发现跟我们的磁盘IO较高的原因时又跟我们的日志采集系统有关，相信现在很大一部分的公司都会用TRACE作为服务的全程链路最终管理。

再采用异步方式把记录在内存中trace日志一次性写入磁盘，所以会出现IO抖动。

接下来我们看下trace 他到底是怎么工作的。

• trace 是类似 strace 的动态跟踪工具，属于问题诊断和调试工具 1.trace 包括两部分：收集跟踪日志和解析跟踪日志。2.trace 收集跟踪日志实质上是运行跟踪模块时记录的控制流信息的日志

重点： trace 模块将上述信息组织成二进制格式写入内存中，直到停止 trace 跟踪，才将上述内存中的信息导出为二进制文件

这个只是给大家提供一个思路，每个人遇到问题或者场景都不一样那得到的结论也都不一样，只能是给大家作为一个参考吧!!!

总结

其实我们在排查问题的时候，我们很容易会被一些其他的表象给迷惑了，认为本来是果的关系变成了因，但是这个本来也就是一个复杂的过程，只能是通过自己不断的积累，不断的学习过程，所以写下这篇文章希望能对大家有一定的帮助.

最后还是要强调一下大家遇到问题不要稀里糊涂解决了就好了，这样下次问题复现你还是稀里糊涂解决不知道什么原因，这样长期下来你的个人成长是很局限的，对一个技术的理解往往是从问题发现到解决理解这中间得到提升的。

我身边的大佬遇到这样的情况都是选择先解决问题(遇到任何线上问题都是优先恢复再考虑查找原因)，然后刨根问底找到答案才罢休的，比如我老东家的leader在遇到一个内存溢出问题时，dump下数据从中午分析到大半夜，分析出来，写了满满一大页的wiki吧过程沉淀下来才回家，我看到的时候是由衷的佩服。

做一行爱一行嘛，我是敖丙，你知道的越多，你不知道的越多，我们下期见。

原文地址：https://mp.weixin.qq.com/s/AXdfaFVJw43BeM4gREKJOA