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

科技

2023-07-18 01:07

阿里妹导读

本文记录了一次问题的排查过程，从中可以学到不少共性的方法论和经验教训，所以做了提炼归纳。（文末有活动）

一、背景

本次问题涉及的系统链路如上图，各系统的基本职责为：

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

二、问题排查

说明：本文用到的消息队列内部称 MetaQ，外部开源版即为 RocketMQ，下文中统一用 “MQ” 指代。

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、限流导致？

Tip：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 ？

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

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

但排查发现，st 正常，排除这种可能：

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

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

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

由此怀疑：是否因为 Proxy 消费停止 or 消费极慢，导致本地缓存一直是满的，于是 MQ 会停止向 queue 中拉消息，于是 offset 一直没变？

但上文已提到，不管从 MQ 控制台、系统监控指标、机器日志来看，该机器都是正常的，与其余机器没什么区别。那为什么该机器的消费位点就是不动，导致堆积越来越严重？

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

Tip：对于本地缓存中的消息，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 点开始卡住后，该线程就不会产生任何新的日志了，随着机器日志滚动清理，现在所有日志都将不含该线程的内容：

至此，Proxy 系统个别机器 MQ 堆积严重的问题根因找到：该机器的某个消费者线程在通过 HTTP 下载图片时一直卡住，导致整个 queue 的消费位点无法往前推进，从而持续堆积。

8、为什么 HTTP 会一直卡住？

至此，虽然堆积的根因已经找到，且经过尝试短期内可通过应用重启/机器下线等方式临时解决。但长远来看始终存在隐患，因为近期每隔几天时不时就会出现相同问题。需要彻底查清楚 HTTP 卡住的根因，才能从根本上解决本次问题。

通过几次蹲点，捞到了一些会导致线程卡住的图片 URL。发现它们都不是内部的图片地址，且地址也打不开，也不是 jpg 形式结尾的格式：


https://ju1.vmhealthy.cnhttps://978.vmhealthy.cnhttps://xiong.bhjgkjhhb.shop

但问题是，即便是输入这种打不开的极端 URL，由于我们对 HttpClient 设置了 5s 超时，顶多也就会卡住 5s 啊，为什么好像超时机制没生效，一直卡住了十多个小时？

Tip：HTTP 会需要先建立连接，再进行数据传输。由此对应着两种超时：1、连接超时，针对建立连接这一阶段；2、socket 超时，针对数据传输过程中的超时。

经检查，目前代码中只设置了 socket timeout，没设置 connection timeout，因此怀疑上面那些请求直接卡在了前面的 connect 阶段，而又由于没设置 connect 超时，所以请求一直卡住？然而，修改代码后重新尝试请求这些地址，发现还是会一直卡住，需要进一步排查。

9、找到 HTTP 卡住的根因

Tip：找到根因。在特定版本的 HttpClient 中，基于 SSL 连接的请求有 bug：实际会先尝试建立连接，再设置超时时长，先后顺序反了。因此若在连接时卡住，超时还没来得及设置，本次 HTTP 请求就会一直卡下去...

再回过头看上面那几个卡住的 URL，无一例外都是https开头的！破案了，原来是项目用的 HttpClient 有 bug。在升级了 HttpClient 版本后，重新在预发构造测试请求，线程不再卡住，且全部发到线上环境后，近期频繁出现的少量机器堆积问题再也没有出现过。

至此，经历了许多曲折，问题终于彻底解决。

2.4 通盘梳理

从最外层 Proxy 个别机器堆积的表象，不断往内层排查中经历了许多关键节点，直到找到根源。目前所有问题已全部查清，现在站在上帝视角，从内向外完整的因果链条如下：

--> Proxy 系统会基于 HttpClient 去下载图片，然后调用图像类模型做预估

--> 所使用 HttpClient 版本有 bug，在访问 https 地址时，超时不会生效

--> Proxy 系统恰好遇到了少量 https 地址，且恰好卡住（低概率事件），于是会因超时不生效而一直卡住

--> 基于 MQ 的 At Least Once 机制，消费位点将一直停留在卡住消息所对应的 offset 处（尽管其余线程都在正常消费）

--> 上游系统仍然源源不断向 Proxy 发送消息，于是消息只进不出，堆积越来越严重

--> 堆积量超过一定阈值，触发监控报警，用户察觉

三、总结

本次问题的排查过程略微曲折，但也能学到不少共性的方法论和经验教训，在本节统一提炼归纳：

善用排查工具：学会使用 jstack、Arthas、jprofile 等利器，在不同情景下善用合适的工具，能高效地发现异常点，找到线索，从而逐步找到问题根因；
异常的敏感度：有时一些发现问题的线索其实早早就展现在了眼前，但当时因为各种原因（比如最初对问题的疑团很多，未排除的干扰因素多等）导致并不能立马发现线索，还需多积累经验；
广泛查阅资料：除了内网查文档、找相关人员咨询，还要学会去外部英文网站查第一手资料；
困难时要坚持：对一些隐蔽的问题，很多时候不是出现一次就能立马发现问题并解决的。可能需要前前后后经历了几轮排查，最终才能找到根因；
补充底层知识：如果最开始能知道 MQ 的 offset 机制，一些问题就不会走那么多弯路了。后续在用各种中间件的过程中，要多去了解它们的底层原理；
没有玄学问题：代码和机器不会骗人，一切“玄学”问题的背后，都有一套严谨又合理的成因；

参考：

HttpClient Bug：https://issues.apache.org/jira/browse/HTTPCLIENT-1478
Connection timeout v.s Socket timeout：https://stackoverflow.com/questions/7360520/connectiontimeout-versus-sockettimeout

有奖讨论

程序员最害怕遇到的代码错误是什么？你在写代码时最害怕遇到什么样的代码错误？又怎样开展代码问题排查？点击阅读原文来阿里云开发者社区分享你的观点吧，参与讨论即有机会获得精美礼品哦～

微信扫码关注该文公众号作者

戳这里提交新闻线索和高质量文章给我们。

来源: qq

点击查看作者最近其他文章