RocketMQ问题篇02 | Broker存储过慢异常分析

RocketMQ问题篇01 | Broker存储过慢异常分析

1、问题描述
2、磁盘IO分析（排除硬件问题）
3、刷盘源码分析（排除刷盘逻辑）
4、macloud的告警源代码分析（定位至pageCache有问题）
5、操作系统排查（排除mmap对应操作系统内存分配产生缺页中断、刷盘脏页回写可能导致的情况）
6、结合堆栈日志进一步进行rocketmq源码分析（分析rocketmq中pageCache逻辑）
7、DLedgerCommitLog的逻辑分析（分析rocketmq中DLedger模块pageCache逻辑）
8、[问题解决] Subbmit PR to Github To fixed DLedger pagecachert overtime

1、问题描述

钉钉告警触发时间：2022年7月26日 22:24

钉钉告警触发内容：
在这里插入图片描述
背景描述：发生告警时候排查了另外一台master集群的几点，其正常。

2、磁盘IO分析（排除硬件问题）

   提交了阿里云工单，并通过iostat、iotop等命令监测了磁盘io情况，排除磁盘问题；

在这里插入图片描述

3、刷盘源码分析（排除刷盘逻辑）

线上刷盘的配置
在这里插入图片描述
大总结：broker启动的时候会启动一个异步线程，用于处理消息的刷盘逻辑，（故：告警系统中刷盘超时误导性提示）代码如下：

此处的StoreType比较重要，rocketmq有两种数据处理方式：FILE、MEMORY，公司使用FILE-MMAP机制；

在这里插入图片描述

启动了一个异步线程来执行刷盘逻辑，Thread.sleep(interval);默认配置500ms，读取配置参数syncFlushTimeout以下是具体逻辑：

4、macloud的告警源代码分析（定位至pageCache有问题）

   根据异步刷盘告警，根据第3点刷盘逻辑，其异步操作且没有线程阻塞逻辑，排除异步刷盘逻辑问题；

此处的告警错误：不应该提示刷盘超时，应提示：写入pageCache超时

在这里插入图片描述

5、操作系统排查（排除mmap对应操作系统内存分配产生缺页中断、刷盘脏页回写可能导致的情况）

排查其缺页中断、脏页回写的场景：

步骤1：消息写入：

第一次发消息 -> 生成内存映射文件new MappedFile(nextFilePath, this.mappedFileSize)；--产生缺页中断

第2次发消息 -> 从文件队列获取到mappedFile，追加写入新消息；

第N次发消息 -> 从文件队列获取到mappedFile发现文件已满，生成下一个内存映射文件new MappedFile(nextFilePath, this.mappedFileSize)；--产生缺页中断

步骤2：消息刷盘

 详细见异步刷盘逻辑，攒500毫秒数据，超过16kb则执行刷盘，不够则一直攒数据，10秒后还没攒够16kb数据则强制刷盘；-–产生脏页回写

内存分页监控（https://www.5ibc.net/centos/157.html）

sar -B 1 10 --每1秒采样一次，连续采样10次，监控内存分页：
在这里插入图片描述
输出项说明：
pgpgin/s：表示每秒从磁盘或SWAP置换到内存的字节数(KB)
pgpgout/s：表示每秒从内存置换到磁盘或SWAP的字节数(KB)
fault/s：每秒钟系统产生的缺页数,即主缺页与次缺页之和(major + minor)
majflt/s：每秒钟产生的主缺页数.
pgfree/s：每秒被放入空闲队列中的页个数
pgscank/s：每秒被kswapd扫描的页个数
pgscand/s：每秒直接被扫描的页个数
pgsteal/s：每秒钟从cache中被清除来满足内存需要的页个数
%vmeff：每秒清除的页(pgsteal)占总扫描页(pgscank+pgscand)的百分比

6、结合堆栈日志进一步进行rocketmq源码分析（分析rocketmq中pageCache逻辑）

堆栈日志：根据log日志putMessage not in lock分析，其告警信息会被触发，但是其逻辑实际为page cache，此异常会出现业务端少部分消息无法发送成功（业务也有发送失败日志），根据源码最终定位最有可能的是写入pageCache超时；
在这里插入图片描述
定位至日志打印的代码位置：

final AtomicLong[] times = this.initPutMessageDistributeTime();是返回上次收集的数据，直接打印。
在这里插入图片描述
broker启动时会运行此线程，属于异步打印，60秒执行一次（上图503行）：

分析：[<=0ms]:0 [0~10ms]:4 [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~]:1

final AtomicLong[] times = this.putMessageDistributeTime; 统计各个时间段内的数量，根据不同档位+1计数
long value参数是耗时具体多少毫秒，放入对应的档位中；
在这里插入图片描述
先看一下日志：

elapsedTime耗时高达38秒，放入大于10秒的统计档位中。
putResultFuture.thenAccept会等待this.commitLog.asyncPutMessage(msg);执行完成，所以耗时在这里：

检查commitLog的实现，线上配置走DLedgerCommitLog逻辑，如下。
在这里插入图片描述