Search before asking
There are 9 brokers and 9 bookies in our production environment. After running for half a year, the number of topic partitions increased from 160 to 280. After restarting the client application, all instances showed full gc after a few hours. Each traffic has only about 50M traffic
Version
broker 2.9.2 , bookkeeper 4.14
Minimal reproduce step
Later we reproduced the problem in the test environment, the cluster has 4 bookies and 4 brokers, persistent://qlm-test/qlm-ns/qlm-test has 500 partitions, The client is an independent machine, and the CPU load is relatively high，The traffic of each broker is only 40M，Full gc can be reproduced locally with the following script:
Start 5 instances on the same linux server：nohup bin/pulsar-perf produce -threads 20 -u pulsar://clusterIp:port -n 20 -s 200 -r 100000 persistent://qlm-test/qlm-ns/qlm-test &
Start 2 instances on the other same linux server：nohup bin/pulsar-perf consume -u pulsar://clusterIp:port -q 5000 -ss qlm-sub -st Shared persistent://qlm-test/qlm-ns/qlm-test &
The broker Full gc log：
2022-11-10T15:40:55.685+0800: 4028.874: [Full GC (Allocation Failure) 15G->7299M(16G), 27.2368180 secs]
[Eden: 0.0B(8192.0M)->0.0B(8192.0M) Survivors: 0.0B->0.0B Heap: 16.0G(16.0G)->7299.4M(16.0G)], [Metaspace: 90357K->86677K(1140736K)]
[Times: user=47.76 sys=1.22, real=27.24 secs]
2022-11-10T15:41:22.924+0800: 4056.113: [GC concurrent-mark-abort]
2022-11-10T15:41:28.922+0800: 4062.110: [GC pause (GCLocker Initiated GC) (young) (to-space exhausted), 7.1966394 secs]
[Parallel Time: 6586.0 ms, GC Workers: 32]
[GC Worker Start (ms): Min: 4062112.3, Avg: 4062112.5, Max: 4062112.7, Diff: 0.4]
[Ext Root Scanning (ms): Min: 1.4, Avg: 2.2, Max: 7.8, Diff: 6.4, Sum: 71.9]
[Update RS (ms): Min: 0.0, Avg: 3.9, Max: 5.3, Diff: 5.3, Sum: 125.8]
[Processed Buffers: Min: 0, Avg: 10.1, Max: 23, Diff: 23, Sum: 323]
[Scan RS (ms): Min: 13.8, Avg: 15.4, Max: 15.8, Diff: 2.0, Sum: 493.0]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
[Object Copy (ms): Min: 2558.9, Avg: 2684.2, Max: 6563.5, Diff: 4004.6, Sum: 85894.9]
[Termination (ms): Min: 0.0, Avg: 3879.3, Max: 4004.6, Diff: 4004.6, Sum: 124138.1]
[Termination Attempts: Min: 1, Avg: 10.9, Max: 18, Diff: 17, Sum: 348]
[GC Worker Other (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 9.7]
[GC Worker Total (ms): Min: 6584.9, Avg: 6585.4, Max: 6585.8, Diff: 0.9, Sum: 210733.7]
[GC Worker End (ms): Min: 4068697.6, Avg: 4068697.9, Max: 4068698.2, Diff: 0.5]
[Code Root Fixup: 0.2 ms]
[Code Root Purge: 0.2 ms]
[Clear CT: 3.5 ms]
[Other: 606.6 ms]
[Evacuation Failure: 573.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 6.1 ms]
[Ref Enq: 0.5 ms]
[Redirty Cards: 5.2 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 1.0 ms]
[Free CSet: 11.8 ms]
[Eden: 8200.0M(8192.0M)->0.0B(7328.0M) Survivors: 0.0B->864.0M Heap: 15.1G(16.0G)->14.9G(16.0G)]
The broker has more logs like this：
2022-11-10 15:41:27.0581 [BookKeeperClientWorker-OrderedExecutor-2-0] WARN org.apache.bookkeeper.client.PendingAddOp - Fencing exception on write: L780738 E1371097 on 10.101.129.75:3181
2022-11-10 15:41:27.0581 [BookKeeperClientWorker-OrderedExecutor-39-0] WARN org.apache.bookkeeper.client.PendingAddOp - Fencing exception on write: L780711 E1370071 on 10.101.129.68:3181
2022-11-10 15:41:27.0581 [BookKeeperClientWorker-OrderedExecutor-18-0] ERROR org.apache.bookkeeper.client.PendingAddOp - Write of ledger entry to quorum failed: L780690 E1374427
2022-11-10 15:41:27.0581 [BookKeeperClientWorker-OrderedExecutor-40-0] WARN org.apache.bookkeeper.client.PendingAddOp - Failed to write entry (780712, 1354072): Bookie operation timeout
2022-11-10 15:41:27.0581 [BookKeeperClientWorker-OrderedExecutor-7-0] WARN org.apache.bookkeeper.client.PendingAddOp - Fencing exception on write: L780743 E1370335 on 10.101.129.68:3181
2022-11-10 15:41:27.0581 [BookKeeperClientWorker-OrderedExecutor-18-0] ERROR org.apache.bookkeeper.client.PendingAddOp - Write of ledger entry to quorum failed: L780690 E1374428
The client has more logs like this：
2022-11-10 16:48:50.0588 [pulsar-timer-78-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [persistent://qlm-test/qlm-ns/qlm-test-partition-279] [pulsar_dev2-118-13100] Reconnecting after timeout
2022-11-10 16:48:50.0588 [pulsar-client-io-16-1] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0x28f60fe8, L:/10.101.75.4:45744 ! R:10.101.129.70/10.101.129.70:6650] Failed to send request to broker: null
2022-11-10 16:48:50.0537 [pulsar-timer-75-1] INFO org.apache.pulsar.client.impl.ConnectionHandler - [persistent://qlm-test/qlm-ns/qlm-test-partition-488] [pulsar_dev2-118-173804] Reconnecting after timeout
2022-11-10 16:48:50.0588 [pulsar-client-io-16-1] ERROR org.apache.pulsar.client.impl.ProducerImpl - [persistent://qlm-test/qlm-ns/qlm-test-partition-160] [pulsar_dev2-119-27579] Failed to create producer: null
2022-11-10 16:48:50.0534 [pulsar-client-io-6-1] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0x9f18bc7a, L:/10.101.75.4:35788 ! R:10.101.129.68/10.101.129.68:6650] Failed to send request 1295575096907667936 to broker: null
2022-11-10 16:48:50.0588 [pulsar-client-io-19-1] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://qlm-test/qlm-ns/qlm-test-partition-226] [pulsar_dev2-119-60703] Created producer on cnx [id: 0xfdb3f279, L:/10.101.75.4:45962 - R:10.101.129.70/10.101.129.70:6650]
What did you expect to see?
The system runs stably
What did you see instead?
Generally, within half an hour, full gc can appear on one or more brokers
Anything else?
No response
Are you willing to submit a PR?
Search before asking
There are 9 brokers and 9 bookies in our production environment. After running for half a year, the number of topic partitions increased from 160 to 280. After restarting the client application, all instances showed full gc after a few hours. Each traffic has only about 50M traffic
Version
broker 2.9.2 , bookkeeper 4.14
Minimal reproduce step
Later we reproduced the problem in the test environment, the cluster has 4 bookies and 4 brokers, persistent://qlm-test/qlm-ns/qlm-test has 500 partitions, The client is an independent machine, and the CPU load is relatively high，The traffic of each broker is only 40M，Full gc can be reproduced locally with the following script:
Start 5 instances on the same linux server：nohup bin/pulsar-perf produce -threads 20 -u pulsar://clusterIp:port -n 20 -s 200 -r 100000 persistent://qlm-test/qlm-ns/qlm-test &
Start 2 instances on the other same linux server：nohup bin/pulsar-perf consume -u pulsar://clusterIp:port -q 5000 -ss qlm-sub -st Shared persistent://qlm-test/qlm-ns/qlm-test &
The broker Full gc log：
The broker has more logs like this：
The client has more logs like this：
What did you expect to see?
The system runs stably
What did you see instead?
Generally, within half an hour, full gc can appear on one or more brokers
Anything else?
No response
Are you willing to submit a PR?