sofastack / sofa-jraft

A production-grade java implementation of RAFT consensus algorithm.
https://www.sofastack.tech/projects/sofa-jraft/
Apache License 2.0
3.62k stars 1.15k forks source link

leader内存持续膨胀问题排查 #833

Closed tsgmq closed 2 years ago

tsgmq commented 2 years ago

Your question

5台机器组成的集群,4台follower内存非常稳定,但是leader内存却持续膨胀,dump下来是leader给4个follower同步logEntry的线程,ThreadLocal中的内容貌似没有释放 以下是follower内存情况 [2022-05-18T01:32:59.622+0000][26023][gc] GC(1797) Garbage Collection (Timer) 1186M(4%)->414M(1%) [2022-05-18T01:33:29.720+0000][26023][gc] GC(1798) Garbage Collection (Timer) 1260M(4%)->420M(1%) [2022-05-18T01:33:59.822+0000][26023][gc] GC(1799) Garbage Collection (Timer) 1308M(4%)->422M(1%) [2022-05-18T01:34:29.920+0000][26023][gc] GC(1800) Garbage Collection (Timer) 1160M(4%)->416M(1%) [2022-05-18T01:35:00.023+0000][26023][gc] GC(1801) Garbage Collection (Timer) 1134M(3%)->478M(1%) [2022-05-18T01:35:30.122+0000][26023][gc] GC(1802) Garbage Collection (Timer) 1200M(4%)->446M(1%) [2022-05-18T01:36:00.223+0000][26023][gc] GC(1803) Garbage Collection (Timer) 1160M(4%)->458M(1%) [2022-05-18T01:36:30.322+0000][26023][gc] GC(1804) Garbage Collection (Timer) 1194M(4%)->464M(1%) [2022-05-18T01:37:00.424+0000][26023][gc] GC(1805) Garbage Collection (Timer) 1230M(4%)->420M(1%) [2022-05-18T01:37:30.522+0000][26023][gc] GC(1806) Garbage Collection (Timer) 1226M(4%)->464M(1%)

以下是leader内存回收情况 [2022-05-18T01:33:59.857+0000][25829][gc] GC(2126) Garbage Collection (Timer) 15554M(47%)->7308M(22%) [2022-05-18T01:34:30.225+0000][25829][gc] GC(2127) Garbage Collection (Timer) 17592M(54%)->7654M(23%) [2022-05-18T01:35:00.552+0000][25829][gc] GC(2128) Garbage Collection (Timer) 14564M(44%)->7436M(23%) [2022-05-18T01:35:30.952+0000][25829][gc] GC(2129) Garbage Collection (Timer) 19306M(59%)->7784M(24%) [2022-05-18T01:36:01.226+0000][25829][gc] GC(2130) Garbage Collection (Timer) 13966M(43%)->7410M(23%) [2022-05-18T01:36:31.541+0000][25829][gc] GC(2131) Garbage Collection (Timer) 14554M(44%)->7404M(23%) [2022-05-18T01:37:01.842+0000][25829][gc] GC(2132) Garbage Collection (Timer) 14676M(45%)->7384M(23%) [2022-05-18T01:37:32.134+0000][25829][gc] GC(2133) Garbage Collection (Timer) 14304M(44%)->7370M(22%) [2022-05-18T01:38:02.449+0000][25829][gc] GC(2134) Garbage Collection (Timer) 14834M(45%)->7406M(23%) [2022-05-18T01:38:32.770+0000][25829][gc] GC(2135) Garbage Collection (Timer) 16140M(49%)->7520M(23%)

以下是从leader机器dump的内存占用情况 image

image

leader的metrics信息 thread_pool_metrics.log.2022-05-18_01-00-51.txt node_metrics.log.2022-05-18_01-00-51.txt node_describe.log.2022-05-18_01-00-51.txt

Environment

killme2008 commented 2 years ago

应该会稳定在一个水位,因为用了 netty 的 threadlocal bytebuffer 缓存池。可以继续观察下。

tsgmq commented 2 years ago

我目前disruptorBufferSize设置的131072,默认值是16384,如果我调小disruptorBufferSize的值,会减少内存占用么?另外出现线程池不够用的问题了,是否跟哪儿处理的卡顿有关系,我们本次使用的1.3.10,是阻塞式提交task 2022-05-16T21:00:05.221655Z ERROR [JRaft-NodeImpl-Disruptor-0] util.LogExceptionHandler - [,-]Handle NodeImpl disruptor event error, event is com.alipay.sofa.jraft.core.NodeImpl$LogEntryAndClosure@70264d42 java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@5e946176[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@7e96d231[Wrapped task = com.alipay.sofa.jraft.storage.impl.LogManagerImpl$$Lambda$1662/0x00000008019f8488@72834c01]] rejected from com.alipay.sofa.jraft.util.MetricThreadPoolExecutor@771d079b[Running, pool size = 240, active threads = 240, queued tasks = 0, completed tasks = 20658273] at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2065) ~[?:?] at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:833) ~[?:?] at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1365) ~[?:?] at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:123) ~[?:?] at com.alipay.sofa.jraft.util.Utils.runInThread(Utils.java:172) ~[jraft-core-1.3.10.jar!/:?] at com.alipay.sofa.jraft.storage.impl.LogManagerImpl.wakeupAllWaiter(LogManagerImpl.java:397) ~[jraft-core-1.3.10.jar!/:?] at com.alipay.sofa.jraft.storage.impl.LogManagerImpl.appendEntries(LogManagerImpl.java:334) ~[jraft-core-1.3.10.jar!/:?] at com.alipay.sofa.jraft.core.NodeImpl.executeApplyingTasks(NodeImpl.java:1399) ~[jraft-core-1.3.10.jar!/:?] at com.alipay.sofa.jraft.core.NodeImpl.access$300(NodeImpl.java:139) ~[jraft-core-1.3.10.jar!/:?] at com.alipay.sofa.jraft.core.NodeImpl$LogEntryAndClosureHandler.onEvent(NodeImpl.java:309) ~[jraft-core-1.3.10.jar!/:?] at com.alipay.sofa.jraft.core.NodeImpl$LogEntryAndClosureHandler.onEvent(NodeImpl.java:289) ~[jraft-core-1.3.10.jar!/:?] at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:168) [disruptor-3.4.2.jar!/:?] at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125) [disruptor-3.4.2.jar!/:?] at java.lang.Thread.run(Thread.java:833) [?:?]

killme2008 commented 2 years ago

