一次消息队列堆积问题排查,我把坑踩了个遍!

吉多 2023-08-07 10:23:36

一、背景

 

图片

 

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

 

  • Proxy:提供请求代理服务。统一代理发往下游系统的各类请求,从而让上游系统无需感知下游各服务的使用差异;同时提供精细化的限流、导流等服务特性;

  • 拉图 SDK:面向各存储平台提供统一的图片下载功能。它通常与图像类算法模型被前后编排在一起;

  • 预估引擎:提供模型推理服务。支持各种机器学习、深度学习算法模型的工程部署;

 

二、问题排查

 

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

 

 
1.问题描述

 

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

 

图片

 

 
2.一句话根因

 

先开门见山直接讲问题根因(详细排查流程可参考后文内容):

 

  • 个别机器堆积:该机器有消费线程被卡住,虽然其余线程正常消费,但 MQ 机制决定消费位点并不前进;

  • HTTP 下载卡住:所使用的 HttpClient 版本有 bug,特定情况下超时不生效,可能导致线程一直卡住;

 

 
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 版本后,重新在预发构造测试请求,线程不再卡住,且全部发到线上环境后,近期频繁出现的少量机器堆积问题再也没有出现过。

 

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

 

 
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

 

作者丨吉多 
来源丨公众号:阿里开发者(ID:ali_tech)
dbaplus社群欢迎广大技术人员投稿,投稿邮箱:editor@dbaplus.cn
最新评论
访客 2024年04月08日

如果字段的最大可能长度超过255字节,那么长度值可能…

访客 2024年03月04日

只能说作者太用心了,优秀

访客 2024年02月23日

感谢详解

访客 2024年02月20日

一般干个7-8年(即30岁左右),能做到年入40w-50w;有…

访客 2023年08月20日

230721

活动预告