218 lines
13 KiB
Markdown
218 lines
13 KiB
Markdown
|
||
|
||
因收到Google相关通知，网站将会择期关闭。相关通知内容
|
||
|
||
|
||
18 案例：如何排查RocketMQ消息发送超时故障？
|
||
你好，我是丁威。
|
||
|
||
不知道你在使用 RocketMQ 的时候有没有遇到过让人有些头疼的问题。我在用 RocketMQ 时遇到的最常见，也最让我头疼的问题就是消息发送超时。而且这种超时不是大面积的，而是偶尔会发生，占比在万分之一到万分之五之间。
|
||
|
||
现象与关键日志
|
||
|
||
消息发送超时的情况下，客户端的日志通常是下面这样：
|
||
|
||
|
||
|
||
我们这节课就从这些日志入手，看看怎样排查 RocketMQ 的消息发送超时故障。
|
||
|
||
首先，我们要查看 RocketMQ 相关的日志，在应用服务器上，RocketMQ 的日志默认路径为 ${USER_HOME}/logs/rocketmqlogs/ rocketmq_client.log。
|
||
|
||
在上面这张图中，有两条非常关键的日志。
|
||
|
||
|
||
invokeSync：wait response timeout exception.
|
||
|
||
|
||
它表示等待响应结果超时。
|
||
|
||
|
||
recive response, but not matched any request.
|
||
|
||
|
||
这条日志非常关键，它表示，尽管客户端在获取服务端返回结果时超时了，但客户端最终还是能收到服务端的响应结果，只是此时客户端已经在等待足够时间之后放弃处理了。
|
||
|
||
单一长连接如何实现多请求并发发送？
|
||
|
||
为什么第二条日志超时后还能收到服务端的响应结果，又为什么匹配不到对应的请求了呢？
|
||
|
||
我们可以详细探究一下这背后的原理。原来，这是使用单一长连接进行网络请求的编程范式。举个例子，一条长连接向服务端先后发送了两个请求，客户端在收到服务端响应结果时，需要判断这个响应结果对应的是哪个请求。
|
||
|
||
|
||
|
||
正如上图所示，客户端多个线程通过一条连接依次发送了 req1，req2 两个请求，服务端解码请求后，会将请求转发到线程池中异步执行。如果请求 2 处理得比较快，比请求 1 更早将结果返回给客户端，那客户端怎么识别服务端返回的数据对应的是哪个请求呢？
|
||
|
||
解决办法是，客户端在发送请求之前，会为这个请求生成一个本机器唯一的请求 ID（requestId），它还会采用 Future 模式，将 requestId 和 Future 对象放到一个 Map 中，然后将 reqestId 放入请求体。服务端在返回响应结果时，会将请求 ID 原封不动地放入响应结果中。客户端收到响应时，会先解码出 requestId，然后从缓存中找到对应的 Future 对象，唤醒业务线程，将返回结果通知给调用方，完成整个通信。
|
||
|
||
结合日志我发现，如果客户端在指定时间内没有收到服务端的请求，最终会抛出超时异常。但是，网络层面上客户端还是能收到服务端的响应结果。这就把矛头直接指向了 Broker 端，是不是 Broker 有瓶颈，处理慢导致的呢？
|
||
|
||
如何诊断 Broker 端内存写入性能？
|
||
|
||
我们知道消息发送时，一个非常重要的过程就是服务端写入。如果服务端出现写入瓶颈，通常会返回各种各样的 Broker Busy。我们可以简单来看一下消息发送的写入流程：
|
||
|
||
|
||
|
||
我们首先要判断的是，是不是消息写入 PageCache 或者磁盘写入慢导致的问题。我们这个集群采用的是异步刷盘机制，所以写磁盘这一环可以忽略。
|
||
|
||
然后，我们可以通过跟踪 Broker 端写入 PageCache 的数据指标来判断 Broker 有没有遇到瓶颈。具体做法是查看 RocketMQ 中的 store.log 文件，具体使用命令如下：
|
||
|
||
cd /home/codingw/logs/rocketmqlogs/store.log //其中codingw为当前rocketmq broker进程的归属用户
|
||
grep "PAGECACHERT" store.log
|
||
|
||
|
||
执行命令后，可以得到这样的结果：
|
||
|
||
|
||
|
||
这段日志记录了消息写入到 PageCache 的耗时分布。通过分析我们可以知道，写入 PageCache 的耗时都小于 100ms，所以 PageCache 的写入并没有产生瓶颈。不过，客户端可是真真切切地在 3 秒后才收到响应结果，难道是网络问题？
|
||
|
||
网络层排查通用方法
|
||
|
||
接下来我们就分析一下网络。
|
||
|
||
通常，我们可以用 netstat 命令来分析网络通信，需要重点关注网络通信中的 Recv-Q 与 Send-Q 这两个指标。
|
||
|
||
netstat 命令的执行效果如下图所示：
|
||
|
||
|
||
|
||
解释一下，这里的 Recv-Q 是 TCP 通道的接受缓存区；Send-Q 是 TCP 通道的发送缓存区。
|
||
|
||
在 TCP 中，Recv-Q 和 Send-Q 的工作机制如下图所示：
|
||
|
||
|
||
|
||
正如上图描述的那样，网络通信有下面几个关键步骤。
|
||
|
||
|
||
客户端调用网络通道时（例如 NIO 的 Channel 写入数据），数据首先是写入到 TCP 的发送缓存区，如果发送缓存区已满，客户端无法继续向该通道发送请求，从 NIO 层面调用 Channel 底层的 write 方法的时候会返回 0。这个时候在应用层面需要注册写事件，待发送缓存区有空闲时，再通知上层应用程序继续写入上次未写入的数据。
|
||
|
||
数据进入到发送缓存区后，会随着网络到达目标端。数据首先进入的是目标端的接收缓存区，如果服务端采用事件选择机制的话，通道的读事件会就绪。应用从接收缓存区成功读取到字节后，会发送 ACK 给发送方。
|
||
|
||
发送方在收到 ACK 后，会删除发送缓冲区的数据。如果接收方一直不读取数据，那发送方也无法发送数据。
|
||
|
||
|
||
运维同事分别在客户端和 MQ 服务器上，在服务器上写一个脚本，每 500ms 采集一次 netstat 。最终汇总到的采集结果如下：
|
||
|
||
|
||
|
||
从客户端来看，客户端的 Recv-Q 中出现大量积压，它对应的是 MQ 的 Send-Q 中的大量积压。
|
||
|
||
结合 Recv-Q、Send-Q 的工作机制，再次怀疑可能是客户端从网络中读取字节太慢导致的。为了验证这个观点，我修改了和 RocketMQ Client 相关的包，加入了 Netty 性能采集方面的代码：
|
||
|
||
|
||
|
||
我的核心思路是，针对每一次被触发的读事件，判断客户端会对一个通道进行多少次读取操作。如果一次读事件需要触发很多次的读取，说明这个通道确实积压了很多数据，网络读存在瓶颈。
|
||
|
||
部分采集数据如下：
|
||
|
||
|
||
|
||
我们可以通过 awk 命令对这个数据进行分析。从结果可以看出，一次读事件触发，大部分通道只要读两次就可以成功抽取读缓存区中的数据。读数据方面并不存在瓶颈。
|
||
|
||
统计分析结果如下图所示：
|
||
|
||
|
||
|
||
如此看来，瓶颈应该不在客户端，还是需要将目光转移到服务端。
|
||
|
||
从刚才的分析中我们已经看到，Broker 服务端写入 PageCache 很快。但是刚刚我们唯独没有监控“响应结果写入网络”这个环节。那是不是写入响应结果不及时，导致消息大量积压在 Netty 的写缓存区，不能及时写入到 TCP 的发送缓冲区，最终造成消息发送超时呢？
|
||
|
||
解决方案
|
||
|
||
为了验证这个设想，我最初的打算是改造代码，从 Netty 层面监控服务端的写性能。但这样做的风险比较大，所以我暂时搁置了这个计划，又认真读了一遍 RocketMQ 封装 Netty 的代码。在这之前，我一直以为 RocketMQ 的 网络层基本不需要参数优化，因为公司的服务器都是 64 核心的，而 Netty 的 IO 线程默认都是 CPU 的核数。
|
||
|
||
但这次阅读源码后我发现，RocketMQ 中和 IO 相关的线程参数有两个，分别是 serverSelectorThreads（默认值为 3）和 serverWorkerThreads（默认值为 8）。
|
||
|
||
在 Netty 中，serverSelectorThreads 就是 WorkGroup，即所谓的 IO 线程池。每一个线程池会持有一个 NIO 中的 Selector 对象用来进行事件选择，所有的通道会轮流注册在这 3 个线程中，绑定在一个线程中的所有 Channel 会串行进行网络读写操作。
|
||
|
||
我们的 MQ 服务器的配置，CPU 的核数都在 48C 及以上，用 3 个线程来做这件事显然太“小家子气”，这个参数可以调优。
|
||
|
||
RocketMQ 的网络通信层使用的是 Netty 框架，默认情况下事件的传播（编码、解码）都在 IO 线程中，也就是上面提到的 Selector 对象所在的线程。
|
||
|
||
在 RocketMQ 中 IO 线程就只负责网络读、写，然后将读取到的二进制数据转发到一个线程池处理。这个线程池会负责数据的编码、解码等操作，线程池线程数量由 serverWorkerThreads 指定。
|
||
|
||
看到这里，我开始心潮澎湃了，我感觉自己离真相越来越近了。参考 Netty 将 IO 线程设置为 CPU 核数的两倍，我的第一波优化是让 serverSelectorThreads=16，serverWorkerThreads=32，然后在生产环境中进行一波验证。
|
||
|
||
经过一个多月的验证，在集群数量逐步减少，业务量逐步上升的背景下，我们生产环境的消息发送超时比例达到了十万分之一，基本可以忽略不计。
|
||
|
||
网络超时问题的排查到这里就彻底完成了。但生产环境复杂无比，我们基本无法做到 100% 不出现超时。
|
||
|
||
比方说，虽然调整了 Broker 服务端网络的相关参数，超时问题得到了极大的缓解，但有时候还是会因为一些未知的问题导致网络超时。如果在一定时间内出现大量网络超时，会导致线程资源耗尽，继而影响其他业务的正常执行。
|
||
|
||
所以在这节课的最后我们再从代码层面介绍如何应对消息发送超时。
|
||
|
||
发送超时兜底策略
|
||
|
||
我们在应用中使用消息中间件就是看中了消息中间件的低延迟。但是如果消息发送超时，这就和我们的初衷相违背了。为了尽可能避免这样的问题出现，消息中间件领域解决超时的另一个思路是：增加快速失败的最大等待时长，并减少消息发送的超时时间，增加重试次数。
|
||
|
||
我们来看下具体做法。
|
||
|
||
|
||
增加 Broker 端快速失败的等待时长。这里建议为 1000。在 Broker 的配置文件中增加如下配置：
|
||
|
||
|
||
maxWaitTimeMillsInQueue=1000
|
||
|
||
|
||
|
||
减少超时时间，增加重试次数。
|
||
|
||
|
||
你可能会问，现在已经发生超时了，你还要减少超时时间，那发生超时的概率岂不是更大了？
|
||
|
||
这样做背后的动机是希望客户端尽快超时并快速重试。因为局域网内的网络抖动是瞬时的，下次重试时就能恢复。并且 RocketMQ 有故障规避机制，重试的时候会尽量选择不同的 Broker。
|
||
|
||
执行这个操作的代码和版本有关，如果 RocketMQ 的客户端版本低于 4.3.0，代码如下：
|
||
|
||
DefaultMQProducer producer = new DefaultMQProducer("dw_test_producer_group");
|
||
producer.setNamesrvAddr("127.0.0.1:9876");
|
||
producer.setRetryTimesWhenSendFailed(5);// 同步发送模式：重试次数
|
||
producer.setRetryTimesWhenSendAsyncFailed(5);// 异步发送模式：重试次数
|
||
producer.start();
|
||
producer.send(msg,500);//消息发送超时时间
|
||
|
||
|
||
如果客户端版本是 4.3.0 及以上版本，因为设置的消息发送超时时间是所有重试的总的超时时间，所以不能直接设置 RocketMQ 的发送 API 的超时时间，而是需要对 RocketMQ API 进行包装，例如示例代码如下：
|
||
|
||
public static SendResult send(DefaultMQProducer producer, Message msg, int
|
||
retryCount) {
|
||
Throwable e = null;
|
||
for(int i =0; i < retryCount; i ++ ) {
|
||
try {
|
||
return producer.send(msg,500); //设置超时时间，为 500ms，内部有重试机制
|
||
} catch (Throwable e2) {
|
||
e = e2;
|
||
}
|
||
}
|
||
throw new RuntimeException("消息发送异常",e);
|
||
}
|
||
|
||
|
||
总结
|
||
|
||
好了，我们这节课就介绍到这里了。
|
||
|
||
这节课，我首先抛出一个生产环境中，消息发送环节最容易遇到的问题：消息发送超时问题。我们对日志现象进行了解读，并引出了单一长连接支持多线程网络请求的原理。
|
||
|
||
整个排查过程，我首先判断了一下 Broker 写入 PageCache 是否有瓶颈，然后通过 netstat 命令，以 Recv-Q、Send-Q 两个指标为依据进行了网络方面的排查，最终定位到瓶颈可能在于服务端网络读写模型。通过研读 RocketMQ 的网络模型，我发现了两个至关重要的参数，serverSelectorThreads 和 serverWorkerThreads。其中：
|
||
|
||
|
||
serverSelectorThreads 是 RocketMQ 服务端 IO 线程的个数，默认为 3，建议设置为 CPU 核数；
|
||
|
||
serverWorkerThreads 是 RocketMQ 事件处理线程数，主要承担编码、解码等责任，默认为 8，建议设置为 CPU 核数的两倍。
|
||
|
||
|
||
通过调整这两个参数，我们极大地降低了网络超时发生的概率。
|
||
|
||
不过，发生网络超时的原因是多种多样的，所以我们还介绍了第二种方法，那就是降低超时时间，增加重试的次数，从而降低网络超时对运行时线程的影响，降低系统响应时间。
|
||
|
||
课后题
|
||
|
||
学完今天的内容，我也给你留一道课后题吧。
|
||
|
||
网络通讯在中间件领域非常重要，掌握网络排查相关的知识对线上故障分析有很大的帮助。建议你系统地学习一下 netstat 命令和网络抓包相关技能，分享一下你的经验和困惑。我们下节课见！
|
||
|
||
|
||
|
||
|