[improve] Trigger pending fetches when producing messages

[Demogorgon314]

Fixes #1419

Motivation

When the Kafka client issues a Fetch and sets a max wait time we are already scheduling a DelayedFetch, but there is no way to trigger that Fetch and it is deemed to wait for the full timeout. This adds latency spikes to the Kafka Consumer.

Modifications

Logic

1. Refactor the existing fetch logic to make the delayed fetch easier to implement.
2. Implement the DelayedFetch: The delayed fetch can be triggered by the produce operation but there are three cases:
   1. When trying to complete the operation triggered, get the last position failed(PositionImpl.EARLIEST), the delay fetch will complete immediately with the previous fetch result.
   2. When the previous last position is last then the current last position, try to adjust the max read entries num, and try to read the records again.
   3. On expiration happened, complete immediately with the previous fetch result.

Metrics

Add WAITING_FETCHES_TRIGGERED stats.

Benchmark Result

Here is some benchmark result with the following workloads in standalone env:

Workloads

---

topics: 1
partitionsPerTopic: 10
messageSize: 100
#payloadFile: "payload/payload-100b.data"
useRandomizedPayloads: true
randomBytesRatio: 0.5
randomizedPayloadPoolSize: 1000

subscriptionsPerTopic: 1
consumerPerSubscription: 10
producersPerTopic: 10

# Discover max-sustainable rate
producerRate: 200000

consumerBacklogSizeGB: 0
testDurationMinutes: 5

End To End Latency 95pct:

---

End To End Latency Avg:

---

End To End Latency Quantiles:

---

Documentation

Check the box below.

Need to update docs?

• [ ] doc-required

  (If you need help on updating docs, create a doc issue)

• [ ] no-need-doc

  (Please explain why)

• [x] doc

  (If this PR contains doc changes)

[Demogorgon314]

@BewareMyPower @eolivelli This PR is ready to get a quick review for earlier feedback.

[codecov[bot]]

Codecov Report

Merging #1423 (b172d3e) into master (349144a) will decrease coverage by 0.29%. The diff coverage is 2.26%.

@@             Coverage Diff              @@
##             master    #1423      +/-   ##
============================================
- Coverage     15.64%   15.34%   -0.30%     
+ Complexity      587      586       -1     
============================================
  Files           163      163              
  Lines         11681    11855     +174     
  Branches       1078     1097      +19     
============================================
- Hits           1827     1819       -8     
- Misses         9704     9881     +177     
- Partials        150      155       +5     

Impacted Files	Coverage Δ
...streamnative/pulsar/handlers/kop/DelayedFetch.java	0.00% <0.00%> (-38.47%)	:arrow_down:
...e/pulsar/handlers/kop/KafkaChannelInitializer.java	0.00% <0.00%> (ø)
...tive/pulsar/handlers/kop/KafkaProtocolHandler.java	0.00% <ø> (ø)
...ative/pulsar/handlers/kop/KafkaRequestHandler.java	1.16% <0.00%> (-0.05%)	:arrow_down:
...pulsar/handlers/kop/KafkaTopicConsumerManager.java	0.00% <ø> (ø)
...ative/pulsar/handlers/kop/MessageFetchContext.java	0.00% <0.00%> (-10.04%)	:arrow_down:
...streamnative/pulsar/handlers/kop/RequestStats.java	0.00% <0.00%> (ø)
...sar/handlers/kop/storage/AppendRecordsContext.java	0.00% <ø> (ø)
...lsar/handlers/kop/storage/PartitionLogManager.java	0.00% <0.00%> (ø)
...ve/pulsar/handlers/kop/storage/ReplicaManager.java	0.00% <0.00%> (ø)
... and 12 more

[gaozhangmin]

@Demogorgon314 Do we have test can reproduce the error Unexpected error code 7 while fetching data before applying this pr?

[Demogorgon314]

@gaozhangmin No, the error code 7 is caused by a timeout error when handling the fetch request.

If you check the Kafka code, you can see when the fetch request timeout, it will return an empty recodes. And it will never return the timeout error response.

As you mention, adding a test to cover this case is better. I'll add it later.

[eolivelli]

@Demogorgon314 @BewareMyPower what's the status of this patch ?

[Demogorgon314]

@eolivelli This patch is still in review.

[BewareMyPower]

@eolivelli @Demogorgon314 Sorry for the delayed review on this PR. I will review it ASAP.

[eolivelli]

@Demogorgon314 FYI I and @dave2wave are going to run performance tests over this patch and we will provide feedback. It seems that this patch has a good chance to solve p9X latency issues.

[Demogorgon314]

@eolivelli @dave2wave Thanks you all for providing feedback!

[BewareMyPower]

Overall LGTM. Merge this PR first.

[BewareMyPower]

Could this PR be cherry-picked into release branches?

[eolivelli]

@Demogorgon314 it is not clear to me the intent of commit b172d3e0855a5fe7acf68f9aedd00839047d8e04 you named it "address review comments" it looks like a forced push with the whole patch

can you please summarise ?

[Demogorgon314]

@eolivelli Oh, this commit just fixed your review comments. https://github.com/streamnative/kop/pull/1423#discussion_r974220673

[Demogorgon314]

Could this PR be cherry-picked into release branches?

@BewareMyPower I'll try to cherry-pick it to 2.9.x and 2.10.x, but I think we can wait for the performance test feedback before cherry-picking.

[eolivelli]

@eolivelli Oh, this commit just fixed your review comments. #1423 (comment)

thanks

[Demogorgon314]

@eolivelli It looks like commit https://github.com/streamnative/kop/commit/b172d3e0855a5fe7acf68f9aedd00839047d8e04 triggered the codecov check, It looks like forced push, but it only changed one line.

[dave2wave]

I ran OMB testing of DataStax's fork of KoP including this patch today from a build provided by @eolivelli .

TL/DR - The results can be summarized as follows:

1. The end to end latency is remarkably improved. Excellent work!
2. The publishing latency is slightly slower, but that is not surprising considering the "delayed fetch" in the new code.
3. There seems to be a resource leak given that later runs had worse end to end latency.

The tests were run on pretty robust cluster that is capable of 1 million messages per second of 100 byte payloads. We used an enhanced OMB based on the DS fork which allows for the produceRate to be stepped up incrementally. All test are 10 topics with 3 partitions.

A. Incremental Pulsar OMB from 20,000 to 400,000 mps of 1K payloads. B. Incremental KoP OMB from 20,000 to 400,000 mps of 1K payloads. C. KoP OMB at 400,000 mps of 1K payloads. One would expect that the performance would look similar to the last 5 minutes of the incremental KoP, but the latency is worse across the board. D. KoP OMB at 1 million mps of 100 byte payloads.

[dave2wave]

Later I ran another test B which was not as good as the first. My theory is that there is a resource leak happening. Here is some OMB output which should give you a comparison. B1.

