[fix][java-client] Fix performance regression with message listener #15162

codelipenghui · 2022-04-13T18:22:41Z

Motivation

#13023 has introduced a performance regression.
For each message, we are switching from external thread pool -> internal thread poll -> external thread pool.

Previously we want to control the outstanding messages of a consumer using a listener, so after #11455,
the message will not move from the receiver queue to the external executor. And #13023 changed the listener trigger
in the internal thread pool to fix the ordering issue, so this is the root cause of the performance regression.

Here is the frame graph to show the thread frame of the internal thread and external thread.
framegraph.html.txt

And also fix the performance issue for multiple topic consumers and key-shared subscriptions which enabled message listeners. Before this change, the messages are processed serially. After this change, We can improve parallelism on the premise of ensuring order.

Modification

Remove the isListenerHandlingMessage control
Move the messages from the receiver queue to the queue of external executor but not increase permits
Increase permits before call message listener

After the above changes, we don't need to call triggerListener from the external executor.

Here is the thread frame graph after applying this change

framegraph2.html.txt

Before this change, the consumer can't reach 50000 messages/s.
After this change, the consumer can reach 400000 messages/s

2022-04-14T02:14:58,208+0800 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 9723124 msg --- 470142.670  msg/s --- 3.587 Mbit/s  --- Latency: mean: 9476.742 ms - med: 9441 - 95pct: 11908 - 99pct: 12152 - 99.9pct: 12239 - 99.99pct: 12247 - Max: 12247
2022-04-14T02:15:08,222+0800 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 14411888 msg --- 468147.684  msg/s --- 3.572 Mbit/s  --- Latency: mean: 15262.627 ms - med: 15253 - 95pct: 18023 - 99pct: 18258 - 99.9pct: 18315 - 99.99pct: 18317 - Max: 18318
2022-04-14T02:15:18,236+0800 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 18841513 msg --- 442446.540  msg/s --- 3.376 Mbit/s  --- Latency: mean: 21164.401 ms - med: 21094 - 95pct: 23664 - 99pct: 23899 - 99.9pct: 23939 - 99.99pct: 23955 - Max: 23955
2022-04-14T02:15:28,253+0800 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 23082078 msg --- 423212.525  msg/s --- 3.229 Mbit/s  --- Latency: mean: 27174.714 ms - med: 27272 - 95pct: 29453 - 99pct: 29698 - 99.9pct: 29725 - 99.99pct: 29736 - Max: 29736
2022-04-14T02:15:38,268+0800 [main] INFO  org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 27647013 msg --- 455823.127  msg/s --- 3.478 Mbit/s  --- Latency: mean: 32438.418 ms - med: 32410 - 95pct: 34870 - 99pct: 35098 - 99.9pct: 35130 - 99.99pct: 35133 - Max: 35134

Documentation

Check the box below or label this PR directly.

Need to update docs?

doc-required
(Your PR needs to update docs and you will update later)
no-need-doc
(Please explain why)
doc
(Your PR contains doc changes)
doc-added
(Docs have been already added)

