实战总结｜记一次消息队列堆积的问题排查

本次问题涉及的系统链路如下图所示：

各系统的基本职责为：

• Proxy：提供请求代理服务。统一代理发往下游系统的各类请求，从而让上游系统无需感知下游各服务的使用差异；同时提供精细化的限流、导流等服务特性。
• 拉图 SDK：面向各存储平台提供统一的图片下载功能。它通常与图像类算法模型被前后编排在一起。
• 预估引擎：提供模型推理服务。支持各种机器学习、深度学习算法模型的工程部署。

2.1 问题描述

某天上午收到报警通知，提示 Proxy 系统的入口 MQ 有堆积。打开控制台，发现 500 台 Proxy 机器中，有 1 台机器堆积十分严重，而其余机器均运行正常：

2.2 一句话根因

• 个别机器堆积：该机器有消费线程被卡住，虽然其余线程正常消费，但 MQ 机制决定消费位点并不前进。
• HTTP 下载卡住：所使用的 HttpClient 版本有 bug，特定情况下超时不生效，可能导致线程一直卡住。

2.3 排查流程

1. 该机器消费速度太慢？

   第一反应是这台机器的消费太慢。同样的消息量，别的机器能快速消化，而它由于消费慢于是持续堆积。然而在 MQ 控制台详细对比后，发现该机器的业务处理时长、消费 TPS 都与其他机器相近，且不同机器的规格本身也是一样的。

   其次，观察 Arthas 画出的火焰图，右边两根比较细长的火焰即为我们系统的业务逻辑（火焰比较高是因为 RPC 的调用栈比较深）。从图中可看出，火焰图并没有明显的“平顶效应”，火焰的宽度都比较窄，也可说明该机器在执行业务逻辑时中并没有明显的耗时卡点，由此也可证明该机器并不是因为业务处理慢而造成的堆积。

   

2. 系统指标是否正常？

   登录机器，发现 CPU、MEM、LOAD 均正常，且与正常机器相近，没有发现明显线索。

   

   且该机器并无明显的 Full GC：

   

3. 限流导致？

   Proxy 在代理请求时会有限流机制，超出限额的流量会触发阻塞等待，从而保护下游同步服务。因此，假如今天系统流量很大，超出了下游服务能承受的限制，则超出部分的请求会触发 RateLimiter 限流而阻塞。于是大量 MQ 消费者线程被阻塞，故 Proxy 系统整体的消息消费速度会变慢，最终体现的结果即为入口 topic 堆积。

   然而，不管是看该机器的日志还是监控，因限流而阻塞的现象都并不严重，比较通畅。其次，如果真是因为今天系统入口流量大导致，那应该所有 Proxy 机器（MQ 消费者）都会出现程度相近的堆积。不应该全堆在同 1 台机器上，而其他 499 台机器都正常。因此，排查系统入口流量太大的可能性。

4. MQ 数据倾斜？

   预期应该是 500 台 Proxy 机器均分入口 MQ 里面的消息，有没有可能是数据分配时出现了倾斜，导致这台机器分到的消息量太多，其他机器分到的消息很少？

   查看 Proxy 上游系统的代码，该系统在向 Proxy 发消息时并没有做自定义 Shuffle，于是会使用 MQ 默认的 selectOneMessageQueue 策略。而该策略会把当前消息发到基于 index % queue_size 选出的队列中。进一步查看 index 的逻辑，发现它初始化时以一个随机数为起点，每次访问时会 +1 自增。

   结合以上两点，实现的效果即为：对各个 queue 从左到右、均匀地分发消息，并通过 % 实现自动循环。

   

   综上可知，MQ 默认 shuffle 策略为：把消息均分到各个 queue 中。因此，可排除因为 MQ 发送消息数据倾斜，导致我们那台 Proxy 机器堆积的可能性。

5. CPU steal ？

   CPU steal 表示虚拟机中运行的进程被宿主机上的其他进程/虚拟机占用了 CPU 时间的百分比，高 CPU steal 值通常意味着虚拟机中的进程性能下降。

   比如机器规格本身写的是 4C，实际因为被 steal 后能用的可能只有 2C。所以体现的结果就是单个请求的 RT 无明显变化（不同 C 之间差异不大），但 C 的量变少了，所以这台机器整体吞吐变小、消费能力变弱，导致堆积。但排查发现，st 正常，排除这种可能。

   

6. 找到线索：MQ 消费位点没变！

   兜兜转转一圈都没找到异常点，由于问题现象是 MQ 堆积，所以又想到可以去查看中间件的日志寻找线索。果然，通过定向搜索卡住机器的 queueId，发现这个队列的消费位点长时间不推进，一直卡在某个位置。

   MQ 拉消息的机制是，拉到的消息会先存放在内存中容量为 1000 的 cache 中，然后这些内存中的消息将被消费者线程消费。当 cache 满了时，就不会再从 queue 中拉取。

   由此怀疑：是否因为 Proxy 消费停止 or 消费极慢，导致本地缓存一直是满的，于是 MQ 会停止向 queue 中拉消息，于是 offset 一直没变？但上文已提到，不管从 MQ 控制台、系统监控指标、机器日志来看，该机器都是正常的，与其余机器没什么区别。那为什么该机器的消费位点就是不动，导致堆积越来越严重？

7. 找到根因：某个消费者线程卡住了

   对于本地缓存中的消息，MQ 会开多线程（线程数量由用户指定）去拉取消费。且为了保证消息不丢失，offset 记录的只是最靠前的那条消息。

   这个机制是合理的。因为在 At Least Once 语义下，消息允许被消费多次但不允许被遗漏。假设现在有两个线程同时拉取了前后两条消息，且后面的消息先执行完毕。由于前一条消息的执行可能会出现异常，所以不能直接用后者的偏移量去更新 offset，否则消费失败的消息就找不回了。因此，消费位点 offset 的含义是：在该位置及之前的所有消息都已经被正确消费（有点类似 Flink 的 Watermark 机制）。

   根据以上机制，回到本问题，假如这台 Proxy 机器的众多 MQ 消费者线程中有任意一个被卡住，那么整个 queue 的消费位点将永远停留在被卡住的消息对应的 offset。此时虽然其他线程都在持续正常消费，但并不能往前推进 offset。另一方面，由于上游还在源源不断往队列中发消息，于是消息只进不出，堆积量 = 最新入口消息的 offset - 消费位点 offset 只增不减，体现在控制台上就是堆积越来越严重！

   基于此分析，通过 jstack 查看所有 MQ 消费者线程的状态，的确发现第 251 号线程永远处于 runnable 状态！有理由怀疑，它就是被卡住的消费线程。

   因为在 Proxy 系统的业务场景中，绝大部分耗时都在 RPC 同步调用深度学习模型这个环节（快的几百毫秒，慢的可能要几秒），因此线程大部分时间应该处于等待同步调用返回的 waiting 状态！而此处 251 线程永远是 runnable，一定有问题。

   进一步打印详情，可找到线程卡住的具体代码位置：

   

   这里 getImageDetail 方法内部会通过 HTTP 下载图片，以便深度学习模型进行预估。其次，搜索业务日志也发现，搜不到这个线程的日志。因为从昨晚 10 点开始卡住后，该线程就不会产生任何新的日志了，随着机器日志滚动清理，现在所有日志都将不含该线程的内容。