卡顿不大可能,很可能是单个 raft group 的吞吐到上限了,建议观察下各项 metric 。调小 disruptor 可以缓解内存问题,但是吞吐也可能下降(缓冲区减少了)

killme2008 commented 2 years ago

可以调下这个参数 jraft.max_collector_size_per_thread

https://github.com/sofastack/sofa-jraft/blob/e91e660144db852e4a2a62435e6c40a044c4b4cb/jraft-core/src/main/java/com/alipay/sofa/jraft/util/Utils.java#L253

tsgmq commented 2 years ago

metic我也放了详细信息了。看看能否打开,我们总共10个group,这个是其中的一个,吞吐不是问题,我们现在10s才写一次,理论上来说应该毫无压力才对,只是现在每10s写入的logEntry包比较大,达到3M左右,不知道这些是否需要调整rocksDB参数来适配这样大的logEntry thread_pool_metrics.log.2022-05-18_01-00-51.txt 5/18/22, 1:00:51 AM ============================================================

-- Timers ---------------------------------------------------------------------- scheduledThreadPool.JRaft-Node-ScheduleThreadPool count = 689105 mean rate = 13.23 calls/second 1-minute rate = 13.21 calls/second 5-minute rate = 13.22 calls/second 15-minute rate = 13.22 calls/second min = 0.00 milliseconds max = 0.04 milliseconds mean = 0.01 milliseconds stddev = 0.00 milliseconds median = 0.01 milliseconds 75% <= 0.01 milliseconds 95% <= 0.01 milliseconds 98% <= 0.01 milliseconds 99% <= 0.02 milliseconds 99.9% <= 0.03 milliseconds threadPool.JRAFT_CLOSURE_EXECUTOR count = 817798 mean rate = 15.58 calls/second 1-minute rate = 24.34 calls/second 5-minute rate = 24.07 calls/second 15-minute rate = 24.12 calls/second min = 0.54 milliseconds max = 280.40 milliseconds mean = 2.16 milliseconds stddev = 8.48 milliseconds median = 1.72 milliseconds 75% <= 2.16 milliseconds 95% <= 2.62 milliseconds 98% <= 3.35 milliseconds 99% <= 3.37 milliseconds 99.9% <= 4.10 milliseconds threadPool.JRAFT_RPC_CLOSURE_EXECUTOR count = 689105 mean rate = 13.23 calls/second 1-minute rate = 13.21 calls/second 5-minute rate = 13.22 calls/second 15-minute rate = 13.22 calls/second min = 0.02 milliseconds max = 2.51 milliseconds mean = 1.02 milliseconds stddev = 0.32 milliseconds median = 0.88 milliseconds 75% <= 1.35 milliseconds 95% <= 1.55 milliseconds 98% <= 1.65 milliseconds 99% <= 1.70 milliseconds 99.9% <= 1.80 milliseconds threadPool.JRaft-RPC-Processor count = 6 mean rate = 0.00 calls/second 1-minute rate = 0.00 calls/second 5-minute rate = 0.00 calls/second 15-minute rate = 0.00 calls/second min = 0.00 milliseconds max = 0.00 milliseconds mean = 0.00 milliseconds stddev = 0.00 milliseconds median = 0.00 milliseconds 75% <= 0.00 milliseconds 95% <= 0.00 milliseconds 98% <= 0.00 milliseconds 99% <= 0.00 milliseconds 99.9% <= 0.00 milliseconds

tsgmq commented 2 years ago

node_metrics.log.2022-05-18_01-00-51.txt -- <demo-app-zone00/demo-app03.zone00.sgc.test.net:19527::1> 5/18/22, 1:00:51 AM ============================================================

-- <demo-app-zone00/demo-app03.zone00.sgc.test.net:19527::1> -- Gauges ---------------------------------------------------------------------- jraft-fsm-caller-disruptor.buffer-size value = 131072 jraft-fsm-caller-disruptor.remaining-capacity value = 131072 jraft-leader-listener value = true jraft-log-manager-disruptor.buffer-size value = 131072 jraft-log-manager-disruptor.remaining-capacity value = 131072 jraft-node-impl-disruptor.buffer-size value = 131072 jraft-node-impl-disruptor.remaining-capacity value = 131072 jraft-node-info-applyIndex value = 3307577032 jraft-node-info-commitIndex value = 3307577032 jraft-node-info-currTerm value = 13 jraft-node-info-logIndex value = 3307577032 jraft-node-info-snapshotIndex value = 3307577003 jraft-node-info-snapshotLogSize value = 599670849 jraft-node-info-snapshotSize value = 9535500 jraft-read-only-service-disruptor.buffer-size value = 131072 jraft-read-only-service-disruptor.remaining-capacity value = 131072 raft-rpc-client-thread-pool.active value = 0 raft-rpc-client-thread-pool.completed value = 6 raft-rpc-client-thread-pool.pool-size value = 6 raft-rpc-client-thread-pool.queued value = 0 raft-utils-closure-thread-pool.active value = 0 raft-utils-closure-thread-pool.completed value = 817798 raft-utils-closure-thread-pool.pool-size value = 48 raft-utils-closure-thread-pool.queued value = 0 replicator-demo-app-zone00/demo-app00.zone00.sga.test.net:19527.append-entries-times value = 30182 replicator-demo-app-zone00/demo-app00.zone00.sga.test.net:19527.heartbeat-times value = 172127 replicator-demo-app-zone00/demo-app00.zone00.sga.test.net:19527.install-snapshot-times value = 0 replicator-demo-app-zone00/demo-app00.zone00.sga.test.net:19527.log-lags value = 0 replicator-demo-app-zone00/demo-app00.zone00.sga.test.net:19527.next-index value = 3307577033 replicator-demo-app-zone00/demo-app00.zone00.sga.test.net:19527.probe-times value = 13 replicator-demo-app-zone00/demo-app01.zone00.sga.test.net:19527.append-entries-times value = 30189 replicator-demo-app-zone00/demo-app01.zone00.sga.test.net:19527.heartbeat-times value = 172222 replicator-demo-app-zone00/demo-app01.zone00.sga.test.net:19527.install-snapshot-times value = 0 replicator-demo-app-zone00/demo-app01.zone00.sga.test.net:19527.log-lags value = 0 replicator-demo-app-zone00/demo-app01.zone00.sga.test.net:19527.next-index value = 3307577033 replicator-demo-app-zone00/demo-app01.zone00.sga.test.net:19527.probe-times value = 9 replicator-demo-app-zone00/demo-app02.zone00.sgb.test.net:19527.append-entries-times value = 30189 replicator-demo-app-zone00/demo-app02.zone00.sgb.test.net:19527.heartbeat-times value = 172222 replicator-demo-app-zone00/demo-app02.zone00.sgb.test.net:19527.install-snapshot-times value = 0 replicator-demo-app-zone00/demo-app02.zone00.sgb.test.net:19527.log-lags value = 0 replicator-demo-app-zone00/demo-app02.zone00.sgb.test.net:19527.next-index value = 3307577033 replicator-demo-app-zone00/demo-app02.zone00.sgb.test.net:19527.probe-times value = 10 replicator-demo-app-zone00/demo-app04.zone00.sgc.test.net:19527.append-entries-times value = 30191 replicator-demo-app-zone00/demo-app04.zone00.sgc.test.net:19527.heartbeat-times value = 172496 replicator-demo-app-zone00/demo-app04.zone00.sgc.test.net:19527.install-snapshot-times value = 0 replicator-demo-app-zone00/demo-app04.zone00.sgc.test.net:19527.log-lags value = 0 replicator-demo-app-zone00/demo-app04.zone00.sgc.test.net:19527.next-index value = 3307577033 replicator-demo-app-zone00/demo-app04.zone00.sgc.test.net:19527.probe-times value = 11