16:55:52.813 [main] INFO - Created 10 topics in 613.167071 ms
16:55:52.813 [main] INFO - Topic: test-topic-COsZ-e0-0000
16:55:52.814 [main] INFO - Topic: test-topic-mr5HVco-0001
16:55:52.814 [main] INFO - Topic: test-topic-q2zRIwU-0002
16:55:52.814 [main] INFO - Topic: test-topic-7o4R2E0-0003
16:55:52.814 [main] INFO - Topic: test-topic-jaWLoZE-0004
16:55:52.814 [main] INFO - Topic: test-topic-Ktc_oAY-0005
16:55:52.814 [main] INFO - Topic: test-topic-XrdAERY-0006
16:55:52.814 [main] INFO - Topic: test-topic-JsL-Boc-0007
16:55:52.814 [main] INFO - Topic: test-topic-3ySMM18-0008
16:55:52.814 [main] INFO - Topic: test-topic-twEgz0o-0009
16:56:02.814 [main] INFO - Paused 10000.086999 ms
16:56:02.818 [main] INFO - Subscription: sub-000-PQstgAA for test-topic-COsZ-e0-0000
16:56:02.819 [main] INFO - Subscription: sub-000-iZkLsU4 for test-topic-mr5HVco-0001
16:56:02.819 [main] INFO - Subscription: sub-000-Dmc5zB8 for test-topic-q2zRIwU-0002
16:56:02.819 [main] INFO - Subscription: sub-000-zJrlFSs for test-topic-7o4R2E0-0003
16:56:02.819 [main] INFO - Subscription: sub-000-lAAhANk for test-topic-jaWLoZE-0004
16:56:02.819 [main] INFO - Subscription: sub-000-gXzY8LM for test-topic-Ktc_oAY-0005
16:56:02.820 [main] INFO - Subscription: sub-000-8lbdOw8 for test-topic-XrdAERY-0006
16:56:02.820 [main] INFO - Subscription: sub-000-0DXwEyE for test-topic-JsL-Boc-0007
16:56:02.820 [main] INFO - Subscription: sub-000-E9mJZM8 for test-topic-3ySMM18-0008
16:56:02.820 [main] INFO - Subscription: sub-000-7PP56_o for test-topic-twEgz0o-0009
16:56:02.873 [main] INFO - Created 10 consumers in 52.762048 ms
16:56:02.910 [main] INFO - Created 10 producers in 36.289315 ms
16:56:02.910 [main] INFO - Waiting for consumers to be ready (10 messages to be received)
16:56:06.302 [main] INFO - All consumers are ready
16:56:06.312 [main] INFO - ----- Starting warm-up traffic ------
16:56:16.687 [main] INFO - Pub rate 429957.2 msg/s / 419.9 MB/s | Cons rate 429934.1 msg/s / 419.9 MB/s | Backlog:  0.2 K | Pub Latency (ms) avg: 59.6 - 50%:  4.4 - 99%: 520.1 - 99.9%: 605.1 - Max: 672.7
16:56:26.855 [main] INFO - Pub rate 405600.2 msg/s / 396.1 MB/s | Cons rate 405521.4 msg/s / 396.0 MB/s | Backlog:  1.1 K | Pub Latency (ms) avg:  3.9 - 50%:  2.7 - 99%: 20.0 - 99.9%: 42.2 - Max: 53.3
16:56:36.968 [main] INFO - Pub rate 402093.5 msg/s / 392.7 MB/s | Cons rate 402128.2 msg/s / 392.7 MB/s | Backlog:  0.7 K | Pub Latency (ms) avg:  3.9 - 50%:  2.7 - 99%: 15.4 - 99.9%: 34.3 - Max: 43.4
16:56:47.086 [main] INFO - Pub rate 400618.8 msg/s / 391.2 MB/s | Cons rate 400659.6 msg/s / 391.3 MB/s | Backlog:  0.3 K | Pub Latency (ms) avg:  3.9 - 50%:  2.7 - 99%: 15.2 - 99.9%: 22.8 - Max: 30.4
16:56:57.201 [main] INFO - Pub rate 401198.2 msg/s / 391.8 MB/s | Cons rate 401107.1 msg/s / 391.7 MB/s | Backlog:  1.2 K | Pub Latency (ms) avg:  4.2 - 50%:  2.9 - 99%: 19.5 - 99.9%: 37.9 - Max: 56.6
16:57:07.309 [main] INFO - Pub rate 401094.4 msg/s / 391.7 MB/s | Cons rate 401180.1 msg/s / 391.8 MB/s | Backlog:  0.3 K | Pub Latency (ms) avg:  3.5 - 50%:  2.6 - 99%: 15.6 - 99.9%: 46.9 - Max: 55.7
16:57:07.497 [main] INFO - ----- Aggregated Pub Latency (ms) avg: 13.8 - 50%:  2.8 - 95%: 15.5 - 99%: 346.7 - 99.9%: 537.4 - 99.99%: 622.1 - Max: 672.7
16:57:07.649 [messaging-benchmark-4-1] INFO - Rate is now 20000
16:57:07.688 [main] INFO - ----- Starting benchmark traffic ------
16:57:17.790 [main] INFO - Pub rate 37381.4 msg/s / 36.5 MB/s | Cons rate 37415.4 msg/s / 36.5 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  1.7 - 50%:  1.7 - 99%:  6.8 - 99.9%: 11.4 - Max: 19.7
16:57:27.890 [main] INFO - Pub rate 20011.8 msg/s / 19.5 MB/s | Cons rate 20011.3 msg/s / 19.5 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  1.7 - 50%:  1.7 - 99%:  4.5 - 99.9%: 14.7 - Max: 21.4
16:57:37.652 [messaging-benchmark-4-1] INFO - Rate is now 40000
16:57:37.991 [main] INFO - Pub rate 20490.0 msg/s / 20.0 MB/s | Cons rate 20491.6 msg/s / 20.0 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  1.6 - 50%:  1.6 - 99%:  3.2 - 99.9%: 10.6 - Max: 22.6
16:57:48.090 [main] INFO - Pub rate 40039.6 msg/s / 39.1 MB/s | Cons rate 40037.5 msg/s / 39.1 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  1.6 - 50%:  1.7 - 99%:  3.2 - 99.9%:  5.3 - Max:  8.5
16:57:58.190 [main] INFO - Pub rate 40026.0 msg/s / 39.1 MB/s | Cons rate 40027.5 msg/s / 39.1 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  1.7 - 50%:  1.7 - 99%:  3.3 - 99.9%:  7.3 - Max: 15.8
16:58:07.655 [messaging-benchmark-4-1] INFO - Rate is now 60000
16:58:08.292 [main] INFO - Pub rate 41097.5 msg/s / 40.1 MB/s | Cons rate 41098.4 msg/s / 40.1 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  1.7 - 50%:  1.7 - 99%:  3.3 - 99.9%:  5.7 - Max:  9.5
16:58:18.392 [main] INFO - Pub rate 60011.1 msg/s / 58.6 MB/s | Cons rate 60010.6 msg/s / 58.6 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  1.7 - 50%:  1.8 - 99%:  3.7 - 99.9%:  6.1 - Max:  9.8
16:58:28.493 [main] INFO - Pub rate 59995.0 msg/s / 58.6 MB/s | Cons rate 59992.0 msg/s / 58.6 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  1.7 - 50%:  1.8 - 99%:  3.8 - 99.9%:  8.1 - Max: 15.4
16:58:37.657 [messaging-benchmark-4-1] INFO - Rate is now 80000
16:58:38.596 [main] INFO - Pub rate 61661.2 msg/s / 60.2 MB/s | Cons rate 61663.3 msg/s / 60.2 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  1.7 - 50%:  1.8 - 99%:  4.0 - 99.9%:  7.9 - Max: 14.4
16:58:48.697 [main] INFO - Pub rate 80209.4 msg/s / 78.3 MB/s | Cons rate 80210.5 msg/s / 78.3 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  1.9 - 50%:  1.8 - 99%:  4.7 - 99.9%: 13.1 - Max: 48.5
16:58:58.799 [main] INFO - Pub rate 80185.8 msg/s / 78.3 MB/s | Cons rate 80191.0 msg/s / 78.3 MB/s | Backlog: -0.1 K | Pub Latency (ms) avg:  1.9 - 50%:  1.9 - 99%:  4.5 - 99.9%:  9.9 - Max: 25.2
16:59:07.660 [messaging-benchmark-4-1] INFO - Rate is now 100000
16:59:08.898 [main] INFO - Pub rate 82485.8 msg/s / 80.6 MB/s | Cons rate 82484.4 msg/s / 80.6 MB/s | Backlog: -0.1 K | Pub Latency (ms) avg:  1.8 - 50%:  1.8 - 99%:  4.6 - 99.9%: 12.5 - Max: 20.8
16:59:19.001 [main] INFO - Pub rate 100370.8 msg/s / 98.0 MB/s | Cons rate 100367.9 msg/s / 98.0 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  1.9 - 50%:  1.9 - 99%:  4.7 - 99.9%: 11.8 - Max: 18.7
16:59:29.102 [main] INFO - Pub rate 100430.5 msg/s / 98.1 MB/s | Cons rate 100429.9 msg/s / 98.1 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  1.9 - 50%:  1.9 - 99%:  4.8 - 99.9%: 11.4 - Max: 16.0
16:59:37.663 [messaging-benchmark-4-1] INFO - Rate is now 120000
16:59:39.201 [main] INFO - Pub rate 103216.7 msg/s / 100.8 MB/s | Cons rate 103211.9 msg/s / 100.8 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  2.0 - 50%:  1.9 - 99%:  6.7 - 99.9%: 14.4 - Max: 22.8
16:59:49.302 [main] INFO - Pub rate 119984.6 msg/s / 117.2 MB/s | Cons rate 119988.1 msg/s / 117.2 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  1.9 - 50%:  1.9 - 99%:  4.9 - 99.9%: 11.7 - Max: 22.7
16:59:59.402 [main] INFO - Pub rate 120019.8 msg/s / 117.2 MB/s | Cons rate 120017.8 msg/s / 117.2 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  2.0 - 50%:  1.9 - 99%:  5.2 - 99.9%: 13.1 - Max: 20.2
17:00:07.667 [messaging-benchmark-4-1] INFO - Rate is now 140000
17:00:09.503 [main] INFO - Pub rate 123469.3 msg/s / 120.6 MB/s | Cons rate 123479.3 msg/s / 120.6 MB/s | Backlog: -0.1 K | Pub Latency (ms) avg:  2.0 - 50%:  1.9 - 99%:  5.3 - 99.9%: 12.2 - Max: 17.5
17:00:19.606 [main] INFO - Pub rate 140219.8 msg/s / 136.9 MB/s | Cons rate 140206.1 msg/s / 136.9 MB/s | Backlog:  0.1 K | Pub Latency (ms) avg:  2.1 - 50%:  1.9 - 99%:  6.0 - 99.9%: 30.1 - Max: 52.5
17:00:29.708 [main] INFO - Pub rate 140248.4 msg/s / 137.0 MB/s | Cons rate 140255.2 msg/s / 137.0 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  1.9 - 50%:  1.9 - 99%:  4.7 - 99.9%: 13.0 - Max: 48.8
17:00:37.670 [messaging-benchmark-4-1] INFO - Rate is now 160000
17:00:39.809 [main] INFO - Pub rate 144354.5 msg/s / 141.0 MB/s | Cons rate 144354.1 msg/s / 141.0 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  2.1 - 50%:  1.9 - 99%:  7.3 - 99.9%: 15.1 - Max: 26.0
17:00:49.911 [main] INFO - Pub rate 160396.1 msg/s / 156.6 MB/s | Cons rate 160395.1 msg/s / 156.6 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  2.6 - 50%:  2.1 - 99%: 10.1 - 99.9%: 16.2 - Max: 24.8
17:01:00.016 [main] INFO - Pub rate 160404.6 msg/s / 156.6 MB/s | Cons rate 160379.0 msg/s / 156.6 MB/s | Backlog:  0.3 K | Pub Latency (ms) avg:  2.7 - 50%:  2.2 - 99%: 11.5 - 99.9%: 47.8 - Max: 66.8
17:01:07.674 [messaging-benchmark-4-1] INFO - Rate is now 180000
17:01:10.119 [main] INFO - Pub rate 165145.2 msg/s / 161.3 MB/s | Cons rate 165152.3 msg/s / 161.3 MB/s | Backlog:  0.2 K | Pub Latency (ms) avg:  2.4 - 50%:  2.1 - 99%:  7.3 - 99.9%: 15.7 - Max: 23.3
17:01:20.222 [main] INFO - Pub rate 180493.8 msg/s / 176.3 MB/s | Cons rate 180497.1 msg/s / 176.3 MB/s | Backlog:  0.2 K | Pub Latency (ms) avg:  2.1 - 50%:  2.0 - 99%:  5.6 - 99.9%: 14.2 - Max: 25.1
17:01:30.321 [main] INFO - Pub rate 180505.1 msg/s / 176.3 MB/s | Cons rate 180515.8 msg/s / 176.3 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  2.3 - 50%:  2.0 - 99%:  7.9 - 99.9%: 14.6 - Max: 21.0
17:01:37.677 [messaging-benchmark-4-1] INFO - Rate is now 200000
17:01:40.421 [main] INFO - Pub rate 185794.5 msg/s / 181.4 MB/s | Cons rate 185795.0 msg/s / 181.4 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  2.2 - 50%:  2.0 - 99%:  6.5 - 99.9%: 12.7 - Max: 20.9
17:01:50.523 [main] INFO - Pub rate 200801.1 msg/s / 196.1 MB/s | Cons rate 200797.0 msg/s / 196.1 MB/s | Backlog:  0.1 K | Pub Latency (ms) avg:  2.3 - 50%:  2.0 - 99%:  7.7 - 99.9%: 39.9 - Max: 54.2
17:02:00.622 [main] INFO - Pub rate 200849.6 msg/s / 196.1 MB/s | Cons rate 200858.2 msg/s / 196.2 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  2.4 - 50%:  2.0 - 99%:  7.9 - 99.9%: 13.9 - Max: 23.4
17:02:07.680 [messaging-benchmark-4-1] INFO - Rate is now 220000
17:02:10.723 [main] INFO - Pub rate 206517.3 msg/s / 201.7 MB/s | Cons rate 206510.7 msg/s / 201.7 MB/s | Backlog:  0.1 K | Pub Latency (ms) avg:  2.2 - 50%:  2.0 - 99%:  7.1 - 99.9%: 17.5 - Max: 30.7
17:02:20.826 [main] INFO - Pub rate 220506.0 msg/s / 215.3 MB/s | Cons rate 220494.1 msg/s / 215.3 MB/s | Backlog:  0.2 K | Pub Latency (ms) avg:  2.5 - 50%:  2.1 - 99%:  7.3 - 99.9%: 68.8 - Max: 90.5
17:02:30.929 [main] INFO - Pub rate 220460.3 msg/s / 215.3 MB/s | Cons rate 220477.7 msg/s / 215.3 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  2.3 - 50%:  2.1 - 99%:  7.0 - 99.9%: 13.8 - Max: 19.8
17:02:37.683 [messaging-benchmark-4-1] INFO - Rate is now 240000
17:02:41.032 [main] INFO - Pub rate 226941.6 msg/s / 221.6 MB/s | Cons rate 226941.5 msg/s / 221.6 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  2.5 - 50%:  2.1 - 99%:  9.1 - 99.9%: 18.6 - Max: 27.1
17:02:51.136 [main] INFO - Pub rate 240446.0 msg/s / 234.8 MB/s | Cons rate 240430.7 msg/s / 234.8 MB/s | Backlog:  0.2 K | Pub Latency (ms) avg:  2.6 - 50%:  2.1 - 99%:  8.6 - 99.9%: 45.7 - Max: 52.2
17:03:01.250 [main] INFO - Pub rate 240203.3 msg/s / 234.6 MB/s | Cons rate 240218.8 msg/s / 234.6 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  2.5 - 50%:  2.1 - 99%:  7.6 - 99.9%: 17.0 - Max: 26.2
17:03:07.686 [messaging-benchmark-4-1] INFO - Rate is now 260000
17:03:11.357 [main] INFO - Pub rate 247692.0 msg/s / 241.9 MB/s | Cons rate 247671.3 msg/s / 241.9 MB/s | Backlog:  0.2 K | Pub Latency (ms) avg:  2.4 - 50%:  2.1 - 99%:  9.5 - 99.9%: 19.5 - Max: 31.4
17:03:21.460 [main] INFO - Pub rate 260662.9 msg/s / 254.6 MB/s | Cons rate 260659.0 msg/s / 254.5 MB/s | Backlog:  0.3 K | Pub Latency (ms) avg:  2.6 - 50%:  2.1 - 99%: 11.5 - 99.9%: 49.6 - Max: 59.0
17:03:31.568 [main] INFO - Pub rate 260390.5 msg/s / 254.3 MB/s | Cons rate 260397.7 msg/s / 254.3 MB/s | Backlog:  0.2 K | Pub Latency (ms) avg:  2.4 - 50%:  2.1 - 99%:  7.1 - 99.9%: 20.9 - Max: 51.9
17:03:37.689 [messaging-benchmark-4-1] INFO - Rate is now 280000
17:03:41.673 [main] INFO - Pub rate 268382.3 msg/s / 262.1 MB/s | Cons rate 268387.6 msg/s / 262.1 MB/s | Backlog:  0.1 K | Pub Latency (ms) avg:  2.6 - 50%:  2.1 - 99%: 10.9 - 99.9%: 22.5 - Max: 37.7
17:03:51.778 [main] INFO - Pub rate 280784.2 msg/s / 274.2 MB/s | Cons rate 280779.4 msg/s / 274.2 MB/s | Backlog:  0.2 K | Pub Latency (ms) avg:  2.4 - 50%:  2.1 - 99%:  7.5 - 99.9%: 19.8 - Max: 33.9
17:04:01.883 [main] INFO - Pub rate 280754.0 msg/s / 274.2 MB/s | Cons rate 280731.3 msg/s / 274.2 MB/s | Backlog:  0.4 K | Pub Latency (ms) avg:  2.6 - 50%:  2.2 - 99%: 11.3 - 99.9%: 20.5 - Max: 30.6
17:04:07.692 [messaging-benchmark-4-1] INFO - Rate is now 300000
17:04:11.990 [main] INFO - Pub rate 288668.8 msg/s / 281.9 MB/s | Cons rate 288704.6 msg/s / 281.9 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  2.5 - 50%:  2.1 - 99%:  7.6 - 99.9%: 22.8 - Max: 40.8
17:04:22.094 [main] INFO - Pub rate 300139.4 msg/s / 293.1 MB/s | Cons rate 300111.2 msg/s / 293.1 MB/s | Backlog:  0.3 K | Pub Latency (ms) avg:  2.8 - 50%:  2.3 - 99%:  8.4 - 99.9%: 17.8 - Max: 24.5
17:04:32.199 [main] INFO - Pub rate 299893.1 msg/s / 292.9 MB/s | Cons rate 299875.6 msg/s / 292.8 MB/s | Backlog:  0.5 K | Pub Latency (ms) avg:  3.4 - 50%:  2.3 - 99%: 14.0 - 99.9%: 29.2 - Max: 49.7
17:04:37.695 [messaging-benchmark-4-1] INFO - Rate is now 320000
17:04:42.304 [main] INFO - Pub rate 309166.4 msg/s / 301.9 MB/s | Cons rate 309149.1 msg/s / 301.9 MB/s | Backlog:  0.7 K | Pub Latency (ms) avg:  3.1 - 50%:  2.3 - 99%: 11.9 - 99.9%: 21.7 - Max: 42.4
17:04:52.412 [main] INFO - Pub rate 320443.6 msg/s / 312.9 MB/s | Cons rate 320409.9 msg/s / 312.9 MB/s | Backlog:  1.0 K | Pub Latency (ms) avg:  4.0 - 50%:  3.0 - 99%: 16.1 - 99.9%: 41.3 - Max: 66.2
17:05:02.517 [main] INFO - Pub rate 320554.2 msg/s / 313.0 MB/s | Cons rate 320595.1 msg/s / 313.1 MB/s | Backlog:  0.6 K | Pub Latency (ms) avg:  4.1 - 50%:  3.1 - 99%: 16.4 - 99.9%: 42.4 - Max: 73.3
17:05:07.698 [messaging-benchmark-4-1] INFO - Rate is now 340000
17:05:12.626 [main] INFO - Pub rate 330251.9 msg/s / 322.5 MB/s | Cons rate 330240.7 msg/s / 322.5 MB/s | Backlog:  0.7 K | Pub Latency (ms) avg:  3.9 - 50%:  2.9 - 99%: 14.4 - 99.9%: 26.2 - Max: 40.8
17:05:22.732 [main] INFO - Pub rate 341070.3 msg/s / 333.1 MB/s | Cons rate 341126.0 msg/s / 333.1 MB/s | Backlog:  0.2 K | Pub Latency (ms) avg:  3.2 - 50%:  2.3 - 99%: 16.4 - 99.9%: 79.8 - Max: 96.8
17:05:32.837 [main] INFO - Pub rate 341021.2 msg/s / 333.0 MB/s | Cons rate 341015.6 msg/s / 333.0 MB/s | Backlog:  0.2 K | Pub Latency (ms) avg:  2.7 - 50%:  2.3 - 99%:  9.8 - 99.9%: 16.8 - Max: 25.0
17:05:37.701 [messaging-benchmark-4-1] INFO - Rate is now 360000
17:05:42.946 [main] INFO - Pub rate 350857.3 msg/s / 342.6 MB/s | Cons rate 350834.1 msg/s / 342.6 MB/s | Backlog:  0.5 K | Pub Latency (ms) avg:  3.3 - 50%:  2.3 - 99%: 20.4 - 99.9%: 65.5 - Max: 78.4
17:05:53.053 [main] INFO - Pub rate 360654.8 msg/s / 352.2 MB/s | Cons rate 360668.2 msg/s / 352.2 MB/s | Backlog:  0.3 K | Pub Latency (ms) avg:  3.1 - 50%:  2.3 - 99%: 12.9 - 99.9%: 22.8 - Max: 34.3
17:06:03.160 [main] INFO - Pub rate 360317.1 msg/s / 351.9 MB/s | Cons rate 359685.8 msg/s / 351.3 MB/s | Backlog:  6.7 K | Pub Latency (ms) avg:  3.3 - 50%:  2.4 - 99%: 13.3 - 99.9%: 41.7 - Max: 69.1
17:06:07.703 [messaging-benchmark-4-1] INFO - Rate is now 380000
17:06:13.264 [main] INFO - Pub rate 372130.3 msg/s / 363.4 MB/s | Cons rate 372756.8 msg/s / 364.0 MB/s | Backlog:  0.4 K | Pub Latency (ms) avg:  3.7 - 50%:  2.6 - 99%: 14.7 - 99.9%: 27.2 - Max: 62.3
17:06:23.377 [main] INFO - Pub rate 380785.2 msg/s / 371.9 MB/s | Cons rate 380792.3 msg/s / 371.9 MB/s | Backlog:  0.3 K | Pub Latency (ms) avg:  3.4 - 50%:  2.5 - 99%: 14.2 - 99.9%: 24.6 - Max: 40.1
17:06:33.487 [main] INFO - Pub rate 381464.1 msg/s / 372.5 MB/s | Cons rate 381431.5 msg/s / 372.5 MB/s | Backlog:  0.6 K | Pub Latency (ms) avg:  3.5 - 50%:  2.5 - 99%: 13.8 - 99.9%: 21.9 - Max: 32.0
17:06:37.706 [messaging-benchmark-4-1] INFO - Rate is now 400000
17:06:43.592 [main] INFO - Pub rate 392585.7 msg/s / 383.4 MB/s | Cons rate 392573.2 msg/s / 383.4 MB/s | Backlog:  0.8 K | Pub Latency (ms) avg:  3.7 - 50%:  2.6 - 99%: 13.3 - 99.9%: 23.3 - Max: 44.8
17:06:53.696 [main] INFO - Pub rate 400935.3 msg/s / 391.5 MB/s | Cons rate 400918.0 msg/s / 391.5 MB/s | Backlog:  0.9 K | Pub Latency (ms) avg:  3.4 - 50%:  2.6 - 99%: 13.7 - 99.9%: 25.7 - Max: 44.5
17:07:03.802 [main] INFO - Pub rate 400647.8 msg/s / 391.3 MB/s | Cons rate 400689.5 msg/s / 391.3 MB/s | Backlog:  0.5 K | Pub Latency (ms) avg:  3.7 - 50%:  2.6 - 99%: 14.3 - 99.9%: 24.3 - Max: 38.4
17:07:13.911 [main] INFO - Pub rate 401006.8 msg/s / 391.6 MB/s | Cons rate 400923.0 msg/s / 391.5 MB/s | Backlog:  1.4 K | Pub Latency (ms) avg:  3.7 - 50%:  2.6 - 99%: 15.2 - 99.9%: 74.0 - Max: 92.4
17:07:24.022 [main] INFO - Pub rate 400779.9 msg/s / 391.4 MB/s | Cons rate 400858.7 msg/s / 391.5 MB/s | Backlog:  0.6 K | Pub Latency (ms) avg:  3.5 - 50%:  2.6 - 99%: 15.3 - 99.9%: 33.3 - Max: 88.4
17:07:34.131 [main] INFO - Pub rate 400977.1 msg/s / 391.6 MB/s | Cons rate 400964.6 msg/s / 391.6 MB/s | Backlog:  0.7 K | Pub Latency (ms) avg:  3.4 - 50%:  2.6 - 99%: 13.1 - 99.9%: 25.9 - Max: 44.7
17:07:44.236 [main] INFO - Pub rate 400988.2 msg/s / 391.6 MB/s | Cons rate 401008.7 msg/s / 391.6 MB/s | Backlog:  0.5 K | Pub Latency (ms) avg:  3.5 - 50%:  2.6 - 99%: 16.5 - 99.9%: 30.2 - Max: 52.4
17:07:54.345 [main] INFO - Pub rate 400778.9 msg/s / 391.4 MB/s | Cons rate 400783.1 msg/s / 391.4 MB/s | Backlog:  0.4 K | Pub Latency (ms) avg:  3.7 - 50%:  2.7 - 99%: 11.8 - 99.9%: 25.3 - Max: 74.3
17:08:04.454 [main] INFO - Pub rate 400366.5 msg/s / 391.0 MB/s | Cons rate 400367.2 msg/s / 391.0 MB/s | Backlog:  0.4 K | Pub Latency (ms) avg:  3.6 - 50%:  2.6 - 99%: 20.1 - 99.9%: 68.8 - Max: 77.2
17:08:14.565 [main] INFO - Pub rate 401389.9 msg/s / 392.0 MB/s | Cons rate 401372.9 msg/s / 392.0 MB/s | Backlog:  0.6 K | Pub Latency (ms) avg:  4.1 - 50%:  2.7 - 99%: 23.3 - 99.9%: 65.9 - Max: 87.3
17:08:24.671 [main] INFO - Pub rate 400966.5 msg/s / 391.6 MB/s | Cons rate 401007.5 msg/s / 391.6 MB/s | Backlog:  0.2 K | Pub Latency (ms) avg:  3.5 - 50%:  2.6 - 99%: 11.8 - 99.9%: 19.7 - Max: 25.3
17:08:34.779 [main] INFO - Pub rate 400854.5 msg/s / 391.5 MB/s | Cons rate 400778.1 msg/s / 391.4 MB/s | Backlog:  1.0 K | Pub Latency (ms) avg:  4.1 - 50%:  2.6 - 99%: 23.9 - 99.9%: 71.8 - Max: 78.9
17:08:44.888 [main] INFO - Pub rate 400781.3 msg/s / 391.4 MB/s | Cons rate 400751.4 msg/s / 391.4 MB/s | Backlog:  1.3 K | Pub Latency (ms) avg:  4.0 - 50%:  2.9 - 99%: 13.8 - 99.9%: 23.9 - Max: 37.1
17:08:54.991 [main] INFO - Pub rate 400936.2 msg/s / 391.5 MB/s | Cons rate 400684.4 msg/s / 391.3 MB/s | Backlog:  3.8 K | Pub Latency (ms) avg:  4.1 - 50%:  3.1 - 99%: 13.0 - 99.9%: 21.2 - Max: 29.7
17:09:05.097 [main] INFO - Pub rate 400787.7 msg/s / 391.4 MB/s | Cons rate 401094.2 msg/s / 391.7 MB/s | Backlog:  0.7 K | Pub Latency (ms) avg:  4.5 - 50%:  3.4 - 99%: 20.2 - 99.9%: 35.0 - Max: 49.7
17:09:15.201 [main] INFO - Pub rate 401317.8 msg/s / 391.9 MB/s | Cons rate 401222.1 msg/s / 391.8 MB/s | Backlog:  1.7 K | Pub Latency (ms) avg:  3.6 - 50%:  2.7 - 99%: 11.3 - 99.9%: 18.4 - Max: 29.9
17:09:25.305 [main] INFO - Pub rate 400582.7 msg/s / 391.2 MB/s | Cons rate 400692.8 msg/s / 391.3 MB/s | Backlog:  0.6 K | Pub Latency (ms) avg:  3.9 - 50%:  2.7 - 99%: 15.6 - 99.9%: 27.4 - Max: 39.9
17:09:35.409 [main] INFO - Pub rate 401114.5 msg/s / 391.7 MB/s | Cons rate 401103.5 msg/s / 391.7 MB/s | Backlog:  0.7 K | Pub Latency (ms) avg:  4.2 - 50%:  2.9 - 99%: 14.3 - 99.9%: 20.5 - Max: 28.8
17:09:45.516 [main] INFO - Pub rate 400710.5 msg/s / 391.3 MB/s | Cons rate 400615.0 msg/s / 391.2 MB/s | Backlog:  1.6 K | Pub Latency (ms) avg:  3.6 - 50%:  2.7 - 99%: 15.4 - 99.9%: 25.8 - Max: 45.1
17:09:55.621 [main] INFO - Pub rate 401041.1 msg/s / 391.6 MB/s | Cons rate 401154.7 msg/s / 391.8 MB/s | Backlog:  0.5 K | Pub Latency (ms) avg:  4.3 - 50%:  3.2 - 99%: 15.5 - 99.9%: 38.5 - Max: 66.1
17:10:05.725 [main] INFO - Pub rate 400920.2 msg/s / 391.5 MB/s | Cons rate 400942.7 msg/s / 391.5 MB/s | Backlog:  0.3 K | Pub Latency (ms) avg:  3.8 - 50%:  3.0 - 99%: 12.1 - 99.9%: 21.0 - Max: 28.7
17:10:15.830 [main] INFO - Pub rate 400666.6 msg/s / 391.3 MB/s | Cons rate 400601.2 msg/s / 391.2 MB/s | Backlog:  0.9 K | Pub Latency (ms) avg:  3.5 - 50%:  2.6 - 99%: 13.2 - 99.9%: 58.5 - Max: 84.1
17:10:25.939 [main] INFO - Pub rate 400932.9 msg/s / 391.5 MB/s | Cons rate 400983.5 msg/s / 391.6 MB/s | Backlog:  0.4 K | Pub Latency (ms) avg:  3.9 - 50%:  2.7 - 99%: 17.3 - 99.9%: 51.6 - Max: 70.8
17:10:36.046 [main] INFO - Pub rate 400947.8 msg/s / 391.6 MB/s | Cons rate 400946.4 msg/s / 391.5 MB/s | Backlog:  0.4 K | Pub Latency (ms) avg:  3.3 - 50%:  2.5 - 99%: 13.7 - 99.9%: 30.8 - Max: 69.9
17:10:46.154 [main] INFO - Pub rate 400768.6 msg/s / 391.4 MB/s | Cons rate 400741.4 msg/s / 391.3 MB/s | Backlog:  0.7 K | Pub Latency (ms) avg:  4.1 - 50%:  2.8 - 99%: 15.5 - 99.9%: 46.4 - Max: 75.6
17:10:56.266 [main] INFO - Pub rate 400734.4 msg/s / 391.3 MB/s | Cons rate 400727.9 msg/s / 391.3 MB/s | Backlog:  0.8 K | Pub Latency (ms) avg:  3.7 - 50%:  2.7 - 99%: 13.9 - 99.9%: 43.9 - Max: 67.1
17:11:06.372 [main] INFO - Pub rate 401164.5 msg/s / 391.8 MB/s | Cons rate 401116.9 msg/s / 391.7 MB/s | Backlog:  1.2 K | Pub Latency (ms) avg:  3.9 - 50%:  2.8 - 99%: 14.5 - 99.9%: 24.9 - Max: 57.0
17:11:16.481 [main] INFO - Pub rate 400815.3 msg/s / 391.4 MB/s | Cons rate 400886.6 msg/s / 391.5 MB/s | Backlog:  0.5 K | Pub Latency (ms) avg:  3.6 - 50%:  2.6 - 99%: 14.5 - 99.9%: 25.9 - Max: 38.3
17:11:26.585 [main] INFO - Pub rate 401066.8 msg/s / 391.7 MB/s | Cons rate 401056.9 msg/s / 391.7 MB/s | Backlog:  0.6 K | Pub Latency (ms) avg:  3.8 - 50%:  2.7 - 99%: 12.7 - 99.9%: 23.5 - Max: 43.4
17:11:36.690 [main] INFO - Pub rate 400856.1 msg/s / 391.5 MB/s | Cons rate 400766.8 msg/s / 391.4 MB/s | Backlog:  1.5 K | Pub Latency (ms) avg:  4.0 - 50%:  2.8 - 99%: 14.9 - 99.9%: 24.3 - Max: 38.6
17:11:46.799 [main] INFO - Pub rate 400616.0 msg/s / 391.2 MB/s | Cons rate 400691.7 msg/s / 391.3 MB/s | Backlog:  0.8 K | Pub Latency (ms) avg:  3.8 - 50%:  2.7 - 99%: 14.4 - 99.9%: 30.2 - Max: 47.8
17:11:56.910 [main] INFO - Pub rate 400829.3 msg/s / 391.4 MB/s | Cons rate 400874.7 msg/s / 391.5 MB/s | Backlog:  0.3 K | Pub Latency (ms) avg:  4.3 - 50%:  2.8 - 99%: 19.5 - 99.9%: 55.7 - Max: 62.8
17:12:07.018 [main] INFO - Pub rate 400989.9 msg/s / 391.6 MB/s | Cons rate 401001.8 msg/s / 391.6 MB/s | Backlog:  0.2 K | Pub Latency (ms) avg:  4.3 - 50%:  2.9 - 99%: 15.0 - 99.9%: 23.1 - Max: 34.6
17:12:17.124 [main] INFO - Pub rate 401083.5 msg/s / 391.7 MB/s | Cons rate 401039.8 msg/s / 391.6 MB/s | Backlog:  0.6 K | Pub Latency (ms) avg:  4.2 - 50%:  2.9 - 99%: 14.7 - 99.9%: 26.1 - Max: 34.3
17:12:17.240 [main] INFO - ----- Aggregated Pub Latency (ms) avg:  3.4 - 50%:  2.4 - 95%:  8.0 - 99%: 13.5 - 99.9%: 35.4 - 99.99%: 71.5 - Max: 96.8
17:12:17.563 [main] INFO - Writing test result into 400k-10-topics-3-partitions-1k-increment-Kafka-2022-11-08-17-12-17.json

