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

速读摘要文章源自JAVA秀-https://www.javaxiu.com/11514.html

这个只是给大家提供一个思路，每个人遇到问题或者场景都不一样那得到的结论也都不一样，只能是给大家作为一个参考吧!!!最后还是要强调一下大家遇到问题不要稀里糊涂解决了就好了，这样下次问题复现你还是稀里糊涂解决不知道什么原因，这样长期下来你的个人成长是很局限的，对一个技术的理解往往是从问题发现到解决理解这中间得到提升的。文章源自JAVA秀-https://www.javaxiu.com/11514.html

原文约 3744 字 | 图片 5 张 | 建议阅读 8 分钟 | 评价反馈文章源自JAVA秀-https://www.javaxiu.com/11514.html

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

原创 三太子敖丙 三太子敖丙 文章源自JAVA秀-https://www.javaxiu.com/11514.html

收录于话题文章源自JAVA秀-https://www.javaxiu.com/11514.html

#dubbo文章源自JAVA秀-https://www.javaxiu.com/11514.html

9个文章源自JAVA秀-https://www.javaxiu.com/11514.html

前言

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

我写过dubbo系列的文章，大家看完这章后想了解更多dubbo细节可以查看往起文章：文章源自JAVA秀-https://www.javaxiu.com/11514.html

• Dubbo文章源自JAVA秀-https://www.javaxiu.com/11514.html

• 高性能NIO框架-Netty文章源自JAVA秀-https://www.javaxiu.com/11514.html

• Netty常见面试题总结文章源自JAVA秀-https://www.javaxiu.com/11514.html

• 敖丙RPC的超时设置，一不小心搞了线上事故文章源自JAVA秀-https://www.javaxiu.com/11514.html

• 敖丙找出Dubbo源码BUG，三歪夸了我一天文章源自JAVA秀-https://www.javaxiu.com/11514.html

• Dubbo基础文章源自JAVA秀-https://www.javaxiu.com/11514.html

• Dubbo的服务暴露过程文章源自JAVA秀-https://www.javaxiu.com/11514.html

• Dubbo的服务引用过程文章源自JAVA秀-https://www.javaxiu.com/11514.html

• Dubbo服务调用过程文章源自JAVA秀-https://www.javaxiu.com/11514.html

• Dubbo的SPI机制是啥？文章源自JAVA秀-https://www.javaxiu.com/11514.html

• Dubbo集群容错负载均衡文章源自JAVA秀-https://www.javaxiu.com/11514.html

• Dubbo面试题文章源自JAVA秀-https://www.javaxiu.com/11514.html

• RPC实践文章源自JAVA秀-https://www.javaxiu.com/11514.html

• Netty文章源自JAVA秀-https://www.javaxiu.com/11514.html

问题

在一天早上突然手机收到公司服务告警短信，线程池耗尽了？在去公司的路上首先回想的就是最近公司有活动？流量突增？大早上就有人在发布系统？还是某歪趁我不在又点坏了我的系统？文章源自JAVA秀-https://www.javaxiu.com/11514.html

怀着种种思考在公司的群里看着同步信息，以上种种可能都被反驳！！！文章源自JAVA秀-https://www.javaxiu.com/11514.html

以下就是当时的告警信息：文章源自JAVA秀-https://www.javaxiu.com/11514.html

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里面线程池默认实现是什么呢？文章源自JAVA秀-https://www.javaxiu.com/11514.html

A：我们在排查问题的时候一定要有一种必须查出因果关系的思想才能对自己有一定的提升，凭借着这种思想我们一步一步向下揭开谜底。文章源自JAVA秀-https://www.javaxiu.com/11514.html

带着问题，接下来我们去查看dubbo的代码配置，了解dubbo底层实现，只有了解底层实现我们才能更加准确的发现问题，处理问题，提升自己......文章源自JAVA秀-https://www.javaxiu.com/11514.html

首先我们看下我们代码配置：文章源自JAVA秀-https://www.javaxiu.com/11514.html

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

从抛出的异常上我们已经设置的线程池的大小为300了文章源自JAVA秀-https://www.javaxiu.com/11514.html