-- <demo-app-zone00/demo-app03.zone00.sgc.test.net:19527::1> -- Histograms ------------------------------------------------------------------ append-logs-bytes count = 30409 min = 33 max = 3439625 mean = 1592658.22 stddev = 454333.07 median = 1391314.00 75% <= 1592734.00 95% <= 2667523.00 98% <= 2769405.00 99% <= 2797192.00 99.9% <= 3026009.00 append-logs-count count = 30409 min = 1 max = 2 mean = 1.00 stddev = 0.03 median = 1.00 75% <= 1.00 95% <= 1.00 98% <= 1.00 99% <= 1.00 99.9% <= 1.00 fsm-apply-tasks-count count = 30386 min = 1 max = 2 mean = 1.00 stddev = 0.03 median = 1.00 75% <= 1.00 95% <= 1.00 98% <= 1.00 99% <= 1.00 99.9% <= 1.00 handle-append-entries-count count = 207 min = 0 max = 0 mean = 0.00 stddev = 0.00 median = 0.00 75% <= 0.00 95% <= 0.00 98% <= 0.00 99% <= 0.00 99.9% <= 0.00 replicate-entries-bytes count = 120747 min = 1177852 max = 3439625 mean = 1592397.68 stddev = 453739.99 median = 1391314.00 75% <= 1592734.00 95% <= 2667523.00 98% <= 2769405.00 99% <= 2797192.00 99.9% <= 3017651.00 replicate-entries-count count = 120747 min = 1 max = 2 mean = 1.00 stddev = 0.03 median = 1.00 75% <= 1.00 95% <= 1.00 98% <= 1.00 99% <= 1.00 99.9% <= 1.00 replicator-demo-app-zone00/demo-app00.zone00.sga.test.net:19527.replicate-inflights-count count = 30195 min = 1 max = 2 mean = 1.00 stddev = 0.00 median = 1.00 75% <= 1.00 95% <= 1.00 98% <= 1.00 99% <= 1.00 99.9% <= 1.00 replicator-demo-app-zone00/demo-app01.zone00.sga.test.net:19527.replicate-inflights-count count = 30198 min = 1 max = 2 mean = 1.00 stddev = 0.00 median = 1.00 75% <= 1.00 95% <= 1.00 98% <= 1.00 99% <= 1.00 99.9% <= 1.00 replicator-demo-app-zone00/demo-app02.zone00.sgb.test.net:19527.replicate-inflights-count count = 30199 min = 1 max = 2 mean = 1.00 stddev = 0.00 median = 1.00 75% <= 1.00 95% <= 1.00 98% <= 1.00 99% <= 1.00 99.9% <= 1.00 replicator-demo-app-zone00/demo-app04.zone00.sgc.test.net:19527.replicate-inflights-count count = 30202 min = 1 max = 2 mean = 1.00 stddev = 0.00 median = 1.00 75% <= 1.00 95% <= 1.00 98% <= 1.00 99% <= 1.00 99.9% <= 1.00

