[performance] Intermittent Pub Latency Spikes
- Dominant language
- Java
- Stars
- 15.3k
- Forks
- 3.8k
- Avg merge
- 1d 14h
- Merged PRs (30d)
- 160
Description
**Describe the bug**
Intermittent latency spikes have been observed from the current master branch, 2.11. When running OpenMessaging Benchmarks long enough for hours, sometimes Pub latency abnormally spikes and comes back to the normal. I suspect this could be due to some random network issues in the test environment(AWS) or some edge-case performance regressions introduced in the latest code. Unfortunately, 2.9 branch didn't show this issue so far.
**To Reproduce**
Steps to reproduce the behavior:
- Run OpenMessaging Benchmark Test(1-topic-100-partitions-1kb-4p-4c-500k) with the current pulsar master branch(2.11) several times(at least 3 times) with duration 15mins for each run. (skip journaling)
- Observe the max latency spikes > 200ms in the logs like the followings.
```
######## Observation 1:
[ec2-user@ip-10-0-0-236 benchmark]$ sudo bin/benchmark \
> --drivers driver-pulsar/pulsar.yaml \
> workloads/1-topic-100-partitions-1kb-4p-4c-500k.yaml
...
05:24:37.011 [main] INFO - Workloads: {
"1-topic-100-partitions-1kb-4p-4c-500k" : {
"name" : "500k rate 4 producers and 4 consumers on 1 topic / 100 partition",
"topics" : 1,
"partitionsPerTopic" : 100,
"keyDistributor" : "NO_KEY",
"messageSize" : 1024,
"useRandomizedPayloads" : true,
"randomBytesRatio" : 0.5,
"randomizedPayloadPoolSize" : 1000,
"payloadFile" : null,
"subscriptionsPerTopic" : 1,
"producersPerTopic" : 4,
"consumerPerSubscription" : 4,
"producerRate" : 500000,
"consumerBacklogSizeGB" : 0,
"testDurationMinutes" : 5,
"warmupDurationMinutes" : 1
}
}
05:24:37.286 [main] INFO - Workers list - producers: [http://10.0.0.236:8080, http://10.0.0.165:8080]
05:24:37.287 [main] INFO - Workers list - consumers: [http://10.0.0.73:8080, http://10.0.0.170:8080]
05:24:37.291 [main] INFO - --------------- WORKLOAD : 500k rate 4 producers and 4 consumers on 1 topic / 100 partition --- DRIVER : Pulsar---------------
05:24:39.028 [main] INFO - Created 1 topics in 1083.131706 ms
05:24:42.706 [main] INFO - Created 4 consumers in 3672.372545 ms
05:24:42.857 [main] INFO - Created 4 producers in 150.298553 ms
05:24:42.857 [main] INFO - Waiting for consumers to be ready
05:24:42.873 [main] INFO - All consumers are ready
05:24:43.008 [main] INFO - ----- Starting warm-up traffic (1m) ------
...
05:26:24.471 [main] INFO - Pub rate 500638.7 msg/s / 488.9 MB/s | Cons rate 500687.5 msg/s / 489.0 MB/s | Backlog: 0.0 K | Pub Latency (ms) avg: 1.6 - 50%: 1.1 - 99%: 1.7 - 99.9%: 138.4 - Max: 511.8 | Pub Delay Latency (us) avg: 26.3 - 50%: 24.0 - 99%: 55.0 - 99.9%: 63.0 - Max: 946.0
...
05:30:26.759 [main] INFO - Pub rate 499597.5 msg/s / 487.9 MB/s | Cons rate 499626.2 msg/s / 487.9 MB/s | Backlog: -5.0 K | Pub Latency (ms) avg: 1.1 - 50%: 1.1 - 99%: 1.6 - 99.9%: 6.1 - Max: 25.9 | Pub Delay Latency (us) avg: 26.2 - 50%: 24.0 - 99%: 55.0 - 99.9%: 62.0 - Max: 163.0
05:30:36.847 [main] INFO - Pub rate 500577.0 msg/s / 488.8 MB/s | Cons rate 500527.0 msg/s / 488.8 MB/s | Backlog: -4.5 K | Pub Latency (ms) avg: 1.1 - 50%: 1.1 - 99%: 1.6 - 99.9%: 1.8 - Max: 70.6 | Pub Delay Latency (us) avg: 26.3 - 50%: 24.0 - 99%: 55.0 - 99.9%: 63.0 - Max: 6422.0
05:30:46.942 [main] INFO - Pub rate 499666.5 msg/s / 488.0 MB/s | Cons rate 499692.0 msg/s / 488.0 MB/s | Backlog: -4.8 K | Pub Latency (ms) avg: 1.1 - 50%: 1.1 - 99%: 1.6 - 99.9%: 4.9 - Max: 64.9 | Pub Delay Latency (us) avg: 26.2 - 50%: 24.0 - 99%: 55.0 - 99.9%: 62.0 - Max: 259.0
05:30:47.044 [main] INFO - ----- Aggregated Pub Latency (ms) avg: 1.2 - 50%: 1.1 - 95%: 1.5 - 99%: 1.6 - 99.9%: 1.9 - 99.99%: 233.5 - Max: 511.8 | Pub Delay (us) avg: 26.2 - 50%: 24.0 - 95%: 55.0 - 99%: 55.0 - 99.9%: 62.0 - 99.99%: 92.0 - Max: 6422.0
05:30:49.357 [main] INFO - Writing test result into 1-topic-100-partitions-1kb-4p-4c-500k-Pulsar-2022-05-17-05-30-49.json
######## Observation 2:
00:37:32.044 [main] INFO - Workloads: {
"1-topic-100-partitions-1kb-4p-4c-500k" : {
"name" : "500k rate 4 producers and 4 consumers on 1 topic / 100 partition",
"topics" : 1,
"partitionsPerTopic" : 100,
"keyDistributor" : "NO_KEY",
"messageSize" : 1024,
"useRandomizedPayloads" : true,
"randomBytesRatio" : 0.5,
"randomizedPayloadPoolSize" : 1000,
"payloadFile" : null,
"subscriptionsPerTopic" : 1,
"producersPerTopic" : 4,
"consumerPerSubscription" : 4,
"producerRate" : 500000,
"consumerBacklogSizeGB" : 0,
"testDurationMinutes" : 15,
"warmupDurationMinutes" : 1
}
}
...
00:47:42.172 [main] INFO - Pub rate 499434.4 msg/s / 487.7 MB/s | Cons rate 499439.6 msg/s / 487.7 MB/s | Backlog: -0.1 K | Pub Latency (ms) avg: 3.6 - 50%: 1.2 - 99%: 108.2 - 99.9%: 159.3 - Max: 220.4 | Pub Delay Latency (us) avg: 26.3 - 50%: 24.0 - 99%: 55.0 - 99.9%: 61.0 - Max: 150.0
...
00:53:35.406 [main] INFO - Pub rate 500426.2 msg/s / 488.7 MB/s | Cons rate 500456.2 msg/s / 488.7 MB/s | Backlog: -0.0 K | Pub Latency (ms) avg: 1.2 - 50%: 1.2 - 99%: 1.8 - 99.9%: 1.9 - Max: 2.4 | Pub Delay Latency (us) avg: 26.2 - 50%: 24.0 - 99%: 55.0 - 99.9%: 62.0 - Max: 131.0
00:53:45.499 [main] INFO - Pub rate 499718.5 msg/s / 488.0 MB/s | Cons rate 499726.6 msg/s / 488.0 MB/s | Backlog: -0.1 K | Pub Latency (ms) avg: 1.2 - 50%: 1.2 - 99%: 1.8 - 99.9%: 1.9 - Max: 2.9 | Pub Delay Latency (us) avg: 26.2 - 50%: 24.0 - 99%: 55.0 - 99.9%: 62.0 - Max: 131.0
00:53:45.612 [main] INFO - ----- Aggregated Pub Latency (ms) avg: 1.2 - 50%: 1.2 - 95%: 1.6 - 99%: 1.8 - 99.9%: 2.0 - 99.99%: 111.2 - Max: 220.4 | Pub Delay (us) avg: 26.4 - 50%: 24.0 - 95%: 55.0 - 99%: 55.0 - 99.9%: 62.0 - 99.99%: 91.0 - Max: 1027.0
```
**Expected behavior**
We expect max Pub latency < 100ms from `1-topic-100-partitions-1kb-4p-4c-500k`. (Please correct me if I am wrong here)
Contributor guide
Research direction
Start by running the OpenMessaging Benchmark command with driver-pulsar/pulsar.yaml and workloads/1-topic-100-partitions-1kb-4p-4c-500k.yaml on the master and 2.9 branches. Compare the latency logs while checking whether the spikes reproduce in the AWS test environment; done means identifying a reproducible cause and establishing whether max publish latency can remain below 100 ms.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- aws, java
- Domain
- distributed-systems, performance
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100