记几次 [线上环境] Dubbo 线程池占满原因分析（第三次：GC STW）

[线上环境] Dubbo 线程池占满原因排查系列

记几次 [线上环境] Dubbo 线程池占满原因分析（第一次：HttpClient）
记几次 [线上环境] Dubbo 线程池占满原因分析（第二次：CompletableFuture）
记几次 [线上环境] Dubbo 线程池占满原因分析（第三次：GC STW）

---

---

前言

  某天晚上正在开开心心写代码，忽然收到了线上告警：dubbo 线程池 活跃线程数告警、应用错误日志告警、dubbo线程池队列长度告警；瞬间意识到要出大事情了，得赶紧定位到原因并解决问题，不然时间长了肯定会影响商家功能使用。

一、问题分析

1、监控分析

  之前已经有过两次处理dubbo线程池占满的经验，心想：不会又是上次两个问题类似的原因吧？既然这里已经确认是dubbo线程池出现了告警，那么我们先看看线上机器dubbo线程池监控信息，发现出现排队情况的机器不多：

  继续排查应用系统日志情况，看看是否有能够利于我们快速定位问题原因的日志信息：

  通过上面日志发现调用中台的接口时间超过10秒，而我们的dubbo框架时有配置 fastfail 3秒快速失败熔断机制的（一个dubbo请求超过 3秒没有返回结果不再继续请求其他dubbo接口，直接抛出fastfail异常，不做任何重试），而这里我们有一个请求超过了26秒，于是咨询一下中间件团队（公司对dubbo框架有过定制开发）看看是否能快速找到答案：

  好吧，中间件同学没能提供其他有效的信息（提供的文档已经看了好几遍），只能靠自己继续排查了。首先我们的相关应用dubbo都是开启了 fastfail 并且超时时间设置的是 3秒，所以接口请求理论上不会超过26秒的（fastfail只有再次请求dubbo接口的时候才会触发，如果dubbo入口只进入一次，应用自己内部逻辑处理超过了3秒是不会触发fastfail机制的）；再根据traceId（调用链ID，上下游所有相关系统都会打印，方便查找整条请求链路的日志）继续排查26秒这个接口内部的请求过程：

  发现代码执行过程很长，有间隔10+秒才走到下一个流程，由于这段代码逻辑嵌套比较深且打印的日志偏少，中间不确定发生了什么？花了大半天时间review了所有相关代码逻辑，修改代码增加相关日志，在 预发环境 使用相同的入参再次调用，速度很快，并没有出现间隔10+秒的问题。而这段逻辑中也不存在前两次的 httpClient、CompletableFuture 线程池之类的问题，到底是什么原因呢？


   经过多次review代码、查看系统日志、告警信息，忽然在大量的告警信息中发现一条线索：


   推测：由于dubbo线程池占满之前有 GC 告警出来； 是否和 GC STW（ stop the world 指的是Gc事件发生过程中，会产生应用程序的停顿。停顿产生时整个应用程序线程都会被暂停，没有任何响应，有点像卡死的感觉，这个停顿称为STW）有关？？？

2、STW 原因排查

   既然是GC出现了问题，也考虑过修改 JVM参数配置，在FullGC前后分别dump出内存快照，这边能够快速定位问题。但是这个方案不可行，主要有两个原因：
      1、FullGC前后分别dump内存快照势必会造成服务器性能出现抖动，而出现问题的是我们核心应用，稳定性十分重要。明知道会造成服务器抖动的配置，线上环境是不允许添加上去的，除非“万不得已”。
      2、线上总共有200多台服务器，而只有少量个别机器短时间内有发生问题且存在随机性，无法确定哪一台会出现问题。如果抽样配置自动dump内存快照，命中概率十分低下，但是这个问题又急需解决。

   先查看线上机器JVM GC配置（线上机器发布脚本都是同一套，所有服务器jvm配置都是一样的）：-XX:+UseConcMarkSweepGC 使用CMS垃圾回收器；-XX:+UseParallelGC：并行收集器，仅对年轻代有效，可以同时并行多个垃圾收集线程，但此时用户线程必须停止：

   准备去定位根因时，忽然遇到一个难题，今天有发布，出现问题的线上机器docker容器都已经下掉了，没有gc日志了； 目前推测大概率是STW时间过长导致，但暂时无法实锤。准备后面再持续观察，如果再出现GC时间过长再去定位根因。

   果然，第二天另一台机器再次出现这个问题，这次先使用 jmap 把内存快照dump下来，因为根据经验推测STW时间长大概率是内存对象较大，导致GC回收时间过长。分别使用JProfiler、IBM的内存分析工具分析了内存dump文件结果如下：

   logback 占用内存较多，推测可能是打印了大日志对象，导致内存占用过高，最终引起GC。接下来去证实一下，去服务器上查询GC日志： 16:59:37 触发了一次FullGC，耗时 4.5s ：

（可以使用 GCEasy 工具对 gc 日志进行完整分析，支持上传整个gc日志文件或者gc日志文本，并且有统计图展示，非常好用 官网地址）

   继续根据 FullGC发生的时间，查看逐行查看问题服务器上的日志（非常考眼力，滴了好几滴眼药水），终于发现了“异常”日志：

营销中心发送了一个大MQ消息，482W字符，将近4.5M的消息体：

   凭借这一个结果，真的可以确定是这个原因造成的吗？ 为了实锤问题原因，这边又根据历史告警记录，找到了其他几台机器的日志，发现都时间都能够对上，超过三次出现时间基本对上，是时候下结论了：由于营销中心业务原因，存在发送单个大MQ消息体的场景，而我们这边有接收这个MQ消息，存在多次JSON对象转换、new新对象、log输出日志等操作导致堆内存会瞬间飙高触发FullGC，由于逻辑嵌套较深，且创建对象较多引起 STW 造成线程停顿，而我们应用dubbo接口qps较高，在停顿期间不断有请求进来，最终引起dubbo线程池占满，队列堆积，dubbo服务出现不可用。

代码案例：

二、解决方案

既然已经知道了原因，那么解决起来也变得很容易了：

1、解析营销中心MQ消息体的地方进行优化，消息体只解析我们关心的参数转成对象；

2、营销中心的消息体设计显然有些不合理，发送的MQ消息过于庞大，在传输和业务处理上可能会造成性能瓶颈（传输速度慢、占用网络宽度多、数据量过大解析起来处理速度慢等）。因此需要向营销中心提需求优化此消息发送策略，拆成小消息发送或者只发送ID让业务方进行反查详细数据，从源头解决这个问题。

   与营销中心同学沟通过程中出现了一个小插曲：由于这个MQ消息监听的业务方比较多，改动影响较大，推动其他业务方一起改造比较困难。在中台同学准备放弃的时候，这边给他们提了个建议：创建一个新的消息通道，将拆分好的消息发送到新通道中，其他业务方依次迁移到新消息中，全部迁移完成之后再废弃掉旧的大消息，我们业务可以第一个配合接入新消息通道。 好在中台同学最终同意采取这个方案，与中台同学沟通部分记录：

三、总结

1、dubbo 线程池占满只是一个表象，可能造成的原因会有很多，可以根据系统日志、监控、告警等信息分析具体原因；
2、学会使用工具分析很重要，比如文中提到的 GCEasy 、JProfiler等，能够快速帮助我们定位问题根因；
3、发现问题之后，可以先有短期临时方案，但是最终还是一定要从源头解决，彻底根治问题；