-- <demo-app-zone00/demo-app03.zone00.sgc.test.net:19527::1> -- Timers ---------------------------------------------------------------------- append-logs count = 30409 mean rate = 0.58 calls/second 1-minute rate = 0.57 calls/second 5-minute rate = 0.57 calls/second 15-minute rate = 0.58 calls/second min = 0.00 milliseconds max = 10.00 milliseconds mean = 4.22 milliseconds stddev = 1.39 milliseconds median = 4.00 milliseconds 75% <= 5.00 milliseconds 95% <= 7.00 milliseconds 98% <= 8.00 milliseconds 99% <= 8.00 milliseconds 99.9% <= 9.00 milliseconds fsm-apply-tasks count = 30386 mean rate = 0.58 calls/second 1-minute rate = 0.58 calls/second 5-minute rate = 0.57 calls/second 15-minute rate = 0.58 calls/second min = 0.00 milliseconds max = 16.00 milliseconds mean = 5.15 milliseconds stddev = 1.21 milliseconds median = 5.00 milliseconds 75% <= 5.00 milliseconds 95% <= 8.00 milliseconds 98% <= 8.00 milliseconds 99% <= 8.00 milliseconds 99.9% <= 10.00 milliseconds fsm-commit count = 30387 mean rate = 0.58 calls/second 1-minute rate = 0.58 calls/second 5-minute rate = 0.57 calls/second 15-minute rate = 0.58 calls/second min = 0.00 milliseconds max = 17.00 milliseconds mean = 5.18 milliseconds stddev = 1.21 milliseconds median = 5.00 milliseconds 75% <= 5.00 milliseconds 95% <= 8.00 milliseconds 98% <= 8.00 milliseconds 99% <= 8.00 milliseconds 99.9% <= 10.00 milliseconds fsm-snapshot-load count = 1 mean rate = 0.00 calls/second 1-minute rate = 0.00 calls/second 5-minute rate = 0.00 calls/second 15-minute rate = 0.00 calls/second min = 0.00 milliseconds max = 0.00 milliseconds mean = 0.00 milliseconds stddev = 0.00 milliseconds median = 0.00 milliseconds 75% <= 0.00 milliseconds 95% <= 0.00 milliseconds 98% <= 0.00 milliseconds 99% <= 0.00 milliseconds 99.9% <= 0.00 milliseconds fsm-snapshot-save count = 437 mean rate = 0.01 calls/second 1-minute rate = 0.01 calls/second 5-minute rate = 0.01 calls/second 15-minute rate = 0.01 calls/second min = 0.00 milliseconds max = 1.00 milliseconds mean = 0.00 milliseconds stddev = 0.03 milliseconds median = 0.00 milliseconds 75% <= 0.00 milliseconds 95% <= 0.00 milliseconds 98% <= 0.00 milliseconds 99% <= 0.00 milliseconds 99.9% <= 0.00 milliseconds fsm-start-following count = 1 mean rate = 0.00 calls/second 1-minute rate = 0.00 calls/second 5-minute rate = 0.00 calls/second 15-minute rate = 0.00 calls/second min = 0.00 milliseconds max = 0.00 milliseconds mean = 0.00 milliseconds stddev = 0.00 milliseconds median = 0.00 milliseconds 75% <= 0.00 milliseconds 95% <= 0.00 milliseconds 98% <= 0.00 milliseconds 99% <= 0.00 milliseconds 99.9% <= 0.00 milliseconds fsm-stop-following count = 1 mean rate = 0.00 calls/second 1-minute rate = 0.00 calls/second 5-minute rate = 0.00 calls/second 15-minute rate = 0.00 calls/second min = 0.00 milliseconds max = 0.00 milliseconds mean = 0.00 milliseconds stddev = 0.00 milliseconds median = 0.00 milliseconds 75% <= 0.00 milliseconds 95% <= 0.00 milliseconds 98% <= 0.00 milliseconds 99% <= 0.00 milliseconds 99.9% <= 0.00 milliseconds handle-append-entries count = 208 mean rate = 0.00 calls/second 1-minute rate = 0.00 calls/second 5-minute rate = 0.00 calls/second 15-minute rate = 0.00 calls/second min = 0.00 milliseconds max = 0.00 milliseconds mean = 0.00 milliseconds stddev = 0.00 milliseconds median = 0.00 milliseconds 75% <= 0.00 milliseconds 95% <= 0.00 milliseconds 98% <= 0.00 milliseconds 99% <= 0.00 milliseconds 99.9% <= 0.00 milliseconds handle-heartbeat-requests count = 1222 mean rate = 0.02 calls/second 1-minute rate = 0.00 calls/second 5-minute rate = 0.00 calls/second 15-minute rate = 0.00 calls/second min = 0.00 milliseconds max = 0.00 milliseconds mean = 0.00 milliseconds stddev = 0.00 milliseconds median = 0.00 milliseconds 75% <= 0.00 milliseconds 95% <= 0.00 milliseconds 98% <= 0.00 milliseconds 99% <= 0.00 milliseconds 99.9% <= 0.00 milliseconds pre-vote count = 3 mean rate = 0.00 calls/second 1-minute rate = 0.00 calls/second 5-minute rate = 0.00 calls/second 15-minute rate = 0.00 calls/second min = 0.00 milliseconds max = 0.00 milliseconds mean = 0.00 milliseconds stddev = 0.00 milliseconds median = 0.00 milliseconds 75% <= 0.00 milliseconds 95% <= 0.00 milliseconds 98% <= 0.00 milliseconds 99% <= 0.00 milliseconds 99.9% <= 0.00 milliseconds replicate-entries count = 120747 mean rate = 2.32 calls/second 1-minute rate = 2.24 calls/second 5-minute rate = 2.27 calls/second 15-minute rate = 2.29 calls/second min = 5.00 milliseconds max = 22.00 milliseconds mean = 9.39 milliseconds stddev = 2.76 milliseconds median = 9.00 milliseconds 75% <= 10.00 milliseconds 95% <= 16.00 milliseconds 98% <= 17.00 milliseconds 99% <= 17.00 milliseconds 99.9% <= 18.00 milliseconds request-vote count = 3 mean rate = 0.00 calls/second 1-minute rate = 0.00 calls/second 5-minute rate = 0.00 calls/second 15-minute rate = 0.00 calls/second min = 0.00 milliseconds max = 0.00 milliseconds mean = 0.00 milliseconds stddev = 0.00 milliseconds median = 0.00 milliseconds 75% <= 0.00 milliseconds 95% <= 0.00 milliseconds 98% <= 0.00 milliseconds 99% <= 0.00 milliseconds 99.9% <= 0.00 milliseconds save-raft-meta count = 1 mean rate = 0.00 calls/second 1-minute rate = 0.00 calls/second 5-minute rate = 0.00 calls/second 15-minute rate = 0.00 calls/second min = 0.00 milliseconds max = 0.00 milliseconds mean = 0.00 milliseconds stddev = 0.00 milliseconds median = 0.00 milliseconds 75% <= 0.00 milliseconds 95% <= 0.00 milliseconds 98% <= 0.00 milliseconds 99% <= 0.00 milliseconds 99.9% <= 0.00 milliseconds truncate-log-prefix count = 437 mean rate = 0.01 calls/second 1-minute rate = 0.01 calls/second 5-minute rate = 0.01 calls/second 15-minute rate = 0.01 calls/second min = 0.00 milliseconds max = 4.00 milliseconds mean = 0.00 milliseconds stddev = 0.06 milliseconds median = 0.00 milliseconds 75% <= 0.00 milliseconds 95% <= 0.00 milliseconds 98% <= 0.00 milliseconds 99% <= 0.00 milliseconds 99.9% <= 0.00 milliseconds

tsgmq commented 2 years ago

