[Bug] With small entry sizes and high throughput, it's necessary to increase dispatcherMaxReadBatchSize and dispatcherMaxReadSizeBytes to utilize CPU on the broker

[lhotari]

Search before reporting

• I searched in the issues and found nothing similar.

Read release policy

• I understand that unsupported versions don't get bug fixes. I will attempt to reproduce the issue on a supported version of Pulsar client and Pulsar broker.

User environment

Experimental branch from current master

Test to reproduce is
https://github.com/lhotari/pulsar/blob/a85ac6fbfb3b763f7eaa4f44e232536748119ca4/tests/integration/src/test/java/org/apache/pulsar/tests/integration/profiling/PulsarProfilingTest.java#L124-L143

In the commit, the problem is fixed. Repo instructions will be later.

Issue Description

The test creates small entries with only 128 bytes for each entry to stress entry creation.
Batching is turned off. Consuming is very slow with default settings and consuming cannot keep up with producing that is over 350000 msgs/s (on Mac M3 Max running Docker with OrbStack).
The consuming speed is only about 11000 msgs/s.

Error messages

No errors

Reproducing the issue

The issue can be reproduced with https://github.com/lhotari/pulsar/blob/a85ac6fbfb3b763f7eaa4f44e232536748119ca4/tests/integration/src/test/java/org/apache/pulsar/tests/integration/profiling/PulsarProfilingTest.java and changes in the branch https://github.com/lhotari/pulsar/tree/lh-small-entry-size-performance-issue .

Please notice that the problem in the branch is fixed. The problem can be reproduced by reverting the last commit lhotari@a85ac6f

This "fixed" the performance issue:

diff --git a/tests/integration/src/test/java/org/apache/pulsar/tests/integration/profiling/PulsarProfilingTest.java b/tests/integration/src/test/java/org/apache/pulsar/tests/integration/profiling/PulsarProfilingTest.java
index a9f718103bf2f..a8d2ec3a5e32f 100644
--- a/tests/integration/src/test/java/org/apache/pulsar/tests/integration/profiling/PulsarProfilingTest.java
+++ b/tests/integration/src/test/java/org/apache/pulsar/tests/integration/profiling/PulsarProfilingTest.java
@@ -219,7 +219,8 @@ protected PulsarClusterSpec.PulsarClusterSpecBuilder beforeSetupCluster(String c
         brokerEnvs.put("dispatcherRetryBackoffMaxTimeInMs", "0");
         //brokerEnvs.put("PULSAR_PREFIX_subscriptionKeySharedUseClassicPersistentImplementation", "true");
         //brokerEnvs.put("PULSAR_PREFIX_subscriptionSharedUseClassicPersistentImplementation", "true");
-        brokerEnvs.put("dispatcherMaxReadBatchSize", "1000");
+        brokerEnvs.put("dispatcherMaxReadBatchSize", "10000");
+        brokerEnvs.put("dispatcherMaxReadSizeBytes", "10000000");
         brokerEnvs.put("dispatcherDispatchMessagesInSubscriptionThread", "false");
         brokerEnvs.put("dispatcherMaxRoundRobinBatchSize", "1000");
         specBuilder.brokerEnvs(brokerEnvs);

Additional information

Although the changein the repro branch "fixed" the issue, it's not a suitable fix. The root cause of the problem should be addressed. It's possible that it's related to entry size estimation changes that have been made fairly recently.

Are you willing to submit a PR?

• I'm willing to submit a PR!

[lhotari]

Now I see the correlation. When maxPendingPublishRequestsPerConnection value is reduced, the consuming will be more responsive with the tradeoff that latency increases and throughput goes down for both producing and consuming.

In the above case, I had increased maxPendingPublishRequestsPerConnection to 10000 from the default 1000 to improve producing throughput.

This seems to be a problem where the produced entries and the consuming (dispatching) are constrained on the same thread and get queued up in the same queue.

There's also #23865. Currently readMoreEntries gets called in random Pulsar IO threads, which doesn't make much sense.

[lhotari]

The problem persists even with maxPendingPublishRequestsPerConnection=1000, after the consumption rate drops, it's never able to catch up.

==> consume.1756905609.txt <==
2025-09-03T13:20:21,423+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 2480116 msg --- 247985.562  msg/s --- 242.174 Mbit/s  --- Latency: mean: 475.180 ms - med: 364 - 95pct: 929 - 99pct: 1015 - 99.9pct: 1033 - 99.99pct: 1034 - Max: 1035
2025-09-03T13:20:31,616+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 5344177 msg --- 281067.409  msg/s --- 274.479 Mbit/s  --- Latency: mean: 1477.922 ms - med: 1232 - 95pct: 2123 - 99pct: 2165 - 99.9pct: 2181 - 99.99pct: 2183 - Max: 2184
2025-09-03T13:20:41,837+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 8538541 msg --- 311929.958  msg/s --- 304.619 Mbit/s  --- Latency: mean: 2242.693 ms - med: 2167 - 95pct: 2552 - 99pct: 2599 - 99.9pct: 2628 - 99.99pct: 2631 - Max: 2632
2025-09-03T13:20:52,033+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 11428523 msg --- 283930.574  msg/s --- 277.276 Mbit/s  --- Latency: mean: 3200.968 ms - med: 3154 - 95pct: 3902 - 99pct: 3953 - 99.9pct: 3965 - 99.99pct: 3967 - Max: 3967
2025-09-03T13:21:02,220+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 13963339 msg --- 248431.573  msg/s --- 242.609 Mbit/s  --- Latency: mean: 4840.201 ms - med: 4631 - 95pct: 5953 - 99pct: 6088 - 99.9pct: 6504 - 99.99pct: 6606 - Max: 6614
2025-09-03T13:21:12,389+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 14082039 msg --- 11675.276  msg/s --- 11.402 Mbit/s  --- Latency: mean: 10595.487 ms - med: 9834 - 95pct: 15946 - 99pct: 16330 - 99.9pct: 16397 - 99.99pct: 16405 - Max: 16405
2025-09-03T13:21:22,574+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 14207139 msg --- 12281.006  msg/s --- 11.993 Mbit/s  --- Latency: mean: 21423.869 ms - med: 21433 - 95pct: 25576 - 99pct: 25915 - 99.9pct: 26079 - 99.99pct: 26202 - Max: 26202
2025-09-03T13:21:32,766+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 14333239 msg --- 12396.715  msg/s --- 12.106 Mbit/s  --- Latency: mean: 31015.429 ms - med: 31071 - 95pct: 35475 - 99pct: 35822 - 99.9pct: 35940 - 99.99pct: 35957 - Max: 35957
2025-09-03T13:21:42,948+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 14453639 msg --- 11787.760  msg/s --- 11.511 Mbit/s  --- Latency: mean: 40793.841 ms - med: 40847 - 95pct: 45110 - 99pct: 45620 - 99.9pct: 45741 - 99.99pct: 45753 - Max: 45753
2025-09-03T13:21:53,113+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 14574539 msg --- 11913.761  msg/s --- 11.635 Mbit/s  --- Latency: mean: 50616.966 ms - med: 50630 - 95pct: 54988 - 99pct: 55331 - 99.9pct: 55410 - 99.99pct: 55419 - Max: 55419

==> produce.1756905610.txt <==
2025-09-03T13:20:21,707+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 2909305 msg --- 290893.0 msg/s ---    284.1 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  61.583 ms - med:  59.997 - 95pct:  79.221 - 99pct:  94.191 - 99.9pct: 123.506 - 99.99pct: 126.534 - Max: 126.836
2025-09-03T13:20:31,973+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 6040341 msg --- 305160.6 msg/s ---    298.0 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  65.233 ms - med:  60.888 - 95pct:  96.654 - 99pct: 157.045 - 99.9pct: 197.298 - 99.99pct: 201.863 - Max: 205.311
2025-09-03T13:20:42,300+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 9542250 msg --- 339691.4 msg/s ---    331.7 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  58.848 ms - med:  57.397 - 95pct:  72.225 - 99pct:  82.660 - 99.9pct: 136.446 - 99.99pct: 138.024 - Max: 138.419
2025-09-03T13:20:52,537+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 12864236 msg --- 324643.1 msg/s ---    317.0 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  61.325 ms - med:  60.040 - 95pct:  73.703 - 99pct:  94.623 - 99.9pct: 137.981 - 99.99pct: 141.839 - Max: 142.164
2025-09-03T13:21:02,851+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 15862437 msg --- 290223.8 msg/s ---    283.4 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  68.900 ms - med:  63.146 - 95pct:  99.333 - 99pct: 229.158 - 99.9pct: 314.035 - 99.99pct: 316.513 - Max: 317.015
2025-09-03T13:21:13,092+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 19015246 msg --- 306440.0 msg/s ---    299.3 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  65.178 ms - med:  62.359 - 95pct:  95.343 - 99pct: 142.081 - 99.9pct: 170.086 - 99.99pct: 174.757 - Max: 176.125
2025-09-03T13:21:23,417+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 22157356 msg --- 305512.9 msg/s ---    298.4 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  65.361 ms - med:  62.668 - 95pct:  78.804 - 99pct: 120.910 - 99.9pct: 263.391 - 99.99pct: 266.913 - Max: 268.609
2025-09-03T13:21:33,712+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 25430649 msg --- 318750.0 msg/s ---    311.3 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  62.615 ms - med:  61.110 - 95pct:  78.980 - 99pct: 102.190 - 99.9pct: 109.717 - 99.99pct: 110.994 - Max: 112.107
2025-09-03T13:21:44,034+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 28480015 msg --- 295567.7 msg/s ---    288.6 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  67.564 ms - med:  64.679 - 95pct:  91.043 - 99pct: 151.943 - 99.9pct: 200.440 - 99.99pct: 201.588 - Max: 201.954
2025-09-03T13:21:54,333+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 31505193 msg --- 293281.1 msg/s ---    286.4 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  67.970 ms - med:  65.604 - 95pct:  82.670 - 99pct: 126.416 - 99.9pct: 248.036 - 99.99pct: 248.534 - Max: 248.685

[lhotari]

With dispatcherMaxReadBatchSize=1000, consuming is able to keep up.

==> consume.1756906641.txt <==
2025-09-03T13:37:33,088+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 2745126 msg --- 274418.424  msg/s --- 267.987 Mbit/s  --- Latency: mean: 74.885 ms - med: 70 - 95pct: 101 - 99pct: 186 - 99.9pct: 214 - 99.99pct: 221 - Max: 222
2025-09-03T13:37:43,227+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 6176301 msg --- 339658.686  msg/s --- 331.698 Mbit/s  --- Latency: mean: 66.355 ms - med: 66 - 95pct: 77 - 99pct: 89 - 99.9pct: 127 - 99.99pct: 131 - Max: 131
2025-09-03T13:37:53,420+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 9502693 msg --- 325858.234  msg/s --- 318.221 Mbit/s  --- Latency: mean: 71.439 ms - med: 67 - 95pct: 90 - 99pct: 209 - 99.9pct: 253 - 99.99pct: 257 - Max: 258
2025-09-03T13:38:03,584+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 12533030 msg --- 298182.342  msg/s --- 291.194 Mbit/s  --- Latency: mean: 74.275 ms - med: 68 - 95pct: 109 - 99pct: 268 - 99.9pct: 341 - 99.99pct: 348 - Max: 349
2025-09-03T13:38:13,779+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 15785498 msg --- 319568.627  msg/s --- 312.079 Mbit/s  --- Latency: mean: 70.165 ms - med: 68 - 95pct: 89 - 99pct: 130 - 99.9pct: 143 - 99.99pct: 154 - Max: 155
2025-09-03T13:38:23,953+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 19036026 msg --- 319576.032  msg/s --- 312.086 Mbit/s  --- Latency: mean: 69.524 ms - med: 67 - 95pct: 95 - 99pct: 127 - 99.9pct: 167 - 99.99pct: 174 - Max: 175
2025-09-03T13:38:34,122+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 21573453 msg --- 249040.310  msg/s --- 243.203 Mbit/s  --- Latency: mean: 87.490 ms - med: 82 - 95pct: 121 - 99pct: 165 - 99.9pct: 314 - 99.99pct: 317 - Max: 317
2025-09-03T13:38:44,310+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 24410600 msg --- 278940.036  msg/s --- 272.402 Mbit/s  --- Latency: mean: 78.566 ms - med: 76 - 95pct: 105 - 99pct: 133 - 99.9pct: 144 - 99.99pct: 149 - Max: 149
2025-09-03T13:38:54,493+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 27058899 msg --- 259684.194  msg/s --- 253.598 Mbit/s  --- Latency: mean: 84.472 ms - med: 83 - 95pct: 102 - 99pct: 115 - 99.9pct: 134 - 99.99pct: 139 - Max: 139
2025-09-03T13:39:04,675+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 29615641 msg --- 251573.251  msg/s --- 245.677 Mbit/s  --- Latency: mean: 86.414 ms - med: 84 - 95pct: 112 - 99pct: 132 - 99.9pct: 141 - 99.99pct: 144 - Max: 145

==> produce.1756906642.txt <==
2025-09-03T13:37:33,440+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 2821633 msg --- 281981.2 msg/s ---    275.4 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  64.284 ms - med:  61.892 - 95pct:  84.115 - 99pct:  97.687 - 99.9pct: 128.139 - 99.99pct: 130.591 - Max: 130.920
2025-09-03T13:37:43,742+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 6338814 msg --- 341086.6 msg/s ---    333.1 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  58.444 ms - med:  57.741 - 95pct:  67.893 - 99pct:  82.207 - 99.9pct:  87.760 - 99.99pct:  88.387 - Max:  88.506
2025-09-03T13:37:54,047+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 9681441 msg --- 323553.7 msg/s ---    316.0 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  61.693 ms - med:  59.132 - 95pct:  82.565 - 99pct: 103.645 - 99.9pct: 129.098 - 99.99pct: 131.207 - Max: 131.346
2025-09-03T13:38:04,360+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 12719767 msg --- 294966.3 msg/s ---    288.1 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  67.764 ms - med:  60.242 - 95pct: 103.736 - 99pct: 264.611 - 99.9pct: 323.267 - 99.99pct: 328.375 - Max: 330.369
2025-09-03T13:38:14,631+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 15985131 msg --- 317436.9 msg/s ---    310.0 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  62.256 ms - med:  60.206 - 95pct:  80.621 - 99pct: 119.492 - 99.9pct: 131.500 - 99.99pct: 137.701 - Max: 138.530
2025-09-03T13:38:24,915+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 19228283 msg --- 316197.3 msg/s ---    308.8 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  63.158 ms - med:  59.091 - 95pct:  83.304 - 99pct: 148.024 - 99.9pct: 305.139 - 99.99pct: 307.847 - Max: 308.375
2025-09-03T13:38:35,225+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 21876285 msg --- 256696.3 msg/s ---    250.7 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  77.904 ms - med:  74.623 - 95pct: 110.860 - 99pct: 127.916 - 99.9pct: 160.067 - 99.99pct: 162.222 - Max: 163.047
2025-09-03T13:38:45,518+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 24725830 msg --- 276930.0 msg/s ---    270.4 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  71.977 ms - med:  69.348 - 95pct:  94.323 - 99pct: 124.832 - 99.9pct: 135.739 - 99.99pct: 137.425 - Max: 137.660
2025-09-03T13:38:55,795+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 27415989 msg --- 261118.6 msg/s ---    255.0 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  76.484 ms - med:  75.604 - 95pct:  92.618 - 99pct: 103.173 - 99.9pct: 113.024 - 99.99pct: 118.638 - Max: 119.452
2025-09-03T13:39:06,077+0000 [main] INFO  org.apache.pulsar.testclient.PerformanceProducer - Throughput produced: 29979710 msg --- 250047.8 msg/s ---    244.2 Mbit/s  --- failure      0.0 msg/s --- Latency: mean:  79.731 ms - med:  77.239 - 95pct: 103.463 - 99pct: 123.482 - 99.9pct: 132.509 - 99.99pct: 133.734 - Max: 136.183

it seems that dispatcherMaxReadBatchSize needs to be close to maxPendingPublishRequestsPerConnection value. This is also a sign that some queues are shared between producing and consuming, although there should only be a need when actual BK reads are made and the entries aren't found in the cache.