All instances of the production cluster are full gc, and topic fenced cannot be written

[keyboardbobo]

Search before asking

• I searched in the issues and found nothing similar.

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?

• I'm willing to submit a PR!

[codelipenghui]

CPU load is relatively high

Do you see which threads consumed lots of the CPU? If you are able to reproduce the issue. It's better to do some CPU profiling by using https://github.com/jvm-profiling-tools/async-profiler or other tools. So that we can understand which thread consumed the CPU resources

[tisonkun]

Moved to discussion. It's more a usage question than a bug.