node_describe.log.2022-05-18_01-00-51.txt nodeId: <test-app-zone00/test-app03.zone00.sgc.test.net:19527::1> state: STATE_LEADER leaderId: test-app03.zone00.sgc.test.net:19527::1 term: 13 conf: ConfigurationEntry [id=LogId [index=3307577003, term=13], conf=test-app04.zone00.sgc.test.net:19527,test-app03.zone00.sgc.test.net:19527,test-app02.zone00.sgb.test.net:19527,test-app01.zone00.sga.test.net:19527,test-app00.zone00.sga.test.net:19527, oldConf=] targetPriority: -1 electionTimer: RepeatedTimer{timeout=null, stopped=true, running=false, destroyed=false, invoking=false, timeoutMs=3000, name='JRaft-ElectionTimer-<test-app-zone00/test-app03.zone00.sgc.test.net:19527::1>'} voteTimer: RepeatedTimer{timeout=null, stopped=true, running=false, destroyed=false, invoking=false, timeoutMs=3000, name='JRaft-VoteTimer-<test-app-zone00/test-app03.zone00.sgc.test.net:19527::1>'} stepDownTimer: RepeatedTimer{timeout=HashedWheelTimeout(deadline: 592082430 ns later, task: com.alipay.sofa.jraft.util.RepeatedTimer$$Lambda$975/0x00000008017156d0@676a2c90), stopped=false, running=true, destroyed=false, invoking=false, timeoutMs=1500, name='JRaft-StepDownTimer-<test-app-zone00/test-app03.zone00.sgc.test.net:19527::1>'} snapshotTimer: RepeatedTimer{timeout=HashedWheelTimeout(deadline: 70193768739 ns later, task: com.alipay.sofa.jraft.util.RepeatedTimer$$Lambda$975/0x00000008017156d0@49badb21), stopped=false, running=true, destroyed=false, invoking=false, timeoutMs=120000, name='JRaft-SnapshotTimer-<test-app-zone00/test-app03.zone00.sgc.test.net:19527::1>'} logManager: storage: [3307576938, 3307577032] diskId: LogId [index=3307577032, term=13] appliedId: LogId [index=3307577032, term=13] lastSnapshotId: LogId [index=3307577003, term=13] fsmCaller: StateMachine [Idle] ballotBox: lastCommittedIndex: 3307577032 pendingIndex: 3307577033 pendingMetaQueueSize: 0 snapshotExecutor: lastSnapshotTerm: 13 lastSnapshotIndex: 3307577003 term: 12 savingSnapshot: false loadingSnapshot: false stopped: false replicatorGroup: replicators: [Replicator [state=Replicate, statInfo=, peerId=test-app02.zone00.sgb.test.net:19527, type=Follower], Replicator [state=Replicate, statInfo=, peerId=test-app01.zone00.sga.test.net:19527, type=Follower], Replicator [state=Replicate, statInfo=, peerId=test-app00.zone00.sga.test.net:19527, type=Follower], Replicator [state=Replicate, statInfo=, peerId=test-app04.zone00.sgc.test.net:19527, type=Follower]] failureReplicators: {} logStorage:

Compaction Stats [default] Level Files Size Score Read(GB) Rn(GB) Rnp1(GB) Write(GB) Wnew(GB) Moved(GB) W-Amp Rd(MB/s) Wr(MB/s) Comp(sec) CompMergeCPU(sec) Comp(cnt) Avg(sec) KeyIn KeyDrop Rblob(GB) Wblob(GB)

L0 0/0 0.00 KB 0.0 0.0 0.0 0.0 43.1 43.1 0.0 1.0 0.0 440.2 100.24 65.40 438 0.229 0 0 0.0 0.0 L1 1/0 101.56 MB 0.2 43.6 22.3 21.3 22.4 1.1 20.7 1.0 469.1 240.7 95.27 77.11 227 0.420 31K 15K 0.0 0.0 Sum 1/0 101.56 MB 0.0 43.6 22.3 21.3 65.5 44.2 20.7 1.5 228.6 343.0 195.50 142.51 665 0.294 31K 15K 0.0 0.0 Int 0/0 0.00 KB 0.0 0.2 0.1 0.1 0.3 0.2 0.1 1.5 243.9 349.5 0.92 0.69 3 0.305 142 73 0.0 0.0

Compaction Stats [default] Priority Files Size Score Read(GB) Rn(GB) Rnp1(GB) Write(GB) Wnew(GB) Moved(GB) W-Amp Rd(MB/s) Wr(MB/s) Comp(sec) CompMergeCPU(sec) Comp(cnt) Avg(sec) KeyIn KeyDrop Rblob(GB) Wblob(GB)

Low 0/0 0.00 KB 0.0 43.6 22.3 21.3 22.4 1.1 0.0 0.0 469.1 240.7 95.27 77.11 227 0.420 31K 15K 0.0 0.0 High 0/0 0.00 KB 0.0 0.0 0.0 0.0 43.1 43.1 0.0 0.0 0.0 440.2 100.16 65.40 437 0.229 0 0 0.0 0.0 User 0/0 0.00 KB 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 465.5 0.08 0.00 1 0.080 0 0 0.0 0.0

Blob file count: 0, total size: 0.0 GB

Uptime(secs): 52475.1 total, 274.6 interval Flush(GB): cumulative 43.090, interval 0.206 AddFile(GB): cumulative 0.000, interval 0.000 AddFile(Total Files): cumulative 0, interval 0 AddFile(L0 Files): cumulative 0, interval 0 AddFile(Keys): cumulative 0, interval 0 Cumulative compaction: 65.48 GB write, 1.28 MB/s write, 43.64 GB read, 0.85 MB/s read, 195.5 seconds Interval compaction: 0.31 GB write, 1.16 MB/s write, 0.22 GB read, 0.81 MB/s read, 0.9 seconds Stalls(count): 0 level0_slowdown, 0 level0_slowdown_with_compaction, 0 level0_numfiles, 0 level0_numfiles_with_compaction, 0 stop for pending_compaction_bytes, 0 slowdown for pending_compaction_bytes, 0 memtable_compaction, 0 memtable_slowdown, interval 0 total count Block cache LRUCache@0x7f91f49796b0 capacity: 512.00 MB collections: 89 last_copies: 0 last_secs: 0.00017 secs_since: 0 Block cache entry stats(count,size,portion): DataBlock(74,2.64 MB,0.514853%) IndexBlock(126,78.08 KB,0.0148922%) OtherBlock(60,6.56 KB,0.0012517%) Misc(1,0.00 KB,0%)

File Read Latency Histogram By Level [default] ** Level 0 read latency histogram (micros): Count: 33049 Average: 253.5336 StdDev: 103.28 Min: 0 Median: 252.2662 Max: 1358 Percentiles: P50: 252.27 P75: 326.72 P99: 578.18 P99.9: 852.38 P99.99: 1229.21

[ 0, 1 ] 1156 3.498% 3.498% # ( 1, 2 ] 775 2.345% 5.843% ( 2, 3 ] 496 1.501% 7.344% ( 3, 4 ] 172 0.520% 7.864% ( 4, 6 ] 12 0.036% 7.900% ( 6, 10 ] 12 0.036% 7.937% ( 10, 15 ] 4 0.012% 7.949% ( 110, 170 ] 39 0.118% 8.067% ( 170, 250 ] 13607 41.172% 49.239% ######## ( 250, 380 ] 14427 43.653% 92.892% ######### ( 380, 580 ] 2037 6.164% 99.056% # ( 580, 870 ] 297 0.899% 99.955% ( 870, 1300 ] 14 0.042% 99.997% ( 1300, 1900 ] 1 0.003% 100.000%