这里我说明一个点，不是线程池配置的越大就越好，这个是授我们系统层面，以及配置JVM参数相关的。一般我们都是默认配置200 大致可以从这几方面去做考虑：文章源自JAVA秀-https://www.javaxiu.com/11514.html

1.JVM参数：-Xms 初始堆大小 -Xmx 最大堆大小 -Xss 每个线程栈大小2.系统层面1.系统最大可创建的线程 2.公式线：程数量 = (机器本身可用内存 - (JVM分配的堆内存+JVM元数据区)) / Xss的值文章源自JAVA秀-https://www.javaxiu.com/11514.html

言归正传我们开始看下撸点源码，这里我们以 2.7.19的版本为列文章源自JAVA秀-https://www.javaxiu.com/11514.html

文章源自JAVA秀-https://www.javaxiu.com/11514.html

我们可以看到ThreadPool接口是个扩展点，然后默认实现是fixed，然后里面有个getExecutor方法，被@Adaptive注解修饰。文章源自JAVA秀-https://www.javaxiu.com/11514.html

在dubbo中ThreadPool有4个实现类文章源自JAVA秀-https://www.javaxiu.com/11514.html

文章源自JAVA秀-https://www.javaxiu.com/11514.html

1.CachedThreadPool 缓存线程池，超过keepAliveTime时间删除，使用的时候再创建文章源自JAVA秀-https://www.javaxiu.com/11514.html

2.FixedThreadPool 固定线程数量线程池，一旦建立，一直持有。文章源自JAVA秀-https://www.javaxiu.com/11514.html

3.LimitedThreadPool 可伸缩线程池，线程只增长不收缩。文章源自JAVA秀-https://www.javaxiu.com/11514.html

4.EagerThreadPool 当core线程数忙的时候，创建新线程，而不是将任务放入阻塞队列。这个使用自己队列TaskQueue。文章源自JAVA秀-https://www.javaxiu.com/11514.html

这里我们就直接看默认实现FixedThreadPool文章源自JAVA秀-https://www.javaxiu.com/11514.html

文章源自JAVA秀-https://www.javaxiu.com/11514.html

异常处理机制文章源自JAVA秀-https://www.javaxiu.com/11514.html

文章源自JAVA秀-https://www.javaxiu.com/11514.html

从代码中我们可以发现：文章源自JAVA秀-https://www.javaxiu.com/11514.html

dubbo线程池采用jdk的ThreadPoolExecutor，默认threads数为200，并且默认采用了SynchronousQueue队列，而如果用户配置的队列长度大于0时，则会采用LinkedBlockingQueue队列。文章源自JAVA秀-https://www.javaxiu.com/11514.html

如果某个线程因为执行异常而结束，那么线程池会添加一个新的线程。文章源自JAVA秀-https://www.javaxiu.com/11514.html

所以由于dubbo默认采用了直接提交的SynchronousQueue工作队列，所以，所有的task会直接提交给线程池中的某一worker线程，如果没有可用线程，那么会拒绝任务的处理然后抛出我们当前现在遇到的问题文章源自JAVA秀-https://www.javaxiu.com/11514.html

以下说明下我们创建一个线程池的必要参数 ：文章源自JAVA秀-https://www.javaxiu.com/11514.html

• corePoolSize - 池中所保存的线程数，包括空闲线程。文章源自JAVA秀-https://www.javaxiu.com/11514.html

• maximumPoolSize-池中允许的最大线程数。文章源自JAVA秀-https://www.javaxiu.com/11514.html

• keepAliveTime - 当线程数大于核心时，此为终止前多余的空闲线程等待新任务的最长时间。文章源自JAVA秀-https://www.javaxiu.com/11514.html

• unit - keepAliveTime 参数的时间单位。文章源自JAVA秀-https://www.javaxiu.com/11514.html

• workQueue - 执行前用于保持任务的队列。此队列仅保持由 execute方法提交的 Runnable任务。文章源自JAVA秀-https://www.javaxiu.com/11514.html

• threadFactory - 执行程序创建新线程时使用的工厂。文章源自JAVA秀-https://www.javaxiu.com/11514.html

