RocketMQ集群突发大量超时问题排查及优化

秒速五厘米 2023-10-15 16:08 39阅读 0赞

## 缘起 ##

访问线上的`RocketMQ`集群的`dashboard`突然上不去了提示超时

![format_png][]

## 初次排查 ##

看报错很清晰可以看到就是`timeout`

所以最简单的是增加了超时时间(我多等一会)，从`5s`增加到`10s`，`15s`

但是发现并没有什么用，还是超时

这时候初步怀疑是网络问题

## 查看RocketMQ log ##

这时候没什么其他办法，只能去服务器上面看看有没有错误log

发现服务器存在大量报错log

java
    
    复制代码
    
    at io.netty.channel.AbstractChannel$AbstractUnsafe.write(ObjectChannelPromise)(Unknown Source) 08-18 19:43:53 ERROR NettyServerNIOSelector_3_2 - Failed to write ressponse[request code: 41, response code: 0, opaque: 166429356] to chanel[id: 0xc0b80baf, L:/192.168.1:30911 R:/192.168.2:56824]

这里可以看到的错误就是`RocketMQ` `broker`一直想要将`client`请求的数据响应给`client`，但是`client`都没有接受这个响应，因为`broker`与`client`之间的连接已经关闭了 大致流程如下

![format_png 1][]

所以这里看到的情况就是服务端一直在报错

`client`一直向`broker`发送请求，但是这些请求`broker`处理了，`client`却在接收响应前断开连接了

这个错误会导致`dashboard`连接不上吗？单看这个log并不能看出问题，我们再看看`RocketMQ`的`remote.log`文件看看，发现有大量的`channelGegistered`

java
    
    复制代码
    
    2023-08-18 20:26:57 INFO NettyServerCodecThread_8 - NETTY SERVER PIPELINE: channelRegistered 192.168.1.12:60912 2023-08-18 20:26:58 INFO NettyServerCodecThread_6 - NETTYSERVER PIPELINE: channelRegistered 192.168.1.12:60914 2023-08-18 20:26:59 INFO NettyServerCodecThread_5 - NETTYSERVER PIPELINE: channelRegistered 192.168.1.12:609968 2023-08-18 20:27:00 INFO NettyServerCodecThread_4 - NETTYSERVER PIPELINE: channelRegistered 192.168.1.12:58374 2023-08-18 20:27:01 INFO NettyServerCodecThread_2 - NETTY SERVER PIPELINE: channelRegistered 192.168.1.12:37832

这里发现有个问题，有个客户端`192.168.1.12`一直在重复注册，也就是重复建立连接

## 猜测可能是BossGroup被打满一直占用着 ##

### RocketMQ 线程池模型 ###

我们知道`RocketMQ`的远程通信线程模型是 1+N+M+M

![format_png 2][]

这一块的线程模型可以给大家看看源码

可以看到`boosGroup`是一个

![format_png 3][]

这里可以看到`workGroup`是多个，实际在`wrokGroup`还有再分多个线程池去处理不同的业务逻辑

![format_png 4][]

由于`boosGroup`是一个，所以存在`boosGroup`被打满的情况，导致`dashboard`连接不上超时

查看linux tcp连接情况

为了确认这个猜想，我这里查看了linux机器上的tcp连接数量

arduino
    
    复制代码
    
    watch -n 1 'netstat -nat | grep ESTABLISHED | wc -l'

会发现打印出来的`tcp`连接数量一直在变化(一直增加又减少)，说明一直在断线重连

## 断线重连问题排查 ##

为什么`client`要一直断线重连呢

这里我们查看源码发现`client`如果发生超时，就会断线。再次请求就需要重新建立连接

![format_png 5][]

我们去查看`broker`的`log`也发现了大量的关闭`socket` `log`

perl
    
    复制代码
    
    invokeSync: close socket because of timeout

## 阿里云 client sdk与开源版本的差异 ##

我们查看源码发现阿里云商业版本的sdk如果超时并不会断开连接

![format_png 6][]

所以只有开源版本才会出现这个问题。

为了解决断线重连的问题，所以`client`添加如下配置

arduino
    
    复制代码
    
    System.setProperty(COM_ROCKETMQ_REMOTING_CLIENT_CLOSE_SOCKET_IF_TIMEOUT, "false");

## client断线重连解决 ##

添加参数后会发现不存在`client`断线重连的log，但是还有如下问题

1.  `dashboard`还是偶尔能连接上
2.  `client`的超时问题并没有解决，只是解决了超时不断线重连
3.  从`broker`仍然存在断线重连

这里还是以为`BossGroup`被打满

由于线上的RocketMQ集群主从同步之间仍然存在断线重连

其次线上RocketMQ 集群不能随便重启，也不能随便修改代码。所以不打算添加`client`之前添加的配置

java
    
    复制代码
    
    System.setProperty(COM_ROCKETMQ_REMOTING_CLIENT_CLOSE_SOCKET_IF_TIMEOUT, "false");

## 再次怀疑是网络问题 ##

这次猜想是可能是主从机器之间网络出了问题

为了更加严谨快速验证，打算用`goland`写一个`client`和`server`进行`tcp`连接，然后仅发送心跳

`server`核心代码如下

![format_png 7][]

*  源码[github][]:[github.com/weihubeats/…][github]

结果验证

![format_png 8][]