** Level 1 read latency histogram (micros): Count: 2753 Average: 49.4054 StdDev: 112.44 Min: 0 Median: 1.0929 Max: 920 Percentiles: P50: 1.09 P75: 2.42 P99: 503.78 P99.9: 813.51 P99.99: 920.00

[ 0, 1 ] 1319 47.911% 47.911% ########## ( 1, 2 ] 619 22.485% 70.396% #### ( 2, 3 ] 299 10.861% 81.257% ## ( 3, 4 ] 38 1.380% 82.637% ( 6, 10 ] 5 0.182% 82.819% ( 10, 15 ] 1 0.036% 82.855% ( 110, 170 ] 3 0.109% 82.964% ( 170, 250 ] 220 7.991% 90.955% ## ( 250, 380 ] 193 7.011% 97.966% # ( 380, 580 ] 46 1.671% 99.637% ( 580, 870 ] 9 0.327% 99.964% ( 870, 1300 ] 1 0.036% 100.000%

DB Stats Uptime(secs): 52475.1 total, 274.6 interval Cumulative writes: 31K writes, 31K keys, 31K commit groups, 1.0 writes per commit group, ingest: 43.09 GB, 0.84 MB/s Cumulative WAL: 31K writes, 0 syncs, 31720.00 writes per sync, written: 43.09 GB, 0.84 MB/s Cumulative stall: 00:00:0.000 H:M:S, 0.0 percent Interval writes: 160 writes, 161 keys, 160 commit groups, 1.0 writes per commit group, ingest: 240.22 MB, 0.87 MB/s Interval WAL: 160 writes, 0 syncs, 160.00 writes per sync, written: 0.23 GB, 0.87 MB/s Interval stall: 00:00:0.000 H:M:S, 0.0 percent