### Motivation apache#13023 has introduced a performance regression. For each message, we are switching from external thread pool -> internal thread poll -> external thread pool. Previously we want to control the outstanding messages of a consumer which using listener, so after apache#11455, the message will not move from the receiver queue to the external executor. And apache#13023 changed the listener trigger in the internal thread pool to fixes the orderding issue, so this is the root cause of the performance regression. Here is the framegraph to to show the thread frame of internal thread and external thread. And also fix the performance issue for multiple topic consumer and key-shared subscription which enabled message listener. Before this change, the messages are processed serially. After this change, We can improve parallelism on the premise of ensuring ordering. ### Modification - Remove the isListenerHandlingMessage control - Move the messages from receiver queue to the queue of external executor but not increase permits - Increase permits before call message listener After the above changes, we don't need to call triggerListener from the external executor. Here is the thread framegraph after apply this change Before this change, the consumer can't reach 50000 messages/s. After this change, the consumer can reach 400000 messages/s ``` 2022-04-14T02:14:58,208+0800 [main] INFO org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 9723124 msg --- 470142.670 msg/s --- 3.587 Mbit/s --- Latency: mean: 9476.742 ms - med: 9441 - 95pct: 11908 - 99pct: 12152 - 99.9pct: 12239 - 99.99pct: 12247 - Max: 12247 2022-04-14T02:15:08,222+0800 [main] INFO org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 14411888 msg --- 468147.684 msg/s --- 3.572 Mbit/s --- Latency: mean: 15262.627 ms - med: 15253 - 95pct: 18023 - 99pct: 18258 - 99.9pct: 18315 - 99.99pct: 18317 - Max: 18318 2022-04-14T02:15:18,236+0800 [main] INFO org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 18841513 msg --- 442446.540 msg/s --- 3.376 Mbit/s --- Latency: mean: 21164.401 ms - med: 21094 - 95pct: 23664 - 99pct: 23899 - 99.9pct: 23939 - 99.99pct: 23955 - Max: 23955 2022-04-14T02:15:28,253+0800 [main] INFO org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 23082078 msg --- 423212.525 msg/s --- 3.229 Mbit/s --- Latency: mean: 27174.714 ms - med: 27272 - 95pct: 29453 - 99pct: 29698 - 99.9pct: 29725 - 99.99pct: 29736 - Max: 29736 2022-04-14T02:15:38,268+0800 [main] INFO org.apache.pulsar.testclient.PerformanceConsumer - Throughput received: 27647013 msg --- 455823.127 msg/s --- 3.478 Mbit/s --- Latency: mean: 32438.418 ms - med: 32410 - 95pct: 34870 - 99pct: 35098 - 99.9pct: 35130 - 99.99pct: 35133 - Max: 35134 ```

### Motivation apache#13023 has introduced a performance regression. For each message, we are switching from external thread pool -> internal thread poll -> external thread pool. Previously we want to control the outstanding messages of a consumer which using listener, so after apache#11455, the message will not move from the receiver queue to the external executor. And apache#13023 changed the listener trigger in the internal thread pool to fixes the orderding issue, so this is the root cause of the performance regression. Here is the framegraph to to show the thread frame of internal thread and external thread. ### Modification - Remove the isListenerHandlingMessage control - Move the messages from receiver queue to the queue of external executor but not increase permits - Increase permits before call message listener After the above changes, we don't need to call triggerListener from the external executor. Here is the thread framegraph after apply this change Before this change, the consumer can't reach 50000 messages/s. After this change, the consumer can reach

Jason918

LGTM

pulsar-client/src/main/java/org/apache/pulsar/client/impl/ConsumerImpl.java

eolivelli

I left one question
PTAL

eolivelli · 2022-04-14T06:43:36Z

pulsar-client/src/main/java/org/apache/pulsar/client/impl/ConsumerBase.java

                    }
-                }
+                } while (msg != null);


my understanding is that this way we are going to occupy the thread forever
other Consumers won't be able to use this thread

No, it will not occupy the thread forever. After enabling the message listener, the incoming messages will trigger here, so we will only have a few messages in the receiver queue. Here just want to make sure all the messages in the receiver queue can be moved out to the external executor.

Demogorgon314

Good job!

shibd

learned a lot.

eolivelli · 2022-04-14T14:47:26Z

pulsar-client/src/main/java/org/apache/pulsar/client/impl/ConsumerBase.java

-                    final Message<T> msg = internalReceive(0, TimeUnit.MILLISECONDS);
+                Message<T> msg;
+                do {
+                    msg = internalReceive(0, TimeUnit.MILLISECONDS);


@codelipenghui here we are doing a "take" operation, without conditions, this will wait forever.

It's not a take operation, it's a poll operation, if no more messages are in the receiver queue, we will get null here immediately.

315157973 · 2022-04-14T15:43:05Z

pulsar-client/src/main/java/org/apache/pulsar/client/impl/ConsumerBase.java

-                    final Message<T> msg = internalReceive(0, TimeUnit.MILLISECONDS);
+                Message<T> msg;
+                do {
+                    msg = internalReceive(0, TimeUnit.MILLISECONDS);


Does the role of ReceiveQueue disappear in this way? Regardless of whether the Consumer has finished consumption, the client will continue to pull messages, and finally make the client OOM

It is controlled by the flow permits, we only increase the permits after triggering the listener.

Technoboy- · 2022-04-19T02:43:39Z

pulsar-client/src/main/java/org/apache/pulsar/client/impl/ConsumerBase.java

                            });
                        }
