Rocketmq: Producer wait for broker response when send a message often shows RemotingTimeoutException
As the title,when producer send messages to broker,shows the flowing WARN：
RemotingTimeoutException: wait response on the channel timeout 3000ms.
We excluded network problems by network packet capture.
When producer send A message ,the broker need 4000ms to respond, or even more.This has exceeded the maximum timeout.
I'm sorry I can't go to the email community to discuss it because I'm a Chinese developer, And the community is for me is 404ERROR.
NEED some help,PLEASE.
Thank you Handsome guys.
a619646645
All 9 comments
By the way,this will not happen at the peak of our operations
a619646645
on 13 Nov 2020
Waiting online. It's urgent
在线等,挺急的
a619646645
on 13 Nov 2020
需要查看一下rocketmqlogs下的日志，比如store日志查看一下刷盘时间，或者查看下是否是同步数据慢了，还有查看一下是否有一些明显的error日志
RongtongJin
on 13 Nov 2020
需要查看一下rocketmqlogs下的日志，一些存储日志查看一下刷盘时间，或者查看下是否是同步数据慢了，还有查看一下是否有一些明显的错误日志
您好，感谢您的解答，我在 store.log 发现了如下错误，请问下是这个原因引起的吗？IP我用slaveIP代替了
2020-11-10 18:47:17 WARN ReadSocketService - ha housekeeping, found this connection[/slaveIP:58620] expired, 20020
2020-11-10 18:47:17 INFO ReadSocketService - ReadSocketService service end
2020-11-10 18:47:17 INFO AcceptSocketService - HAService receive new connection, /slaveIP:59356
2020-11-10 18:47:17 INFO ReadSocketService - ReadSocketService service started
2020-11-10 18:47:17 INFO WriteSocketService - WriteSocketService service started
2020-11-10 18:47:17 INFO WriteSocketService - WriteSocketService service end
2020-11-10 18:47:20 INFO StoreStatsService - [STORETPS] put_tps 0.6832877808146124 get_found_tps 0.6832877808146124 get_miss_tps 1.9832011199253383 get_transfered_tps 0.6832877808146124
2020-11-10 18:47:20 INFO StoreStatsService - [PAGECACHERT] TotalPut 38, PutMessageDistributeTime [<=0ms]:15 [0~10ms]:23 [10~50ms]:0 [50~100ms]:0 [100~200ms]:0 [200~500ms]:0 [500ms~1s]:0 [1~2s]:0 [2~3s]:0 [3~4s]:0 [4~5s]:0 [5~10s]:0 [10s~]:0
2020-11-10 18:47:22 INFO ReadSocketService - slave[/10.8.130.121:59356] request offset 1280444295
2020-11-10 18:47:22 INFO WriteSocketService - master transfer data from 1280444295 to slave[/10.8.130.121:59356], and slave request 1280444295
2020-11-10 18:47:22 WARN SendMessageThread_5 - putMessage not in lock eclipse time(ms)=4401, bodyLength=520
2020-11-10 18:47:22 WARN SendMessageThread_44 - putMessage not in lock eclipse time(ms)=4344, bodyLength=497
2020-11-10 18:47:22 WARN SendMessageThread_35 - putMessage not in lock eclipse time(ms)=2453, bodyLength=539
2020-11-10 18:47:22 WARN SendMessageThread_43 - putMessage not in lock eclipse time(ms)=3086, bodyLength=552
同时也在broker.log发现如下错误：
IP 用nameServerIp代替
2020-10-15 15:14:22 WARN main - registerBroker Exception, nameServerIp:9876
org.apache.rocketmq.remoting.exception.RemotingConnectException: connect to <nameServerIp:9876> failed
at org.apache.rocketmq.remoting.netty.NettyRemotingClient.invokeSync(NettyRemotingClient.java:388) ~[rocketmq-remoting-4.2.0-frxs.jar:4.2.0-frxs]
at org.apache.rocketmq.broker.out.BrokerOuterAPI.registerBroker(BrokerOuterAPI.java:167) ~[rocketmq-broker-4.2.0-frxs.jar:4.2.0-frxs]
at org.apache.rocketmq.broker.out.BrokerOuterAPI.registerBrokerAll(BrokerOuterAPI.java:116) ~[rocketmq-broker-4.2.0-frxs.jar:4.2.0-frxs]
at org.apache.rocketmq.broker.BrokerController.registerBrokerAll(BrokerController.java:719) [rocketmq-broker-4.2.0-frxs.jar:4.2.0-frxs]
at org.apache.rocketmq.broker.BrokerController.start(BrokerController.java:681) [rocketmq-broker-4.2.0-frxs.jar:4.2.0-frxs]
at org.apache.rocketmq.broker.BrokerStartup.start(BrokerStartup.java:62) [rocketmq-broker-4.2.0-frxs.jar:4.2.0-frxs]
at org.apache.rocketmq.broker.BrokerStartup.main(BrokerStartup.java:56) [rocketmq-broker-4.2.0-frxs.jar:4.2.0-frxs]
我们现在是双主双从 8C32G的配置，客户端服务端版本都是4.2.0，两个broker都存在这个问题。
同时，通过观察业务端日志，我还发现一个现象：
在出现这个问题之前，某一个broker在大约20S内都没有接收到消息，例如broker-a出现了RemotingTimeoutException，那么在broker-a之前的20s内，他都是没有收到消息的。
@RongtongJin 您能进一步给出排障意见吗？非常感谢！
a619646645
on 14 Nov 2020
putMessage not in lock eclipse
2020-11-10 18:47:22 WARN SendMessageThread_5 - putMessage not in lock eclipse time(ms)=4401, bodyLength=520
2020-11-10 18:47:22 WARN SendMessageThread_44 - putMessage not in lock eclipse time(ms)=4344, bodyLength=497
2020-11-10 18:47:22 WARN SendMessageThread_35 - putMessage not in lock eclipse time(ms)=2453, bodyLength=539
2020-11-10 18:47:22 WARN SendMessageThread_43 - putMessage not in lock eclipse time(ms)=3086, bodyLength=552
这些日志显示某些请求的putMessage时间超过了4s，但从当前日志无法判定是刷盘慢了，还是同步数据数据慢了，又或者是发生了full gc, 可以排查一下broker的gc日志，或者看看store.log中[PAGECACHERT]的统计是否有明显刷盘超时等
RongtongJin
on 14 Nov 2020
这几天在写CURD，这个问题还是存在，
store.log中[PAGECACHERT]的统计存在明显的刷盘超时：
2020-11-18 14:22:05 INFO StoreStatsService - [PAGECACHERT] TotalPut 50, PutMessageDistributeTime [<=0ms]:10 [0~10ms]:35 [10~50ms]:0 [50~100ms]:0 [100~200ms]:0 [200~500ms]:0 [500ms~1s]:1 [1~2s]:1 [2~3s]:1 [3~4s]:0 [4~5s]:2 [5~10s]:0 [10s~]:0
在每次发生这个现象的时候都会出现这些异常：
我们的broker配置如下：
brokerClusterName = DefaultCluster
brokerName = broker-a
brokerId = 0
deleteWhen = 04
fileReservedTime = 48
brokerRole = ASYNC_MASTER
flushDiskType = ASYNC_FLUSH
看PAGECACHERT中有 2--3s:1、4--5s:2 这种明显的超时
2020-11-18 14:21:05 INFO StoreStatsService - [PAGECACHERT] TotalPut 52, PutMessageDistributeTime [<=0ms]:9 [0~10ms]:43 [10~50ms]:0 [50~100ms]:0 [100~200ms]:0 [200~500ms]:0 [500ms~1s]:0 [1~2s]:0 [2~3s]:0 [3~4s]:0 [4~5s]:0 [5~10s]:0 [10s~]:0
2020-11-18 14:21:14 WARN ReadSocketService - ha housekeeping, found this connection[/slaveIP:47894] expired, 20019
2020-11-18 14:21:14 INFO ReadSocketService - ReadSocketService service end
2020-11-18 14:21:14 INFO AcceptSocketService - HAService receive new connection, /slaveIP:33400
2020-11-18 14:21:14 INFO ReadSocketService - ReadSocketService service started
2020-11-18 14:21:14 INFO WriteSocketService - WriteSocketService service started
2020-11-18 14:21:14 INFO WriteSocketService - WriteSocketService service end
2020-11-18 14:21:19 INFO ReadSocketService - slave[/slaveIP:33400] request offset 2235247317
2020-11-18 14:21:19 INFO WriteSocketService - master transfer data from 2235247317 to slave[/slaveIP:33400], and slave request 2235247317
2020-11-18 14:21:19 WARN SendMessageThread_40 - putMessage not in lock eclipse time(ms)=4370, bodyLength=492
2020-11-18 14:21:19 WARN SendMessageThread_37 - putMessage not in lock eclipse time(ms)=4056, bodyLength=466
2020-11-18 14:21:19 WARN SendMessageThread_34 - putMessage not in lock eclipse time(ms)=2280, bodyLength=459
2020-11-18 14:21:19 WARN SendMessageThread_10 - putMessage not in lock eclipse time(ms)=1081, bodyLength=523
2020-11-18 14:21:19 WARN SendMessageThread_28 - putMessage not in lock eclipse time(ms)=719, bodyLength=444
2020-11-18 14:22:05 INFO StoreStatsService - [STORETPS] put_tps 0.8332777814812345 get_found_tps 0.8332777814812345 get_miss_tps 4.466368908739417 get_transfered_tps 0.8332777814812345
2020-11-18 14:22:05 INFO StoreStatsService - [PAGECACHERT] TotalPut 50, PutMessageDistributeTime [<=0ms]:10 [0~10ms]:35 [10~50ms]:0 [50~100ms]:0 [100~200ms]:0 [200~500ms]:0 [500ms~1s]:1 [1~2s]:1 [2~3s]:1 [3~4s]:0 [4~5s]:2 [5~10s]:0 [10s~]:0
GC的情况：
查看了GC的日志，发现GC是没有什么问题的，GC时间都很短而且在RemotingTimeoutException异常发生时没有出现GC
认真研读了Commitlog#putmessage(msg) 的逻辑，同时观察日志没有出现明显的异常，现在似乎是卡在这里了，是不是我们的内存配置，或者是主从交换的配置有什么问题，看到有一个issue：issues428的情况跟我一样，是有关于心跳的问题吗?
@RongtongJin 期待您的回答，万分感谢您！
a619646645
on 19 Nov 2020
这几天在写CURD，这个问题还是存在，
store.log中[PAGECACHERT]的统计存在明显的刷盘超时：
2020-11-18 14:22:05 INFO StoreStatsService - [PAGECACHERT] TotalPut 50, PutMessageDistributeTime [<=0ms]:10 [0~10ms]:35 [10~50ms]:0 [50~100ms]:0 [100~200ms]:0 [200~500ms]:0 [500ms~1s]:1 [1~2s]:1 [2~3s]:1 [3~4s]:0 [4~5s]:2 [5~10s]:0 [10s~]:0在每次发生这个现象的时候都会出现这些异常：
我们的broker配置如下：
brokerClusterName = DefaultCluster brokerName = broker-a brokerId = 0 deleteWhen = 04 fileReservedTime = 48 brokerRole = ASYNC_MASTER flushDiskType = ASYNC_FLUSH看PAGECACHERT中有 2--3s:1、4--5s:2 这种明显的超时
2020-11-18 14:21:05 INFO StoreStatsService - [PAGECACHERT] TotalPut 52, PutMessageDistributeTime [<=0ms]:9 [0~10ms]:43 [10~50ms]:0 [50~100ms]:0 [100~200ms]:0 [200~500ms]:0 [500ms~1s]:0 [1~2s]:0 [2~3s]:0 [3~4s]:0 [4~5s]:0 [5~10s]:0 [10s~]:0 2020-11-18 14:21:14 WARN ReadSocketService - ha housekeeping, found this connection[/slaveIP:47894] expired, 20019 2020-11-18 14:21:14 INFO ReadSocketService - ReadSocketService service end 2020-11-18 14:21:14 INFO AcceptSocketService - HAService receive new connection, /slaveIP:33400 2020-11-18 14:21:14 INFO ReadSocketService - ReadSocketService service started 2020-11-18 14:21:14 INFO WriteSocketService - WriteSocketService service started 2020-11-18 14:21:14 INFO WriteSocketService - WriteSocketService service end 2020-11-18 14:21:19 INFO ReadSocketService - slave[/slaveIP:33400] request offset 2235247317 2020-11-18 14:21:19 INFO WriteSocketService - master transfer data from 2235247317 to slave[/slaveIP:33400], and slave request 2235247317 2020-11-18 14:21:19 WARN SendMessageThread_40 - putMessage not in lock eclipse time(ms)=4370, bodyLength=492 2020-11-18 14:21:19 WARN SendMessageThread_37 - putMessage not in lock eclipse time(ms)=4056, bodyLength=466 2020-11-18 14:21:19 WARN SendMessageThread_34 - putMessage not in lock eclipse time(ms)=2280, bodyLength=459 2020-11-18 14:21:19 WARN SendMessageThread_10 - putMessage not in lock eclipse time(ms)=1081, bodyLength=523 2020-11-18 14:21:19 WARN SendMessageThread_28 - putMessage not in lock eclipse time(ms)=719, bodyLength=444 2020-11-18 14:22:05 INFO StoreStatsService - [STORETPS] put_tps 0.8332777814812345 get_found_tps 0.8332777814812345 get_miss_tps 4.466368908739417 get_transfered_tps 0.8332777814812345 2020-11-18 14:22:05 INFO StoreStatsService - [PAGECACHERT] TotalPut 50, PutMessageDistributeTime [<=0ms]:10 [0~10ms]:35 [10~50ms]:0 [50~100ms]:0 [100~200ms]:0 [200~500ms]:0 [500ms~1s]:1 [1~2s]:1 [2~3s]:1 [3~4s]:0 [4~5s]:2 [5~10s]:0 [10s~]:0GC的情况：
查看了GC的日志，发现GC是没有什么问题的，GC时间都很短而且在RemotingTimeoutException异常发生时没有出现GC
认真研读了Commitlog#putmessage(msg) 的逻辑，同时观察日志没有出现明显的异常，现在似乎是卡在这里了，是不是我们的内存配置，或者是主从交换的配置有什么问题，看到有一个issue：issues428的情况跟我一样，是有关于心跳的问题吗?
@RongtongJin 期待您的回答，万分感谢您！
那就看看是不是磁盘的问题，应该刷盘慢的时间段await, io util也很高，但看起来业务量不大。配置看起来设置比较简单，MQ这边可以调优一下线程数sendMessageThreadPoolNums，开启transientStorePoolEnable减少刷盘毛刺。可以执行下distribution/bin/os.sh脚本优化一下操作系统参数，特别是一些脏页writeback参数、IO请求调度算法等，另外尽量不要使用swap分区，需要通过工具来复现找出具体原因。
和issue428应该没有什么关系，刷盘慢是原因，timeout是结果。
RongtongJin
on 20 Nov 2020
I will close the Issue first, but please feel free to reopen it if you have any other issues.
RongtongJin
on 23 Nov 2020
Related issues
xxd763795151
·
6Comments
xingzheone
·
4Comments
ylh23y
·
3Comments
Switch-vov
·
3Comments
baihezhuo
·
3Comments
Most helpful comment
那就看看是不是磁盘的问题，应该刷盘慢的时间段await, io util也很高，但看起来业务量不大。配置看起来设置比较简单，MQ这边可以调优一下线程数sendMessageThreadPoolNums，开启transientStorePoolEnable减少刷盘毛刺。可以执行下distribution/bin/os.sh脚本优化一下操作系统参数，特别是一些脏页writeback参数、IO请求调度算法等，另外尽量不要使用swap分区，需要通过工具来复现找出具体原因。
和issue428应该没有什么关系，刷盘慢是原因，timeout是结果。