rocksdb.block.cache.miss COUNT : 34423 rocksdb.block.cache.hit COUNT : 3451 rocksdb.block.cache.add COUNT : 4092 rocksdb.block.cache.add.failures COUNT : 0 rocksdb.block.cache.index.miss COUNT : 1778 rocksdb.block.cache.index.hit COUNT : 1204 rocksdb.block.cache.index.add COUNT : 1778 rocksdb.block.cache.index.bytes.insert COUNT : 1154192 rocksdb.block.cache.index.bytes.evict COUNT : 0 rocksdb.block.cache.filter.miss COUNT : 0 rocksdb.block.cache.filter.hit COUNT : 0 rocksdb.block.cache.filter.add COUNT : 0 rocksdb.block.cache.filter.bytes.insert COUNT : 0 rocksdb.block.cache.filter.bytes.evict COUNT : 0 rocksdb.block.cache.data.miss COUNT : 32645 rocksdb.block.cache.data.hit COUNT : 2247 rocksdb.block.cache.data.add COUNT : 2314 rocksdb.block.cache.data.bytes.insert COUNT : 868417680 rocksdb.block.cache.bytes.read COUNT : 1999851824 rocksdb.block.cache.bytes.write COUNT : 869571872 rocksdb.bloom.filter.useful COUNT : 0 rocksdb.bloom.filter.full.positive COUNT : 0 rocksdb.bloom.filter.full.true.positive COUNT : 0 rocksdb.bloom.filter.micros COUNT : 0 rocksdb.persistent.cache.hit COUNT : 0 rocksdb.persistent.cache.miss COUNT : 0 rocksdb.sim.block.cache.hit COUNT : 0 rocksdb.sim.block.cache.miss COUNT : 0 rocksdb.memtable.hit COUNT : 797443 rocksdb.memtable.miss COUNT : 785 rocksdb.l0.hit COUNT : 118 rocksdb.l1.hit COUNT : 667 rocksdb.l2andup.hit COUNT : 0 rocksdb.compaction.key.drop.new COUNT : 15452 rocksdb.compaction.key.drop.obsolete COUNT : 874 rocksdb.compaction.key.drop.range_del COUNT : 15015 rocksdb.compaction.key.drop.user COUNT : 0 rocksdb.compaction.range_del.drop.obsolete COUNT : 874 rocksdb.compaction.optimized.del.drop.obsolete COUNT : 0 rocksdb.compaction.cancelled COUNT : 0 rocksdb.number.keys.written COUNT : 31742 rocksdb.number.keys.read COUNT : 798228 rocksdb.number.keys.updated COUNT : 0 rocksdb.bytes.written COUNT : 46272570411 rocksdb.bytes.read COUNT : 1208390449175 rocksdb.number.db.seek COUNT : 2 rocksdb.number.db.next COUNT : 1 rocksdb.number.db.prev COUNT : 0 rocksdb.number.db.seek.found COUNT : 2 rocksdb.number.db.next.found COUNT : 0 rocksdb.number.db.prev.found COUNT : 0 rocksdb.db.iter.bytes.read COUNT : 1509201 rocksdb.no.file.closes COUNT : 0 rocksdb.no.file.opens COUNT : 1769 rocksdb.no.file.errors COUNT : 0 rocksdb.l0.slowdown.micros COUNT : 0 rocksdb.memtable.compaction.micros COUNT : 0 rocksdb.l0.num.files.stall.micros COUNT : 0 rocksdb.stall.micros COUNT : 0 rocksdb.db.mutex.wait.micros COUNT : 0 rocksdb.rate.limit.delay.millis COUNT : 0 rocksdb.num.iterators COUNT : 0 rocksdb.number.multiget.get COUNT : 0 rocksdb.number.multiget.keys.read COUNT : 0 rocksdb.number.multiget.bytes.read COUNT : 0 rocksdb.number.deletes.filtered COUNT : 0 rocksdb.number.merge.failures COUNT : 0 rocksdb.bloom.filter.prefix.checked COUNT : 0 rocksdb.bloom.filter.prefix.useful COUNT : 0 rocksdb.number.reseeks.iteration COUNT : 0 rocksdb.getupdatessince.calls COUNT : 0 rocksdb.block.cachecompressed.miss COUNT : 0 rocksdb.block.cachecompressed.hit COUNT : 0 rocksdb.block.cachecompressed.add COUNT : 0 rocksdb.block.cachecompressed.add.failures COUNT : 0 rocksdb.wal.synced COUNT : 0 rocksdb.wal.bytes COUNT : 46272570411 rocksdb.write.self COUNT : 31720 rocksdb.write.other COUNT : 0 rocksdb.write.timeout COUNT : 0 rocksdb.write.wal COUNT : 63440 rocksdb.compact.read.bytes COUNT : 46163379671 rocksdb.compact.write.bytes COUNT : 24081033067 rocksdb.flush.write.bytes COUNT : 46229206407 rocksdb.compact.read.marked.bytes COUNT : 0 rocksdb.compact.read.periodic.bytes COUNT : 0 rocksdb.compact.read.ttl.bytes COUNT : 0 rocksdb.compact.write.marked.bytes COUNT : 0 rocksdb.compact.write.periodic.bytes COUNT : 0 rocksdb.compact.write.ttl.bytes COUNT : 0 rocksdb.number.direct.load.table.properties COUNT : 0 rocksdb.number.superversion_acquires COUNT : 15608 rocksdb.number.superversion_releases COUNT : 1752 rocksdb.number.superversion_cleanups COUNT : 0 rocksdb.number.block.compressed COUNT : 0 rocksdb.number.block.decompressed COUNT : 0 rocksdb.number.block.not_compressed COUNT : 0 rocksdb.merge.operation.time.nanos COUNT : 0 rocksdb.filter.operation.time.nanos COUNT : 0 rocksdb.row.cache.hit COUNT : 0 rocksdb.row.cache.miss COUNT : 0 rocksdb.read.amp.estimate.useful.bytes COUNT : 0 rocksdb.read.amp.total.read.bytes COUNT : 0 rocksdb.number.rate_limiter.drains COUNT : 0 rocksdb.number.iter.skip COUNT : 0 rocksdb.blobdb.num.put COUNT : 0 rocksdb.blobdb.num.write COUNT : 0 rocksdb.blobdb.num.get COUNT : 0 rocksdb.blobdb.num.multiget COUNT : 0 rocksdb.blobdb.num.seek COUNT : 0 rocksdb.blobdb.num.next COUNT : 0 rocksdb.blobdb.num.prev COUNT : 0 rocksdb.blobdb.num.keys.written COUNT : 0 rocksdb.blobdb.num.keys.read COUNT : 0 rocksdb.blobdb.bytes.written COUNT : 0 rocksdb.blobdb.bytes.read COUNT : 0 rocksdb.blobdb.write.inlined COUNT : 0 rocksdb.blobdb.write.inlined.ttl COUNT : 0 rocksdb.blobdb.write.blob COUNT : 0 rocksdb.blobdb.write.blob.ttl COUNT : 0 rocksdb.blobdb.blob.file.bytes.written COUNT : 0 rocksdb.blobdb.blob.file.bytes.read COUNT : 0 rocksdb.blobdb.blob.file.synced COUNT : 0 rocksdb.blobdb.blob.index.expired.count COUNT : 0 rocksdb.blobdb.blob.index.expired.size COUNT : 0 rocksdb.blobdb.blob.index.evicted.count COUNT : 0 rocksdb.blobdb.blob.index.evicted.size COUNT : 0 rocksdb.blobdb.gc.num.files COUNT : 0 rocksdb.blobdb.gc.num.new.files COUNT : 0 rocksdb.blobdb.gc.failures COUNT : 0 rocksdb.blobdb.gc.num.keys.overwritten COUNT : 0 rocksdb.blobdb.gc.num.keys.expired COUNT : 0 rocksdb.blobdb.gc.num.keys.relocated COUNT : 0 rocksdb.blobdb.gc.bytes.overwritten COUNT : 0 rocksdb.blobdb.gc.bytes.expired COUNT : 0 rocksdb.blobdb.gc.bytes.relocated COUNT : 0 rocksdb.blobdb.fifo.num.files.evicted COUNT : 0 rocksdb.blobdb.fifo.num.keys.evicted COUNT : 0 rocksdb.blobdb.fifo.bytes.evicted COUNT : 0 rocksdb.txn.overhead.mutex.prepare COUNT : 0 rocksdb.txn.overhead.mutex.old.commit.map COUNT : 0 rocksdb.txn.overhead.duplicate.key COUNT : 0 rocksdb.txn.overhead.mutex.snapshot COUNT : 0 rocksdb.txn.get.tryagain COUNT : 0 rocksdb.number.multiget.keys.found COUNT : 0 rocksdb.num.iterator.created COUNT : 2 rocksdb.num.iterator.deleted COUNT : 2 rocksdb.block.cache.compression.dict.miss COUNT : 0 rocksdb.block.cache.compression.dict.hit COUNT : 0 rocksdb.block.cache.compression.dict.add COUNT : 0 rocksdb.block.cache.compression.dict.bytes.insert COUNT : 0 rocksdb.block.cache.compression.dict.bytes.evict COUNT : 0 rocksdb.block.cache.add.redundant COUNT : 14 rocksdb.block.cache.index.add.redundant COUNT : 0 rocksdb.block.cache.filter.add.redundant COUNT : 0 rocksdb.block.cache.data.add.redundant COUNT : 14 rocksdb.block.cache.compression.dict.add.redundant COUNT : 0 rocksdb.files.marked.trash COUNT : 0 rocksdb.files.deleted.immediately COUNT : 2335 rocksdb.error.handler.bg.errro.count COUNT : 0 rocksdb.error.handler.bg.io.errro.count COUNT : 0 rocksdb.error.handler.bg.retryable.io.errro.count COUNT : 0 rocksdb.error.handler.autoresume.count COUNT : 0 rocksdb.error.handler.autoresume.retry.total.count COUNT : 0 rocksdb.error.handler.autoresume.success.count COUNT : 0 rocksdb.memtable.payload.bytes.at.flush COUNT : 46226936600 rocksdb.memtable.garbage.bytes.at.flush COUNT : 0 rocksdb.db.get.micros P50 : 292.278070 P95 : 476.417728 P99 : 627.919383 P100 : 3218.000000 COUNT : 798228 SUM : 227011441 rocksdb.db.write.micros P50 : 2450.206546 P95 : 4079.056755 P99 : 5759.098143 P100 : 11795.000000 COUNT : 31720 SUM : 76145621 rocksdb.compaction.times.micros P50 : 1894.570136 P95 : 541020.202020 P99 : 566507.070707 P100 : 787031.000000 COUNT : 664 SUM : 96062949 rocksdb.compaction.times.cpu_micros P50 : 359.944904 P95 : 371710.144928 P99 : 418055.000000 P100 : 418055.000000 COUNT : 664 SUM : 77246248 rocksdb.subcompaction.setup.times.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.table.sync.micros P50 : 41500.000000 P95 : 109932.864450 P99 : 235000.000000 P100 : 566883.000000 COUNT : 875 SUM : 44902493 rocksdb.compaction.outfile.sync.micros P50 : 22523.809524 P95 : 72943.925234 P99 : 118100.000000 P100 : 318488.000000 COUNT : 892 SUM : 23640843 rocksdb.wal.file.sync.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.manifest.file.sync.micros P50 : 1149.006456 P95 : 2243.000000 P99 : 5313.733333 P100 : 22581.000000 COUNT : 1977 SUM : 2610973 rocksdb.table.open.io.micros P50 : 77.513548 P95 : 133.471831 P99 : 163.370423 P100 : 384.000000 COUNT : 1769 SUM : 136491 rocksdb.db.multiget.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.read.block.compaction.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.read.block.get.micros P50 : 1250.373186 P95 : 1975.000000 P99 : 2801.301370 P100 : 3758.000000 COUNT : 36192 SUM : 42413271 rocksdb.write.raw.block.micros P50 : 1579.777437 P95 : 2627.507457 P99 : 3760.748642 P100 : 4783.000000 COUNT : 55033 SUM : 78872109 rocksdb.l0.slowdown.count P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.memtable.compaction.count P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.num.files.stall.count P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.hard.rate.limit.delay.count P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.soft.rate.limit.delay.count P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.numfiles.in.singlecompaction P50 : 2.000000 P95 : 2.000000 P99 : 2.000000 P100 : 2.000000 COUNT : 1 SUM : 2 rocksdb.db.seek.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.db.write.stall P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.sst.read.micros P50 : 228.462429 P95 : 411.851319 P99 : 571.080096 P100 : 1358.000000 COUNT : 41499 SUM : 8526620 rocksdb.num.subcompactions.scheduled P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.bytes.per.read P50 : 1574733.927466 P95 : 2368609.183030 P99 : 3309203.652806 P100 : 3549623.000000 COUNT : 798228 SUM : 1208390449175 rocksdb.bytes.per.write P50 : 1559476.812445 P95 : 2371216.341690 P99 : 3309279.279279 P100 : 5861220.000000 COUNT : 31720 SUM : 46272570411 rocksdb.bytes.per.multiget P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.bytes.compressed P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.bytes.decompressed P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.compression.times.nanos P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.decompression.times.nanos P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.read.num.merge_operands P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.blobdb.key.size P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.blobdb.value.size P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.blobdb.write.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.blobdb.get.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.blobdb.multiget.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.blobdb.seek.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.blobdb.next.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.blobdb.prev.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.blobdb.blob.file.write.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.blobdb.blob.file.read.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.blobdb.blob.file.sync.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.blobdb.gc.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.blobdb.compression.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.blobdb.decompression.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.db.flush.micros P50 : 22000.000000 P95 : 249055.276382 P99 : 376896.774194 P100 : 718487.000000 COUNT : 874 SUM : 100916558 rocksdb.sst.batch.size P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.num.index.and.filter.blocks.read.per.level P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.num.data.blocks.read.per.level P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.num.sst.read.per.level P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0 rocksdb.error.handler.autoresume.retry.count P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0