B2.

21:31:32.833 [main] INFO - Created 10 topics in 246.544177 ms
21:31:32.833 [main] INFO - Topic: test-topic-Trf180w-0000
21:31:32.833 [main] INFO - Topic: test-topic-Ym9dhAs-0001
21:31:32.833 [main] INFO - Topic: test-topic-eCxt_m0-0002
21:31:32.833 [main] INFO - Topic: test-topic-1ohtBYo-0003
21:31:32.833 [main] INFO - Topic: test-topic-HwW_uwo-0004
21:31:32.833 [main] INFO - Topic: test-topic-K7ds_00-0005
21:31:32.833 [main] INFO - Topic: test-topic-SmImdqk-0006
21:31:32.833 [main] INFO - Topic: test-topic-6Dgjs4k-0007
21:31:32.833 [main] INFO - Topic: test-topic-rI1vKYU-0008
21:31:32.833 [main] INFO - Topic: test-topic-h8rRp6I-0009
21:31:42.833 [main] INFO - Paused 10000.088735 ms
21:31:42.837 [main] INFO - Subscription: sub-000-76764m0 for test-topic-Trf180w-0000
21:31:42.838 [main] INFO - Subscription: sub-000-Pj_Lpyk for test-topic-Ym9dhAs-0001
21:31:42.838 [main] INFO - Subscription: sub-000-6dW2zzg for test-topic-eCxt_m0-0002
21:31:42.838 [main] INFO - Subscription: sub-000-FEPeZTs for test-topic-1ohtBYo-0003
21:31:42.838 [main] INFO - Subscription: sub-000-ixFbCxU for test-topic-HwW_uwo-0004
21:31:42.838 [main] INFO - Subscription: sub-000-lkyNK60 for test-topic-K7ds_00-0005
21:31:42.838 [main] INFO - Subscription: sub-000-3xZIoUU for test-topic-SmImdqk-0006
21:31:42.838 [main] INFO - Subscription: sub-000-roFs5PA for test-topic-6Dgjs4k-0007
21:31:42.838 [main] INFO - Subscription: sub-000-_hggXzA for test-topic-rI1vKYU-0008
21:31:42.838 [main] INFO - Subscription: sub-000-N0DRTdA for test-topic-h8rRp6I-0009
21:31:42.852 [main] INFO - Created 10 consumers in 13.633972 ms
21:31:42.864 [main] INFO - Created 10 producers in 11.44043 ms
21:31:42.864 [main] INFO - Waiting for consumers to be ready (10 messages to be received)
21:31:46.154 [main] INFO - All consumers are ready
21:31:46.164 [main] INFO - ----- Starting warm-up traffic ------
21:31:56.484 [main] INFO - Pub rate 430743.4 msg/s / 420.6 MB/s | Cons rate 430628.4 msg/s / 420.5 MB/s | Backlog:  1.2 K | Pub Latency (ms) avg: 28.9 - 50%:  4.3 - 99%: 344.4 - 99.9%: 400.0 - Max: 443.0
21:32:06.629 [main] INFO - Pub rate 405263.0 msg/s / 395.8 MB/s | Cons rate 405296.4 msg/s / 395.8 MB/s | Backlog:  0.8 K | Pub Latency (ms) avg:  4.2 - 50%:  3.6 - 99%: 11.1 - 99.9%: 15.4 - Max: 47.9
21:32:16.753 [main] INFO - Pub rate 401135.8 msg/s / 391.7 MB/s | Cons rate 401129.2 msg/s / 391.7 MB/s | Backlog:  0.9 K | Pub Latency (ms) avg:  4.2 - 50%:  3.4 - 99%: 12.1 - 99.9%: 26.1 - Max: 45.2
21:32:26.875 [main] INFO - Pub rate 401003.7 msg/s / 391.6 MB/s | Cons rate 400978.9 msg/s / 391.6 MB/s | Backlog:  1.2 K | Pub Latency (ms) avg:  4.6 - 50%:  3.5 - 99%: 23.7 - 99.9%: 71.9 - Max: 82.2
21:32:36.999 [main] INFO - Pub rate 400836.2 msg/s / 391.4 MB/s | Cons rate 400675.9 msg/s / 391.3 MB/s | Backlog:  2.8 K | Pub Latency (ms) avg:  4.3 - 50%:  3.5 - 99%: 14.2 - 99.9%: 25.5 - Max: 37.7
21:32:47.110 [main] INFO - Pub rate 401380.2 msg/s / 392.0 MB/s | Cons rate 401551.7 msg/s / 392.1 MB/s | Backlog:  1.1 K | Pub Latency (ms) avg:  4.1 - 50%:  3.4 - 99%: 11.8 - 99.9%: 25.8 - Max: 48.9
21:32:47.258 [main] INFO - ----- Aggregated Pub Latency (ms) avg:  8.7 - 50%:  3.6 - 95%: 10.2 - 99%: 197.8 - 99.9%: 363.6 - 99.99%: 414.3 - Max: 443.0
21:32:47.356 [messaging-benchmark-4-1] INFO - Rate is now 20000
21:32:47.396 [main] INFO - ----- Starting benchmark traffic ------
21:32:57.497 [main] INFO - Pub rate 33845.7 msg/s / 33.1 MB/s | Cons rate 33950.0 msg/s / 33.2 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  1.7 - 50%:  1.7 - 99%:  5.1 - 99.9%: 16.9 - Max: 25.5
21:33:07.597 [main] INFO - Pub rate 20012.4 msg/s / 19.5 MB/s | Cons rate 20012.6 msg/s / 19.5 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  1.6 - 50%:  1.7 - 99%:  3.7 - 99.9%: 11.4 - Max: 22.9
21:33:17.358 [messaging-benchmark-4-1] INFO - Rate is now 40000
21:33:17.697 [main] INFO - Pub rate 20487.9 msg/s / 20.0 MB/s | Cons rate 20490.4 msg/s / 20.0 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  1.6 - 50%:  1.7 - 99%:  3.4 - 99.9%:  8.6 - Max: 19.9
21:33:27.797 [main] INFO - Pub rate 40033.5 msg/s / 39.1 MB/s | Cons rate 40030.1 msg/s / 39.1 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  1.7 - 50%:  1.7 - 99%:  3.6 - 99.9%:  6.3 - Max: 13.9
21:33:37.899 [main] INFO - Pub rate 40026.3 msg/s / 39.1 MB/s | Cons rate 40027.2 msg/s / 39.1 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  1.8 - 50%:  1.7 - 99%:  5.8 - 99.9%: 11.1 - Max: 16.3
21:33:47.361 [messaging-benchmark-4-1] INFO - Rate is now 60000
21:33:48.002 [main] INFO - Pub rate 41097.7 msg/s / 40.1 MB/s | Cons rate 41097.8 msg/s / 40.1 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  1.8 - 50%:  1.8 - 99%:  4.4 - 99.9%:  8.0 - Max: 15.8
21:33:58.103 [main] INFO - Pub rate 60019.0 msg/s / 58.6 MB/s | Cons rate 60018.8 msg/s / 58.6 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  1.8 - 50%:  1.8 - 99%:  4.6 - 99.9%:  8.5 - Max: 16.2
21:34:08.201 [main] INFO - Pub rate 60007.1 msg/s / 58.6 MB/s | Cons rate 60005.3 msg/s / 58.6 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  1.8 - 50%:  1.8 - 99%:  4.4 - 99.9%:  8.2 - Max: 12.6
21:34:17.364 [messaging-benchmark-4-1] INFO - Rate is now 80000
21:34:18.302 [main] INFO - Pub rate 61671.4 msg/s / 60.2 MB/s | Cons rate 61672.2 msg/s / 60.2 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  1.8 - 50%:  1.8 - 99%:  4.2 - 99.9%:  8.5 - Max: 18.3
21:34:28.406 [main] INFO - Pub rate 80171.6 msg/s / 78.3 MB/s | Cons rate 80167.7 msg/s / 78.3 MB/s | Backlog:  0.1 K | Pub Latency (ms) avg:  2.0 - 50%:  1.9 - 99%:  5.7 - 99.9%: 14.8 - Max: 27.9
21:34:38.505 [main] INFO - Pub rate 80210.9 msg/s / 78.3 MB/s | Cons rate 80218.0 msg/s / 78.3 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  2.0 - 50%:  1.9 - 99%:  5.6 - 99.9%: 24.6 - Max: 39.9
21:34:47.367 [messaging-benchmark-4-1] INFO - Rate is now 100000
21:34:48.608 [main] INFO - Pub rate 82456.7 msg/s / 80.5 MB/s | Cons rate 82454.4 msg/s / 80.5 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  2.0 - 50%:  1.9 - 99%:  5.7 - 99.9%: 16.3 - Max: 23.8
21:34:58.709 [main] INFO - Pub rate 100422.5 msg/s / 98.1 MB/s | Cons rate 100421.7 msg/s / 98.1 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  2.1 - 50%:  2.0 - 99%:  6.5 - 99.9%: 16.2 - Max: 24.3
21:35:08.812 [main] INFO - Pub rate 100390.6 msg/s / 98.0 MB/s | Cons rate 100387.4 msg/s / 98.0 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  2.2 - 50%:  1.9 - 99%:  6.4 - 99.9%: 56.0 - Max: 71.7
21:35:17.369 [messaging-benchmark-4-1] INFO - Rate is now 120000
21:35:18.914 [main] INFO - Pub rate 103220.9 msg/s / 100.8 MB/s | Cons rate 103223.5 msg/s / 100.8 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  2.0 - 50%:  1.9 - 99%:  5.0 - 99.9%: 11.5 - Max: 23.0
21:35:29.015 [main] INFO - Pub rate 119998.2 msg/s / 117.2 MB/s | Cons rate 120001.0 msg/s / 117.2 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  2.2 - 50%:  2.0 - 99%:  7.7 - 99.9%: 21.3 - Max: 38.7
21:35:39.117 [main] INFO - Pub rate 120014.3 msg/s / 117.2 MB/s | Cons rate 120014.5 msg/s / 117.2 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  2.1 - 50%:  1.9 - 99%:  6.4 - 99.9%: 24.9 - Max: 46.6
21:35:47.372 [messaging-benchmark-4-1] INFO - Rate is now 140000
21:35:49.221 [main] INFO - Pub rate 123465.8 msg/s / 120.6 MB/s | Cons rate 123451.3 msg/s / 120.6 MB/s | Backlog:  0.1 K | Pub Latency (ms) avg:  2.5 - 50%:  2.1 - 99%: 10.5 - 99.9%: 26.1 - Max: 40.4
21:35:59.326 [main] INFO - Pub rate 140232.2 msg/s / 136.9 MB/s | Cons rate 140228.7 msg/s / 136.9 MB/s | Backlog:  0.2 K | Pub Latency (ms) avg:  2.3 - 50%:  2.1 - 99%:  6.1 - 99.9%: 15.2 - Max: 29.4
21:36:09.427 [main] INFO - Pub rate 140284.0 msg/s / 137.0 MB/s | Cons rate 140295.7 msg/s / 137.0 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  2.1 - 50%:  2.0 - 99%:  5.9 - 99.9%: 19.5 - Max: 26.9
21:36:17.375 [messaging-benchmark-4-1] INFO - Rate is now 160000
21:36:19.533 [main] INFO - Pub rate 144273.2 msg/s / 140.9 MB/s | Cons rate 144265.9 msg/s / 140.9 MB/s | Backlog:  0.1 K | Pub Latency (ms) avg:  2.2 - 50%:  2.0 - 99%:  7.0 - 99.9%: 15.9 - Max: 23.4
21:36:29.637 [main] INFO - Pub rate 160426.2 msg/s / 156.7 MB/s | Cons rate 160439.2 msg/s / 156.7 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg:  2.3 - 50%:  2.0 - 99%:  8.1 - 99.9%: 69.0 - Max: 89.3
21:36:39.739 [main] INFO - Pub rate 160526.1 msg/s / 156.8 MB/s | Cons rate 160517.0 msg/s / 156.8 MB/s | Backlog:  0.1 K | Pub Latency (ms) avg:  2.4 - 50%:  2.0 - 99%: 10.5 - 99.9%: 35.1 - Max: 60.8
21:36:47.378 [messaging-benchmark-4-1] INFO - Rate is now 180000
21:36:49.841 [main] INFO - Pub rate 165111.5 msg/s / 161.2 MB/s | Cons rate 165105.7 msg/s / 161.2 MB/s | Backlog:  0.1 K | Pub Latency (ms) avg:  2.4 - 50%:  2.1 - 99%:  7.2 - 99.9%: 20.0 - Max: 35.8
21:36:59.944 [main] INFO - Pub rate 180451.7 msg/s / 176.2 MB/s | Cons rate 180451.7 msg/s / 176.2 MB/s | Backlog:  0.1 K | Pub Latency (ms) avg:  2.5 - 50%:  2.2 - 99%:  7.3 - 99.9%: 16.7 - Max: 27.2
21:37:10.047 [main] INFO - Pub rate 180486.8 msg/s / 176.3 MB/s | Cons rate 180492.6 msg/s / 176.3 MB/s | Backlog:  0.1 K | Pub Latency (ms) avg:  2.7 - 50%:  2.2 - 99%: 10.2 - 99.9%: 19.2 - Max: 29.5
21:37:17.380 [messaging-benchmark-4-1] INFO - Rate is now 200000
21:37:20.149 [main] INFO - Pub rate 185839.2 msg/s / 181.5 MB/s | Cons rate 185821.8 msg/s / 181.5 MB/s | Backlog:  0.3 K | Pub Latency (ms) avg:  2.6 - 50%:  2.1 - 99%:  8.5 - 99.9%: 24.6 - Max: 41.3
21:37:30.251 [main] INFO - Pub rate 200829.4 msg/s / 196.1 MB/s | Cons rate 200717.8 msg/s / 196.0 MB/s | Backlog:  1.4 K | Pub Latency (ms) avg:  2.6 - 50%:  2.1 - 99%:  9.7 - 99.9%: 22.2 - Max: 36.1
21:37:40.353 [main] INFO - Pub rate 200802.2 msg/s / 196.1 MB/s | Cons rate 200915.7 msg/s / 196.2 MB/s | Backlog:  0.2 K | Pub Latency (ms) avg:  2.4 - 50%:  2.1 - 99%:  7.3 - 99.9%: 17.3 - Max: 23.9
21:37:47.383 [messaging-benchmark-4-1] INFO - Rate is now 220000
21:37:50.454 [main] INFO - Pub rate 206646.8 msg/s / 201.8 MB/s | Cons rate 206657.2 msg/s / 201.8 MB/s | Backlog:  0.1 K | Pub Latency (ms) avg:  2.4 - 50%:  2.2 - 99%:  7.3 - 99.9%: 15.2 - Max: 28.3
21:38:00.559 [main] INFO - Pub rate 220431.0 msg/s / 215.3 MB/s | Cons rate 220415.9 msg/s / 215.2 MB/s | Backlog:  0.3 K | Pub Latency (ms) avg:  2.9 - 50%:  2.2 - 99%: 11.1 - 99.9%: 24.9 - Max: 38.2
21:38:10.661 [main] INFO - Pub rate 220573.5 msg/s / 215.4 MB/s | Cons rate 220552.1 msg/s / 215.4 MB/s | Backlog:  0.5 K | Pub Latency (ms) avg:  2.9 - 50%:  2.2 - 99%:  9.2 - 99.9%: 48.3 - Max: 71.1
21:38:17.386 [messaging-benchmark-4-1] INFO - Rate is now 240000
21:38:20.762 [main] INFO - Pub rate 226992.0 msg/s / 221.7 MB/s | Cons rate 227025.2 msg/s / 221.7 MB/s | Backlog:  0.2 K | Pub Latency (ms) avg:  2.7 - 50%:  2.2 - 99%:  9.8 - 99.9%: 21.3 - Max: 30.0
21:38:30.863 [main] INFO - Pub rate 240404.0 msg/s / 234.8 MB/s | Cons rate 240388.9 msg/s / 234.8 MB/s | Backlog:  0.3 K | Pub Latency (ms) avg:  2.9 - 50%:  2.3 - 99%: 10.4 - 99.9%: 21.7 - Max: 31.0
21:38:40.968 [main] INFO - Pub rate 240374.6 msg/s / 234.7 MB/s | Cons rate 240363.8 msg/s / 234.7 MB/s | Backlog:  0.4 K | Pub Latency (ms) avg:  3.1 - 50%:  2.3 - 99%: 13.4 - 99.9%: 27.3 - Max: 53.0
21:38:47.389 [messaging-benchmark-4-1] INFO - Rate is now 260000
21:38:51.072 [main] INFO - Pub rate 247607.4 msg/s / 241.8 MB/s | Cons rate 247650.6 msg/s / 241.8 MB/s | Backlog:  0.0 K | Pub Latency (ms) avg:  3.2 - 50%:  2.6 - 99%:  9.9 - 99.9%: 24.7 - Max: 31.8
21:39:01.173 [main] INFO - Pub rate 260612.0 msg/s / 254.5 MB/s | Cons rate 260584.3 msg/s / 254.5 MB/s | Backlog:  0.3 K | Pub Latency (ms) avg:  3.3 - 50%:  2.6 - 99%: 12.2 - 99.9%: 26.7 - Max: 40.2
21:39:11.276 [main] INFO - Pub rate 260567.7 msg/s / 254.5 MB/s | Cons rate 260552.6 msg/s / 254.4 MB/s | Backlog:  0.4 K | Pub Latency (ms) avg:  3.1 - 50%:  2.4 - 99%: 12.1 - 99.9%: 55.3 - Max: 72.2
21:39:17.392 [messaging-benchmark-4-1] INFO - Rate is now 280000
21:39:21.379 [main] INFO - Pub rate 268171.3 msg/s / 261.9 MB/s | Cons rate 268224.0 msg/s / 261.9 MB/s | Backlog: -0.1 K | Pub Latency (ms) avg:  3.4 - 50%:  2.6 - 99%: 11.2 - 99.9%: 24.2 - Max: 30.9
21:39:31.484 [main] INFO - Pub rate 280805.9 msg/s / 274.2 MB/s | Cons rate 280767.2 msg/s / 274.2 MB/s | Backlog:  0.3 K | Pub Latency (ms) avg:  3.5 - 50%:  2.6 - 99%: 12.3 - 99.9%: 21.5 - Max: 31.3
21:39:41.585 [main] INFO - Pub rate 280837.1 msg/s / 274.3 MB/s | Cons rate 280818.1 msg/s / 274.2 MB/s | Backlog:  0.5 K | Pub Latency (ms) avg:  3.1 - 50%:  2.5 - 99%: 10.1 - 99.9%: 21.8 - Max: 40.2
21:39:47.395 [messaging-benchmark-4-1] INFO - Rate is now 300000
21:39:51.686 [main] INFO - Pub rate 288675.4 msg/s / 281.9 MB/s | Cons rate 288597.9 msg/s / 281.8 MB/s | Backlog:  1.3 K | Pub Latency (ms) avg:  3.6 - 50%:  2.7 - 99%: 13.0 - 99.9%: 27.5 - Max: 40.5
21:40:01.792 [main] INFO - Pub rate 299446.3 msg/s / 292.4 MB/s | Cons rate 299578.3 msg/s / 292.6 MB/s | Backlog: -0.1 K | Pub Latency (ms) avg:  4.2 - 50%:  3.1 - 99%: 19.0 - 99.9%: 54.8 - Max: 64.5
21:40:11.897 [main] INFO - Pub rate 300551.2 msg/s / 293.5 MB/s | Cons rate 300462.2 msg/s / 293.4 MB/s | Backlog:  0.8 K | Pub Latency (ms) avg:  3.7 - 50%:  2.7 - 99%: 17.4 - 99.9%: 36.6 - Max: 48.0
21:40:17.398 [messaging-benchmark-4-1] INFO - Rate is now 320000
21:40:22.003 [main] INFO - Pub rate 309020.2 msg/s / 301.8 MB/s | Cons rate 308969.0 msg/s / 301.7 MB/s | Backlog:  1.3 K | Pub Latency (ms) avg:  3.6 - 50%:  2.7 - 99%: 11.6 - 99.9%: 20.8 - Max: 31.2
21:40:32.106 [main] INFO - Pub rate 320602.8 msg/s / 313.1 MB/s | Cons rate 320671.5 msg/s / 313.2 MB/s | Backlog:  0.6 K | Pub Latency (ms) avg:  3.5 - 50%:  2.6 - 99%: 12.5 - 99.9%: 26.1 - Max: 43.2
21:40:42.207 [main] INFO - Pub rate 320585.3 msg/s / 313.1 MB/s | Cons rate 320598.4 msg/s / 313.1 MB/s | Backlog:  0.5 K | Pub Latency (ms) avg:  3.2 - 50%:  2.6 - 99%: 10.4 - 99.9%: 23.0 - Max: 31.6
21:40:47.401 [messaging-benchmark-4-1] INFO - Rate is now 340000
21:40:52.313 [main] INFO - Pub rate 330100.6 msg/s / 322.4 MB/s | Cons rate 330103.6 msg/s / 322.4 MB/s | Backlog:  0.5 K | Pub Latency (ms) avg:  3.8 - 50%:  2.8 - 99%: 13.4 - 99.9%: 27.0 - Max: 48.5
21:41:02.415 [main] INFO - Pub rate 341099.5 msg/s / 333.1 MB/s | Cons rate 341033.1 msg/s / 333.0 MB/s | Backlog:  1.2 K | Pub Latency (ms) avg:  3.5 - 50%:  2.7 - 99%: 11.1 - 99.9%: 21.4 - Max: 33.1
21:41:12.517 [main] INFO - Pub rate 341063.1 msg/s / 333.1 MB/s | Cons rate 341074.1 msg/s / 333.1 MB/s | Backlog:  1.0 K | Pub Latency (ms) avg:  3.6 - 50%:  2.8 - 99%: 12.2 - 99.9%: 30.3 - Max: 36.4
21:41:17.403 [messaging-benchmark-4-1] INFO - Rate is now 360000
21:41:22.624 [main] INFO - Pub rate 350677.3 msg/s / 342.5 MB/s | Cons rate 350727.9 msg/s / 342.5 MB/s | Backlog:  0.5 K | Pub Latency (ms) avg:  3.6 - 50%:  2.8 - 99%: 13.4 - 99.9%: 25.3 - Max: 35.1
21:41:32.728 [main] INFO - Pub rate 360789.1 msg/s / 352.3 MB/s | Cons rate 360755.0 msg/s / 352.3 MB/s | Backlog:  0.9 K | Pub Latency (ms) avg:  4.4 - 50%:  3.2 - 99%: 14.8 - 99.9%: 76.1 - Max: 104.8
21:41:42.834 [main] INFO - Pub rate 360488.5 msg/s / 352.0 MB/s | Cons rate 360424.5 msg/s / 352.0 MB/s | Backlog:  1.5 K | Pub Latency (ms) avg:  4.0 - 50%:  3.1 - 99%: 14.8 - 99.9%: 24.9 - Max: 39.8
21:41:47.406 [messaging-benchmark-4-1] INFO - Rate is now 380000
21:41:52.940 [main] INFO - Pub rate 371674.9 msg/s / 363.0 MB/s | Cons rate 371709.0 msg/s / 363.0 MB/s | Backlog:  1.2 K | Pub Latency (ms) avg:  4.6 - 50%:  3.7 - 99%: 16.1 - 99.9%: 30.2 - Max: 44.0
21:42:03.044 [main] INFO - Pub rate 381277.8 msg/s / 372.3 MB/s | Cons rate 381176.7 msg/s / 372.2 MB/s | Backlog:  2.2 K | Pub Latency (ms) avg:  5.1 - 50%:  4.1 - 99%: 18.0 - 99.9%: 32.6 - Max: 54.0
21:42:13.152 [main] INFO - Pub rate 381153.3 msg/s / 372.2 MB/s | Cons rate 381113.1 msg/s / 372.2 MB/s | Backlog:  2.6 K | Pub Latency (ms) avg:  4.4 - 50%:  3.5 - 99%: 12.7 - 99.9%: 21.5 - Max: 36.3
21:42:17.409 [messaging-benchmark-4-1] INFO - Rate is now 400000
21:42:23.255 [main] INFO - Pub rate 392530.8 msg/s / 383.3 MB/s | Cons rate 392577.1 msg/s / 383.4 MB/s | Backlog:  2.1 K | Pub Latency (ms) avg:  4.4 - 50%:  3.4 - 99%: 15.9 - 99.9%: 26.8 - Max: 42.7
21:42:33.361 [main] INFO - Pub rate 400697.4 msg/s / 391.3 MB/s | Cons rate 400836.5 msg/s / 391.4 MB/s | Backlog:  0.7 K | Pub Latency (ms) avg:  4.9 - 50%:  4.0 - 99%: 14.9 - 99.9%: 22.8 - Max: 31.5
21:42:43.472 [main] INFO - Pub rate 400746.0 msg/s / 391.4 MB/s | Cons rate 400717.4 msg/s / 391.3 MB/s | Backlog:  1.0 K | Pub Latency (ms) avg:  4.9 - 50%:  3.4 - 99%: 34.1 - 99.9%: 85.1 - Max: 103.5
21:42:53.587 [main] INFO - Pub rate 400914.9 msg/s / 391.5 MB/s | Cons rate 400853.1 msg/s / 391.5 MB/s | Backlog:  1.6 K | Pub Latency (ms) avg:  5.8 - 50%:  3.5 - 99%: 71.0 - 99.9%: 130.2 - Max: 141.8
21:43:03.699 [main] INFO - Pub rate 400950.7 msg/s / 391.6 MB/s | Cons rate 400927.3 msg/s / 391.5 MB/s | Backlog:  1.9 K | Pub Latency (ms) avg:  5.0 - 50%:  3.9 - 99%: 18.2 - 99.9%: 56.6 - Max: 72.0
21:43:13.802 [main] INFO - Pub rate 401125.7 msg/s / 391.7 MB/s | Cons rate 401098.2 msg/s / 391.7 MB/s | Backlog:  2.2 K | Pub Latency (ms) avg:  4.5 - 50%:  3.7 - 99%: 14.9 - 99.9%: 28.7 - Max: 46.1
21:43:23.912 [main] INFO - Pub rate 400421.0 msg/s / 391.0 MB/s | Cons rate 400556.1 msg/s / 391.2 MB/s | Backlog:  0.8 K | Pub Latency (ms) avg:  5.3 - 50%:  4.2 - 99%: 17.9 - 99.9%: 28.0 - Max: 47.7
21:43:34.019 [main] INFO - Pub rate 401259.0 msg/s / 391.9 MB/s | Cons rate 401271.8 msg/s / 391.9 MB/s | Backlog:  0.7 K | Pub Latency (ms) avg:  4.7 - 50%:  3.6 - 99%: 16.8 - 99.9%: 54.1 - Max: 63.6
21:43:44.128 [main] INFO - Pub rate 400753.1 msg/s / 391.4 MB/s | Cons rate 400589.4 msg/s / 391.2 MB/s | Backlog:  2.3 K | Pub Latency (ms) avg:  4.9 - 50%:  3.9 - 99%: 16.6 - 99.9%: 28.2 - Max: 50.0
21:43:54.237 [main] INFO - Pub rate 401018.4 msg/s / 391.6 MB/s | Cons rate 401055.3 msg/s / 391.7 MB/s | Backlog:  1.9 K | Pub Latency (ms) avg:  5.1 - 50%:  4.1 - 99%: 17.1 - 99.9%: 46.6 - Max: 56.3
21:44:04.346 [main] INFO - Pub rate 400820.4 msg/s / 391.4 MB/s | Cons rate 400882.9 msg/s / 391.5 MB/s | Backlog:  1.3 K | Pub Latency (ms) avg:  6.1 - 50%:  4.4 - 99%: 34.1 - 99.9%: 82.4 - Max: 96.4
21:44:14.451 [main] INFO - Pub rate 401150.1 msg/s / 391.7 MB/s | Cons rate 400977.1 msg/s / 391.6 MB/s | Backlog:  3.1 K | Pub Latency (ms) avg:  4.1 - 50%:  3.3 - 99%: 12.8 - 99.9%: 26.5 - Max: 35.7
21:44:24.558 [main] INFO - Pub rate 400530.2 msg/s / 391.1 MB/s | Cons rate 399882.0 msg/s / 390.5 MB/s | Backlog:  9.6 K | Pub Latency (ms) avg:  5.8 - 50%:  4.1 - 99%: 43.6 - 99.9%: 91.7 - Max: 111.9
21:44:34.665 [main] INFO - Pub rate 401136.3 msg/s / 391.7 MB/s | Cons rate 401984.1 msg/s / 392.6 MB/s | Backlog:  1.0 K | Pub Latency (ms) avg:  4.3 - 50%:  3.5 - 99%: 13.3 - 99.9%: 21.1 - Max: 29.1
21:44:44.770 [main] INFO - Pub rate 400935.7 msg/s / 391.5 MB/s | Cons rate 398924.7 msg/s / 389.6 MB/s | Backlog: 21.4 K | Pub Latency (ms) avg:  5.1 - 50%:  4.1 - 99%: 17.3 - 99.9%: 35.1 - Max: 55.3
21:44:54.877 [main] INFO - Pub rate 400571.6 msg/s / 391.2 MB/s | Cons rate 402635.6 msg/s / 393.2 MB/s | Backlog:  0.5 K | Pub Latency (ms) avg:  5.4 - 50%:  4.4 - 99%: 17.2 - 99.9%: 56.7 - Max: 69.4
21:45:04.985 [main] INFO - Pub rate 401149.2 msg/s / 391.7 MB/s | Cons rate 400584.3 msg/s / 391.2 MB/s | Backlog:  6.2 K | Pub Latency (ms) avg:  5.9 - 50%:  4.3 - 99%: 35.9 - 99.9%: 87.1 - Max: 104.3
21:45:15.088 [main] INFO - Pub rate 401031.1 msg/s / 391.6 MB/s | Cons rate 401377.7 msg/s / 392.0 MB/s | Backlog:  2.7 K | Pub Latency (ms) avg:  4.2 - 50%:  3.4 - 99%: 12.3 - 99.9%: 18.9 - Max: 25.3
21:45:25.194 [main] INFO - Pub rate 400556.3 msg/s / 391.2 MB/s | Cons rate 400389.2 msg/s / 391.0 MB/s | Backlog:  4.4 K | Pub Latency (ms) avg:  5.1 - 50%:  3.9 - 99%: 16.8 - 99.9%: 57.3 - Max: 86.0
21:45:35.300 [main] INFO - Pub rate 401007.5 msg/s / 391.6 MB/s | Cons rate 401186.8 msg/s / 391.8 MB/s | Backlog:  2.6 K | Pub Latency (ms) avg:  5.4 - 50%:  4.1 - 99%: 19.3 - 99.9%: 32.4 - Max: 51.7
21:45:45.414 [main] INFO - Pub rate 400760.2 msg/s / 391.4 MB/s | Cons rate 400818.8 msg/s / 391.4 MB/s | Backlog:  2.0 K | Pub Latency (ms) avg:  4.9 - 50%:  3.6 - 99%: 25.8 - 99.9%: 68.9 - Max: 81.5
21:45:55.524 [main] INFO - Pub rate 400923.5 msg/s / 391.5 MB/s | Cons rate 400808.2 msg/s / 391.4 MB/s | Backlog:  3.2 K | Pub Latency (ms) avg:  5.2 - 50%:  4.0 - 99%: 20.8 - 99.9%: 34.4 - Max: 64.9
21:46:05.628 [main] INFO - Pub rate 401006.5 msg/s / 391.6 MB/s | Cons rate 401240.9 msg/s / 391.8 MB/s | Backlog:  0.8 K | Pub Latency (ms) avg:  5.1 - 50%:  4.3 - 99%: 14.4 - 99.9%: 22.0 - Max: 33.5
21:46:15.731 [main] INFO - Pub rate 400960.3 msg/s / 391.6 MB/s | Cons rate 400893.0 msg/s / 391.5 MB/s | Backlog:  1.5 K | Pub Latency (ms) avg:  5.3 - 50%:  4.2 - 99%: 18.7 - 99.9%: 32.9 - Max: 41.5
21:46:25.843 [main] INFO - Pub rate 400739.0 msg/s / 391.3 MB/s | Cons rate 400648.8 msg/s / 391.3 MB/s | Backlog:  2.4 K | Pub Latency (ms) avg:  5.3 - 50%:  3.9 - 99%: 24.7 - 99.9%: 69.1 - Max: 80.3
21:46:35.949 [main] INFO - Pub rate 401090.0 msg/s / 391.7 MB/s | Cons rate 401201.2 msg/s / 391.8 MB/s | Backlog:  1.3 K | Pub Latency (ms) avg:  5.4 - 50%:  4.2 - 99%: 17.8 - 99.9%: 71.2 - Max: 87.8
21:46:46.059 [main] INFO - Pub rate 400789.0 msg/s / 391.4 MB/s | Cons rate 400872.3 msg/s / 391.5 MB/s | Backlog:  0.4 K | Pub Latency (ms) avg:  5.4 - 50%:  3.8 - 99%: 37.6 - 99.9%: 78.4 - Max: 87.9
21:46:56.169 [main] INFO - Pub rate 400764.2 msg/s / 391.4 MB/s | Cons rate 400240.2 msg/s / 390.9 MB/s | Backlog:  5.7 K | Pub Latency (ms) avg:  4.8 - 50%:  3.7 - 99%: 16.8 - 99.9%: 32.4 - Max: 50.2
21:47:06.277 [main] INFO - Pub rate 400970.3 msg/s / 391.6 MB/s | Cons rate 401341.0 msg/s / 391.9 MB/s | Backlog:  2.0 K | Pub Latency (ms) avg:  5.6 - 50%:  4.5 - 99%: 17.7 - 99.9%: 45.4 - Max: 69.2
21:47:16.385 [main] INFO - Pub rate 400966.4 msg/s / 391.6 MB/s | Cons rate 401041.8 msg/s / 391.6 MB/s | Backlog:  1.2 K | Pub Latency (ms) avg:  5.1 - 50%:  4.1 - 99%: 16.1 - 99.9%: 51.7 - Max: 81.4
21:47:26.494 [main] INFO - Pub rate 400793.9 msg/s / 391.4 MB/s | Cons rate 400795.1 msg/s / 391.4 MB/s | Backlog:  1.2 K | Pub Latency (ms) avg:  4.7 - 50%:  3.3 - 99%: 23.3 - 99.9%: 79.4 - Max: 91.7
21:47:36.599 [main] INFO - Pub rate 401123.3 msg/s / 391.7 MB/s | Cons rate 399538.2 msg/s / 390.2 MB/s | Backlog: 17.2 K | Pub Latency (ms) avg:  5.1 - 50%:  4.0 - 99%: 18.6 - 99.9%: 39.2 - Max: 57.5
21:47:46.709 [main] INFO - Pub rate 400705.5 msg/s / 391.3 MB/s | Cons rate 402175.0 msg/s / 392.7 MB/s | Backlog:  2.4 K | Pub Latency (ms) avg:  5.5 - 50%:  4.4 - 99%: 20.7 - 99.9%: 60.6 - Max: 67.8
21:47:56.818 [main] INFO - Pub rate 400857.5 msg/s / 391.5 MB/s | Cons rate 400937.7 msg/s / 391.5 MB/s | Backlog:  1.5 K | Pub Latency (ms) avg:  5.5 - 50%:  4.4 - 99%: 18.4 - 99.9%: 32.6 - Max: 44.4
21:47:56.954 [main] INFO - ----- Aggregated Pub Latency (ms) avg:  4.3 - 50%:  3.0 - 95%: 10.0 - 99%: 16.2 - 99.9%: 55.6 - 99.99%: 100.8 - Max: 141.8
21:47:57.282 [main] INFO - Writing test result into 400k-10-topics-3-partitions-1k-increment-Kafka-2022-11-08-21-47-57.json

[Demogorgon314]

@dave2wave Thanks for sharing the benchmark results! I'll check if there are any resource leaks.

[eolivelli]

@Demogorgon314 @BewareMyPower after analysing the dumps of the JVMs of @dave2wave 's tests I have come to this small improvement https://github.com/streamnative/kop/pull/1563

let's follow up there the discussion