DLedger pagecachert overtime

[yewenhai-github]

1. Please describe the issue you observed:
   4.9.1版本DLedger，有时消息会出现超时特别严重现象，日志中38秒延迟。

2. Please tell us about your environment:
   生产环境，DLedger1主2从模式，使用默认的mmap模式。

3. Other information (e.g. detailed explanation, logs, related issues, suggestions on how to fix, etc):
   项目钉钉告警会抓取PutMessageDistributeTime的broker分析数据，对于超过200ms以上的数据进行告警，监控到10s以上的告警比较频繁，比如图中的38秒告警，在此期间是没有任何数据写入的。

store.log
2022-07-26 22:23:13 WARN QuorumAckChecker-n1 - putMessage not in lock elapsed time(ms)=38044, bodyLength=179
2022-07-26 22:23:45 INFO StoreStatsService - [STORETPS] put_tps 0.08331944675887352 get_found_tps 0.06665555740709882 get_miss_tps 8.765205799033494 get_transfered_tps 0.06665555740709882
2022-07-26 22:23:45 INFO StoreStatsService - [PAGECACHERT] TotalPut 5, PutMessageDistributeTime [<=0ms]:0 [010ms]:4 [1050ms]:0 [50100ms]:0 [100200ms]:0 [200500ms]:0 [500ms1s]:0 [12s]:0 [23s]:0 [34s]:0 [45s]:0 [510s]:0 **[10s]:1**

store.log

broker_default.log 3个broker的水位线日志

问题定位
1、定位日志打印位置：****INFO StoreStatsService - [PAGECACHERT] ***
broker启动时会运行此线程StoreStatsService.run()，60秒执行一次异步打印；

2、定位堵塞代码位置：
putResultFuture.thenAccept会等待this.commitLog.asyncPutMessage(msg);执行完成，所以耗时的38秒在这里；

写入一条数据时，会生成一个AppendFuture，等待QuorumAckChecker异步进程来AppendFuture.complete响应；

3、DLedger数据同步、ACK逻辑分析
主从数据同步：数据写入时触发DLedgerMmapFileStore.appendAsLeader方法ledgerEndIndex++时，DLedger数据同步触发，DLedgerEntryPusher.EntryDispatcher.dowork将主数据同步给从并更新从的水位线。
QuorumAckChecker.doWork()移除peerWaterMarksByTerm内的临时数据逻辑中，此时如果写入的数据并未放入peerWaterMarksByTerm时（下图，qa环境中加入了休眠随机1-10秒验证，可以复现此现象），那么将会走if（future == null）逻辑转补偿逻辑，补偿(futureEntry.getKey() < quorumIndex)不会处理此数据，lastQuorumIndex更新为最新水位线，在此期间如果没有数据写入，那么一直走检查超时的逻辑，但超时逻辑从quorumIndex + 1开始检查，补偿逻辑又只处理<quorumIndex的数据，完美的错过了futureEntry.getKey() = quorumIndex的场景，造成此数据只能等待下一次数据来冲洗。

4、修复方案
补偿逻辑中：if (futureEntry.getKey() < quorumIndex) 更改为 if (futureEntry.getKey() <= quorumIndex)
更好的方案可以在放入地方处理，但那会比较影响性能。

5、同事给的对于 if (futureEntry.getKey() <= quorumIndex) 更改后，对于此类数据的处理截图效果

the same to rocketmq issues：apache/rocketmq#4814

[RongtongJin]

Hi @yewenhai-github could you submit a pull request to fix the issue?

[dongeforever]

@yewenhai-github 为啥future会为null呢？这个根因可以再找一下哈。
目前用一个leakCheck逻辑来修复是一个 walk around的方案，不是特别理想哈。

[yewenhai-github]

你好： &nbsp; &nbsp; 从ledgerEndIndex++;开始触发主从数据同步、ack更新完lastQuorumIndex时，pendingAppendResponsesByTerm.get(entry.getTerm()).put(entry.getIndex(), future);还未放入； 原因是此处三个线程是并行的，写入线程用了两次synchronized，应该是jvm释放锁较慢导致，即使没有synchronized的效率问题，也不能完全保证主从复制与ack不比他们快。&nbsp; 如果需要更严谨的逻辑处理：其实应该从根源上解决ack时future为null的情况，比如只有pendingAppendResponsesByTerm put成功之后才能触发最新这一条数据的主从复制逻辑。 其实此处还有一个缺陷，就是此类场景的数据，必须等到1秒后的补偿逻辑进行，其实还是会造成写入过慢的情况，即1秒。

…

------------------&nbsp;原始邮件&nbsp;------------------ 发件人: "openmessaging/dledger" ***@***.***&gt;; 发送时间:&nbsp;2022年8月15日(星期一) 下午4:00 ***@***.***&gt;; ***@***.******@***.***&gt;; 主题:&nbsp;Re: [openmessaging/dledger] DLedger pagecachert overtime (Issue #199) @yewenhai-github 为啥future会为null呢？这个根因可以再找一下哈。 目前用一个leakCheck逻辑来修复是一个 walk around的方案，不是特别理想哈。 — Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you were mentioned.Message ID: ***@***.***&gt;

[dongeforever]

@yewenhai-github 嗯嗯 这里有并发问题，有可能EntryPusher的执行更快，导致updatePeerWaterMark快于pendingAppendResponsesByTerm put。

可以加一个逻辑，给 EntryPusher 加一个变量，maxAllowedPushIndex，由append线程来更新。

EntryPusher判断一下 writeIndex 和 maxAllowedPushIndex 的大小，如果小于，就不push。