• handler  由于超出线程范围和队列容量而使执行被阻塞时所使用的处理程序。ThreadPoolExecutor是Executors类的底层实现。文章源自JAVA秀-https://www.javaxiu.com/11514.html

好，看了这么多源码，从上面我们已经了解这个异常来的来源了，那是什么原因导致我遇到的这次的线程池耗尽呢？文章源自JAVA秀-https://www.javaxiu.com/11514.html

排查思路

第一阶段：

由于10.33.xx.xxx这台机器出现线程池耗尽的时候，伴随出现了一次时间比较久的ygc；所以怀疑是因为ygc时间较长，导致了机器资源紧张，从而拖垮了线程池；文章源自JAVA秀-https://www.javaxiu.com/11514.html

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时间这么长：文章源自JAVA秀-https://www.javaxiu.com/11514.html

这里给大家简单说明下为什么IO高会导致GC时间长文章源自JAVA秀-https://www.javaxiu.com/11514.html

1.JVM GC需要通过发起系统调用write()，来记录GC行为。文章源自JAVA秀-https://www.javaxiu.com/11514.html

2.write()调用可以被后台磁盘IO所阻塞。文章源自JAVA秀-https://www.javaxiu.com/11514.html

3.记录GC日志属于JVM停顿的一部分，因此write()调用的时间也会被计算在JVM STW的停顿时间内。文章源自JAVA秀-https://www.javaxiu.com/11514.html

通过GC日志可以看到新生代在进行垃圾回收的时候停顿时间是在3.92s；对于新生代空间在1.8G左右的显然是不正常的；ParNew收集器的工作过程中会出现以下步骤：文章源自JAVA秀-https://www.javaxiu.com/11514.html

（1）标记-标记出来活着的对象 ----> (2) 将对象从eden区复制到survior区 -----> (3)清理eden区文章源自JAVA秀-https://www.javaxiu.com/11514.html

理论上来说第三步的时间是一定的，那可能时间会比较久的要么在第一步，要么在第二步文章源自JAVA秀-https://www.javaxiu.com/11514.html

如果是第一步标记时间过长，就意味着本次GC之前，eden区存在大量的小对象（因为eden区大小是一定的），量级应该是正常的对象数量的数十倍文章源自JAVA秀-https://www.javaxiu.com/11514.html

如果是第二步时间过长的话，那么存在以下可能：文章源自JAVA秀-https://www.javaxiu.com/11514.html

1.标记完之后，eden区还有大量的对象(表现是回收之后新生代的对象占用内存仍然很大)，这个从gclog可以排除（回收之后新生代的大小还有39M)文章源自JAVA秀-https://www.javaxiu.com/11514.html

2.标记完之后仍然有大量碎片化的小对象存在文章源自JAVA秀-https://www.javaxiu.com/11514.html

3.YGC出发了fullGC，但是我们没有查看到有关日志文章源自JAVA秀-https://www.javaxiu.com/11514.html

此时以上的情况都指向一种可能，那就是新生代存在大量的碎片化的小对象；文章源自JAVA秀-https://www.javaxiu.com/11514.html

为了验证这个论据，那就只有一种办法就是去分析一下堆快照，但是我们那个时候刚好机器被重起，无法查明原因文章源自JAVA秀-https://www.javaxiu.com/11514.html

在我们无法验证的时候，第二台机器出现了同样的问题，准备再次jump日志的时候，回过头来看了一下GC日志，发现GC正常。所以推翻阶段一结论文章源自JAVA秀-https://www.javaxiu.com/11514.html

这里给大家介绍一些我们常用的服务器命令：文章源自JAVA秀-https://www.javaxiu.com/11514.html

top : 这是最常用的，也是展示信息最全的，可以看到负载，内存，cpu等很多东西文章源自JAVA秀-https://www.javaxiu.com/11514.html

比如使用top常见分析步奏：文章源自JAVA秀-https://www.javaxiu.com/11514.html

1.top -Hp命令，查看具体是哪个线程占用率较高 2.使用printf命令查看这个线程的16进制 3.使用jstack命令查看当前线程正在执行的方法文章源自JAVA秀-https://www.javaxiu.com/11514.html