+                    } else {
+                        if (log.isDebugEnabled()) {
+                            log.debug("[{}] [{}] Message has been cleared from the queue", topic, subscription);


Seem there will be more logs.

@Technoboy- It's debugging level logs, it will help for troubleshooting problems if we see this log but there are messages in the queue.

codelipenghui · 2022-04-19T13:00:39Z

@eolivelli Could you please help review again?

…pache#15162) ### Motivation apache#13023 has introduced a performance regression. For each message, we are switching from external thread pool -> internal thread poll -> external thread pool. Previously we want to control the outstanding messages of a consumer using a listener, so after apache#11455, the message will not move from the receiver queue to the external executor. And apache#13023 changed the listener trigger in the internal thread pool to fix the ordering issue, so this is the root cause of the performance regression. Here is the frame graph to show the thread frame of the internal thread and external thread. [framegraph.html.txt](https://github.com/apache/pulsar/files/8483765/framegraph.html.txt) And also fix the performance issue for multiple topic consumers and key-shared subscriptions which enabled message listeners. Before this change, the messages are processed serially. After this change, We can improve parallelism on the premise of ensuring order. ### Modification - Remove the isListenerHandlingMessage control - Move the messages from the receiver queue to the queue of external executor but not increase permits - Increase permits before call message listener

…15162) #13023 has introduced a performance regression. For each message, we are switching from external thread pool -> internal thread poll -> external thread pool. Previously we want to control the outstanding messages of a consumer using a listener, so after #11455, the message will not move from the receiver queue to the external executor. And #13023 changed the listener trigger in the internal thread pool to fix the ordering issue, so this is the root cause of the performance regression. Here is the frame graph to show the thread frame of the internal thread and external thread. [framegraph.html.txt](https://github.com/apache/pulsar/files/8483765/framegraph.html.txt) And also fix the performance issue for multiple topic consumers and key-shared subscriptions which enabled message listeners. Before this change, the messages are processed serially. After this change, We can improve parallelism on the premise of ensuring order. - Remove the isListenerHandlingMessage control - Move the messages from the receiver queue to the queue of external executor but not increase permits - Increase permits before call message listener (cherry picked from commit 83cd791)

…pache#15162) apache#13023 has introduced a performance regression. For each message, we are switching from external thread pool -> internal thread poll -> external thread pool. Previously we want to control the outstanding messages of a consumer using a listener, so after apache#11455, the message will not move from the receiver queue to the external executor. And apache#13023 changed the listener trigger in the internal thread pool to fix the ordering issue, so this is the root cause of the performance regression. Here is the frame graph to show the thread frame of the internal thread and external thread. [framegraph.html.txt](https://github.com/apache/pulsar/files/8483765/framegraph.html.txt) And also fix the performance issue for multiple topic consumers and key-shared subscriptions which enabled message listeners. Before this change, the messages are processed serially. After this change, We can improve parallelism on the premise of ensuring order. - Remove the isListenerHandlingMessage control - Move the messages from the receiver queue to the queue of external executor but not increase permits - Increase permits before call message listener (cherry picked from commit 83cd791) (cherry picked from commit c712441)

michaeljmarshall

Sorry, for the late review. Great work @codelipenghui! LGTM.

…pache#15162) apache#13023 has introduced a performance regression. For each message, we are switching from external thread pool -> internal thread poll -> external thread pool. Previously we want to control the outstanding messages of a consumer using a listener, so after apache#11455, the message will not move from the receiver queue to the external executor. And apache#13023 changed the listener trigger in the internal thread pool to fix the ordering issue, so this is the root cause of the performance regression. Here is the frame graph to show the thread frame of the internal thread and external thread. [framegraph.html.txt](https://github.com/apache/pulsar/files/8483765/framegraph.html.txt) And also fix the performance issue for multiple topic consumers and key-shared subscriptions which enabled message listeners. Before this change, the messages are processed serially. After this change, We can improve parallelism on the premise of ensuring order. - Remove the isListenerHandlingMessage control - Move the messages from the receiver queue to the queue of external executor but not increase permits - Increase permits before call message listener (cherry picked from commit 83cd791) (cherry picked from commit c712441)

dave2wave · 2022-06-01T01:48:43Z

Has this been cherry picked to 2.10, 2.9, and 2.8 yet?

BewareMyPower · 2022-06-01T01:59:07Z

Yes, see the cherry-picked labels.

codelipenghui added 2 commits April 14, 2022 02:20

codelipenghui added this to the 2.11.0 milestone Apr 13, 2022

codelipenghui added component/client-java release/2.9.3 release/2.8.4 release/2.10.1 labels Apr 13, 2022

codelipenghui self-assigned this Apr 13, 2022

github-actions bot added the doc-not-needed Your PR changes do not impact docs label Apr 13, 2022

Fix test.

b0b6d1b

codelipenghui changed the title ~~[fix][java-client] Fix performance regression~~ [fix][java-client] Fix performance regression with message listener Apr 14, 2022

Fix MultiConsumerImpl with listener.

94d27f5

codelipenghui requested review from Technoboy-, BewareMyPower, michaeljmarshall, 315157973, eolivelli, gaoran10, hangc0276, Jason918, lhotari, merlimat and RobertIndie April 14, 2022 01:07

Jason918 approved these changes Apr 14, 2022

View reviewed changes

BewareMyPower reviewed Apr 14, 2022

View reviewed changes

pulsar-client/src/main/java/org/apache/pulsar/client/impl/ConsumerImpl.java Show resolved Hide resolved

BewareMyPower approved these changes Apr 14, 2022

View reviewed changes

eolivelli requested changes Apr 14, 2022

View reviewed changes

Demogorgon314 approved these changes Apr 14, 2022

View reviewed changes

HQebupt approved these changes Apr 14, 2022

View reviewed changes

shibd approved these changes Apr 14, 2022

View reviewed changes

eolivelli reviewed Apr 14, 2022

View reviewed changes

315157973 reviewed Apr 14, 2022

View reviewed changes

315157973 approved these changes Apr 16, 2022

View reviewed changes

Technoboy- reviewed Apr 19, 2022

View reviewed changes

eolivelli approved these changes Apr 19, 2022

View reviewed changes

codelipenghui merged commit 83cd791 into apache:master Apr 19, 2022

codelipenghui deleted the penghui/fix-consumer-performance branch April 19, 2022 14:18

codelipenghui added the cherry-picked/branch-2.10 label Apr 20, 2022

codelipenghui added the cherry-picked/branch-2.9 Archived: 2.9 is end of life label Apr 20, 2022

codelipenghui added the cherry-picked/branch-2.8 Archived: 2.8 is end of life label Apr 20, 2022

michaeljmarshall approved these changes Apr 20, 2022

View reviewed changes

codelipenghui restored the penghui/fix-consumer-performance branch May 17, 2022 01:20

codelipenghui deleted the penghui/fix-consumer-performance branch May 17, 2022 01:29

BewareMyPower mentioned this pull request Jun 2, 2022

Fix performance regression in pulsar client 2.8.3 #14976

Closed

2 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[fix][java-client] Fix performance regression with message listener #15162

[fix][java-client] Fix performance regression with message listener #15162

codelipenghui commented Apr 13, 2022

Jason918 left a comment

eolivelli left a comment

eolivelli Apr 14, 2022

codelipenghui Apr 14, 2022

Demogorgon314 left a comment

shibd left a comment

eolivelli Apr 14, 2022

codelipenghui Apr 15, 2022

315157973 Apr 14, 2022

codelipenghui Apr 15, 2022

Technoboy- Apr 19, 2022

codelipenghui Apr 19, 2022

codelipenghui commented Apr 19, 2022

michaeljmarshall left a comment

dave2wave commented Jun 1, 2022

BewareMyPower commented Jun 1, 2022

[fix][java-client] Fix performance regression with message listener #15162

[fix][java-client] Fix performance regression with message listener #15162

Conversation

codelipenghui commented Apr 13, 2022

Motivation

Modification

Documentation

Jason918 left a comment

Choose a reason for hiding this comment

eolivelli left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Demogorgon314 left a comment

Choose a reason for hiding this comment

shibd left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

codelipenghui commented Apr 19, 2022

michaeljmarshall left a comment

Choose a reason for hiding this comment

dave2wave commented Jun 1, 2022

BewareMyPower commented Jun 1, 2022