可以看到网络耗时都在`1ms`左右，所以其实两台机器网络都没问题

## 怀疑是堆外内存不够、serverSelectorThreads、serverWorkerThreads不够 ##

检查线上的`RocketMQ`部署实际给到的jvm内存为宿主机的90%,但是`RocketMQ`使用使用了大量的堆外内存。

其次在网上看到一篇博文也是遇到类似的问题说是 `serverSelectorThreads`和`serverWorkerThreads`线程池不够

![format_png 9][]

所以又对集群进行了优化

1.  优化JVM启动参数
2.  优化Netty bossGroup为EpollEventLoopGroup
3.  增大serverSelectorThreads和serverWorkerThreads

然后重启部署

结果: 问题还是没解决

![format_png 10][]

## 排除网络问题 ##

每天茶饭不思，突然突发灵感。

我在`broker`这台机器发送请求自己，如果响应还是超时，那么就可以确定不是网络问题

在broker执行如下脚本

shell

复制代码

`./mqadmin getBrokerConfig -n 127.0.0.1:9000 -c xiaozou`

发现还是`broker`自己请求自己 还是超时

所以可以确定**一定不是网络问题**

## 是否gc导致的 ##

检查服务端`gc`、`cpu`、`内存`请求

发现都是非常正常，且低频的，没有任何异常

## arthas加入战场 ##

为了定位到到底是哪里导致的超时，使用了`arthas`进行了方法耗时追踪

![format_png 11][]

发现整个请求基本在240ms就完成了，根本不会超过5s

### 抓取整个逻辑代码的处理 ###

![format_png 12][]

发现代码的耗时只要是在异步转同步

这里实际是又开了一个线程池去处理请求

也就就是1+n+m里面的M

这里初步怀疑是M线程池`(AdminBrokerThread_)`满了导致的

![format_png 13][]

随即使用`arthas`抓取线程池里面的任务

css
    
    复制代码
    
    vmtool --action getInstances --className org.apache.rocketmq.broker.latency.BrokerFixedThreadPoolExecutor --limit 100 --express "instances[5].workQueue.{#this.runnable}" -x 2

然后发现大量堆积任务

再次使用`arthas`看看queue里面堆积了多少个任务

css
    
    复制代码
    
    vmtool --action getInstances --className org.apache.rocketmq.broker.latency.BrokerFixedThreadPoolExecutor --limit 100 --express "instances[5]"

发现`workQueue`还在一直增加

## 总结 ##

这里真相水落石出了，主要是还是`(AdminBrokerThread_)`线程池被打满堆积了太多任务导致的

如何处理呢

1.  增大`(AdminBrokerThread_)`线程池
2.  减少对`(AdminBrokerThread_)`线程池的请求
3.  `(AdminBrokerThread_)`线程池添加监控
4.  broker添加相关的请求限流

[format_png]: https://img-blog.csdnimg.cn/img_convert/6169480352c673dccc2aab07dbab327e.webp?x-oss-process=image/format,png
[format_png 1]: https://img-blog.csdnimg.cn/img_convert/a84a111811b1f39f937530b46ed44ef2.webp?x-oss-process=image/format,png
[format_png 2]: https://img-blog.csdnimg.cn/img_convert/35c56ffebc517aa9c3cd274383f162aa.webp?x-oss-process=image/format,png
[format_png 3]: https://img-blog.csdnimg.cn/img_convert/c59357329fe43a4a21c45962e2404f43.webp?x-oss-process=image/format,png
[format_png 4]: https://img-blog.csdnimg.cn/img_convert/98817df52bff2215af2813f5c4600aad.webp?x-oss-process=image/format,png
[format_png 5]: https://img-blog.csdnimg.cn/img_convert/56ffc6b148af2a583c8eec17c5177908.webp?x-oss-process=image/format,png
[format_png 6]: https://img-blog.csdnimg.cn/img_convert/af2a851d7bc0822b65298a09e785d5bb.webp?x-oss-process=image/format,png
[format_png 7]: https://img-blog.csdnimg.cn/img_convert/9a8dbc6087272532664e95f8bdb97987.webp?x-oss-process=image/format,png
[github]: https://link.juejin.cn?target=https%3A%2F%2Fgithub.com%2Fweihubeats%2Fjava-to-go-learning%2Fblob%2Fmain%2Ftcp-demo%2Fserver%2Fserver.go
[format_png 8]: https://img-blog.csdnimg.cn/img_convert/599183f6349950dcf6a85144e48b7ec7.webp?x-oss-process=image/format,png
[format_png 9]: https://img-blog.csdnimg.cn/img_convert/66776ae7a1aaf07c44846e6cfd9aba4c.webp?x-oss-process=image/format,png
[format_png 10]: https://img-blog.csdnimg.cn/img_convert/33b914293c97226151241c79a0f51644.webp?x-oss-process=image/format,png
[format_png 11]: https://img-blog.csdnimg.cn/img_convert/b27128f025ddf5519d94c29dfbae323a.webp?x-oss-process=image/format,png
[format_png 12]: https://img-blog.csdnimg.cn/img_convert/c9a3fcb74dfaf9b97e0ccac2cb76d0bc.webp?x-oss-process=image/format,png
[format_png 13]: https://img-blog.csdnimg.cn/img_convert/5db0b44c19d8f5935a6f7b1aa78138ed.webp?x-oss-process=image/format,png