文章源自JAVA秀-https://www.javaxiu.com/11514.html

使用jmap查看内存情况，并分析是否存在内存泄露。文章源自JAVA秀-https://www.javaxiu.com/11514.html

jmap -heap 3331：查看java 堆（heap）使用情况文章源自JAVA秀-https://www.javaxiu.com/11514.html

jmap -histo 3331：查看堆内存(histogram)中的对象数量及大小文章源自JAVA秀-https://www.javaxiu.com/11514.html

jmap -histo:live 3331：JVM会先触发gc，然后再统计信息文章源自JAVA秀-https://www.javaxiu.com/11514.html

jmap -dump:format=b,file=heapDump 3331：将内存使用的详细情况输出到文件文章源自JAVA秀-https://www.javaxiu.com/11514.html

当然还有很多其他的命令比如 jstack,jinfo，uptime 等等很多命令。。。文章源自JAVA秀-https://www.javaxiu.com/11514.html

开启阶段二的排查：

第二次出现异常的机器伴随着各种redis查询超时，从而导致所有的查询 都走到了DB，从而导致数据库压力大增，慢SQl告警等等。文章源自JAVA秀-https://www.javaxiu.com/11514.html

所以又再次去查询什么原因导致我们的redis查询超时呢？文章源自JAVA秀-https://www.javaxiu.com/11514.html

第一步肯定都是去查看redis服务的各项性能指标是不是出现异常，结果也没有很大的变化，那么问题肯定是在服务器本身.文章源自JAVA秀-https://www.javaxiu.com/11514.html

查看本身指标发现：文章源自JAVA秀-https://www.javaxiu.com/11514.html

那就是在报警时间段，cpu，cpu_iowait, 指标会飙升，磁盘IO则呈现不间断锯齿状，其余指标基本不存在波动文章源自JAVA秀-https://www.javaxiu.com/11514.html

但是什么原因引起的CPU波动呢？cpu波动跟线程池耗尽之间又有什么因果关系呢？文章源自JAVA秀-https://www.javaxiu.com/11514.html

因此似乎得到了答案磁盘IO较高，导致cpu_iowait变高，cpu等IO，瞬间分配不到时间片，rt就会抖动。文章源自JAVA秀-https://www.javaxiu.com/11514.html

最后我们发现跟我们的磁盘IO较高的原因时又跟我们的日志采集系统有关，相信现在很大一部分的公司都会用TRACE作为服务的全程链路最终管理。文章源自JAVA秀-https://www.javaxiu.com/11514.html

再采用异步方式把记录在内存中trace日志一次性写入磁盘，所以会出现IO抖动。文章源自JAVA秀-https://www.javaxiu.com/11514.html

接下来我们看下trace 他到底是怎么工作的。文章源自JAVA秀-https://www.javaxiu.com/11514.html

trace 是类似 strace 的动态跟踪工具，属于问题诊断和调试工具 1.trace 包括两部分：收集跟踪日志和解析跟踪日志。2.trace 收集跟踪日志实质上是运行跟踪模块时记录的控制流信息的日志文章源自JAVA秀-https://www.javaxiu.com/11514.html

重点： trace 模块将上述信息组织成二进制格式写入内存中，直到停止 trace 跟踪，才将上述内存中的信息导出为二进制文件文章源自JAVA秀-https://www.javaxiu.com/11514.html

这个只是给大家提供一个思路，每个人遇到问题或者场景都不一样那得到的结论也都不一样，只能是给大家作为一个参考吧！！！文章源自JAVA秀-https://www.javaxiu.com/11514.html

总结

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

最后还是要强调一下大家遇到问题不要稀里糊涂解决了就好了，这样下次问题复现你还是稀里糊涂解决不知道什么原因，这样长期下来你的个人成长是很局限的，对一个技术的理解往往是从问题发现到解决理解这中间得到提升的。文章源自JAVA秀-https://www.javaxiu.com/11514.html

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

做一行爱一行嘛，我是敖丙，你知道的越多，你不知道的越多，我们下期见。文章源自JAVA秀-https://www.javaxiu.com/11514.html