tsgmq commented 2 years ago

Utils中的CLOSURE_EXECUTOR出现线程池不够用的情况,是否跟升级1.3.10有关系,里面是不是增加了log的合并删除,那个位置是否会导致JRaft-Closure-Executor的卡顿呢? image

tsgmq commented 2 years ago

image

fengjiachun commented 2 years ago

在启动 jraft 之前执行 SystemPropertyUtil.setInt("jraft.recyclers.maxCapacityPerThread", 0); 关闭 Recyclers 再观察下,猜测不是 Recyclers 的泄露的问题

也可以进程启动 -D 的形式设置这个参数

@tsgmq

killme2008 commented 2 years ago

这些 closure 在干什么? 可以抓抓堆栈看看。

54zero96 commented 2 years ago

Recyclers.weakOrderQueue.link中保存了回收对象的引用,作为对象池,回收的对象是ByteBufferCollector,其中HeapByteBuffer中持有的hb字段保存了大量的字节数组,大小为3m左右

当ByteBufferCollector对象回收时,会判断当前buffer大小是否超过阈值4m,超过了直接丢弃,未超过则调用clear清理。 middle_img_v2_3bc1cef3-d0e7-42ad-9a0d-1b4a4306434h

buffer对应的类型是HeapByteBuffer,调用的clear逻辑中没有清理hb对象,导致了内存残留。从字段position和mark的赋值上可以确认接口已被调用。 origin_img_v2_35e1a8c9-49b0-4adc-ad00-33be0df3b84h

想问下调用HeapByteBuffer中clear不清理hb是预期中的吗,现在看下来由于对象池持有的对象中没有清理hb中的字节数组,导致了大量内存没有被释放。 这里是否可以提供ByteBufferCollector清理时阈值的设置接口(现在阈值设置的是4m,我们的数据大小是3m,没有被清理),或者直接将HeapByteBuffer,直接统一设置为null image

fengjiachun commented 2 years ago

@54zero96 Recyclers 的逻辑是,如果大于 4M,那么不做池化的缓存处理 Recyclers 是个对象池,你上面的代码都符合预期,只调用 Buffer.clear 是为了复用呀,回收了还怎么复用呢 :)

Recyclers 如果在这个场景里不适用,可以按照我上面的建议,先关闭试一下,看看还有没有问题,有可能现在看到的是假象,核心原因没准是吞吐太大了导致的,因为 appendEnties 的 ByteBuf 需要异步回调来回收,这个异步回调是需要得到对端 response 才能触发的, appendEnties 的 RPC 到瓶颈了,或者 follower 响应慢了,都会导致堆积,尤其是你发送这种大数据块,所以还是建议先关闭了再看

tsgmq commented 2 years ago

做了如下四点调整后,在测试环境目前是比较稳定,等下周发布线上后,再继续观察

  1. disruptorBufferSize=16384 (由131072调整到16384)
  2. -Djraft.max_collector_size_per_thread=64 (默认值调整到64)
  3. -Djraft.recyclers.maxCapacityPerThread=0 (默认值调整到0)
  4. snapshotIntervalSecs: 600 (由120调整到600)

image