Commit ab88df7
authored
KAFKA-20535: Improve async consumer CPU usage under low max.poll.records. (apache#22199)
### Description
KAFKA-20332 fixed a correctness issue in the async consumer where the
application thread could collect buffered records before the background
thread had checked for pending reconciliations. The fix added a wait on
`inflightPoll.reconciliationCheckFuture()` in
`AsyncKafkaConsumer.collectFetch()`.
This restored the correctness guarantee, but it also increased CPU usage
in low `max.poll.records` scenarios. With `max.poll.records=5`,
profiling shows that the additional cost mainly comes from the
application thread waiting on
`ConsumerUtils.getResult(inflightPoll.reconciliationCheckFuture(),
timeoutMs)` even when the consumer group member is not reconciling.
This patch avoids that unnecessary wait by tracking the consumer group
member state in `AsyncKafkaConsumer`. `AbstractMembershipManager` now
notifies `MemberStateListener` whenever the consumer member transitions
to a new state. `AsyncKafkaConsumer` uses this signal to wait for the
reconciliation check only while the member is in
`MemberState.RECONCILING`.
### Test Condition
- Broker
- stand alone
- 12 vCPU, 32GB RAM.
- Producer
- Use `bin/kafka-producer-perf-test.sh` in Broker.
- throughput 50000
- record-size 100
- Consumer (before, after, optimized)
- kubernetes environment.
- All consumers are scheduled on the same worker node.
- Profiler
- async-profiler
- duration 180 seconds.
- branch
- `before`: 5a2dcf8
- `after`: 7e1c9db
- `optimized`: this PR
### Test Result
1. Check the throughput of each consumer
```
Before - RATE: 49997.400259974005 records/sec, total=7050826
After - RATE: 50002.199780022 records/sec, total=7557854
Optimized - RATE: 50002.199780022 records/sec, total=7584198
```
- All consumers have same throughput.
2. Average CPU usage from `kubectl top pod`
| Revision | Average CPU | |---|---:| | Before | 225.7m | |
After | 325.7m | | Optimized | 248.4m |
every 30second, 10 times. The optimized version reduced CPU usage by
about 23.7% compared with `after`.
### Flame Graph Summary
| Metric | Before | After | Optimized |
|---|---:|---:|---:|
| Samples | 2,402 | 3,160 | 2,542 |
| markReconciliationCheckComplete | 0.00% | 2.82% | 0.51% |
| setActiveTask | 0.00% | 0.06% | 0.00% |
| pollTimeMs | 0.00% | 0.00% | 0.00% |
| AsyncPollEvent | 0.37% | 2.91% | 0.87% |
| processBackgroundEvents | 2.37% | 1.93% | 2.28% |
| Reaper | 0.17% | 0.19% | 0.35% |
| parkNanos | 1.08% | 4.05% | 0.94% |
| unpark | 0.37% | 2.06% | 0.63% |
| AsyncKafkaConsumer.poll | 38.68% | 38.32% | 38.20% |
| AsyncKafkaConsumer.collectFetch | 20.32% | 23.61% | 19.39% |
| ApplicationEventProcessor.process | 2.66% | 6.46% | 2.83% |
| ApplicationEventHandler.add | 7.87% | 7.37% | 8.06% |
`After` shows higher CPU usage, and the profile also shows increased
time in `parkNanos` and `unpark`. This suggests that the additional wait
on `reconciliationCheckFuture` introduced more application/background
thread coordination overhead.
### AsyncKafkaConsumer.collectFetch
| Metric | Before | After | Optimized |
|---|---:|---:|---:|
| AsyncKafkaConsumer.collectFetch samples | 488 | 746 | 493 |
| AsyncKafkaConsumer.collectFetch % | 20.32% | 23.61% | 19.39% |
| FetchCollector.collectFetch samples | 482 | 512 | 477 |
| FetchCollector.collectFetch % | 20.07% | 16.20% | 18.76% |
| ConsumerUtils.getResult samples | 0 | 194 | 0 |
| ConsumerUtils.getResult % | 0.00% | 6.14% | 0.00% |
In `after`, the application thread spends additional time in
`ConsumerUtils.getResult()` while waiting for the reconciliation check
future. This also increases related park/unpark activity and application
event processing on the background thread. In the optimized version,
this wait is skipped unless the member is actually in `RECONCILING`
state.
### ConsumerNetworkThread.runOnce
| Metric | Before | After | Optimized |
|---|---:|---:|---:|
| ConsumerNetworkThread.runOnce samples | 1,216 | 1,621 | 1,295 |
| ConsumerNetworkThread.runOnce % | 50.62% | 51.30% | 50.94% |
| ConsumerNetworkThread.processApplicationEvents samples | 283 | 442 |
263 |
| ConsumerNetworkThread.processApplicationEvents % | 11.78% | 13.99% |
10.35% |
| FetchRequestManager.poll samples | 169 | 194 | 158 |
| FetchRequestManager.poll % | 7.04% | 6.13% | 6.22% |
| NetworkClientDelegate.poll samples | 600 | 755 | 684 |
| NetworkClientDelegate.poll % | 24.98% | 23.89% | 26.91% |
The higher CPU usage in `onsumerNetworkThread` appears to be a secondary
effect of the application thread waiting on `reconciliationCheckFuture`
more often. Each wait requires coordination between the application
thread and the ackground thread: the app thread enqueues an
`AsyncPollEvent`, waits for the reconciliation check to complete, and
the background thread processes that event and completes the future. As
a result, `ConsumerNetworkThread.processApplicationEvents` and related
`AsyncPollEvent` processing show higher CPU usage in the after profile.
Reviewers: Lianet Magrans <lmagrans@confluent.io>1 parent 7b7fae7 commit ab88df7
4 files changed
Lines changed: 77 additions & 1 deletion
File tree
- clients/src
- main/java/org/apache/kafka/clients/consumer/internals
- test/java/org/apache/kafka/clients/consumer/internals
Lines changed: 1 addition & 0 deletions
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
245 | 245 | | |
246 | 246 | | |
247 | 247 | | |
| 248 | + | |
248 | 249 | | |
249 | 250 | | |
250 | 251 | | |
| |||
Lines changed: 12 additions & 1 deletion
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
420 | 420 | | |
421 | 421 | | |
422 | 422 | | |
| 423 | + | |
| 424 | + | |
423 | 425 | | |
424 | 426 | | |
425 | 427 | | |
| |||
430 | 432 | | |
431 | 433 | | |
432 | 434 | | |
| 435 | + | |
| 436 | + | |
| 437 | + | |
| 438 | + | |
| 439 | + | |
433 | 440 | | |
434 | 441 | | |
435 | 442 | | |
| |||
873 | 880 | | |
874 | 881 | | |
875 | 882 | | |
| 883 | + | |
| 884 | + | |
| 885 | + | |
| 886 | + | |
876 | 887 | | |
877 | 888 | | |
878 | 889 | | |
| |||
2028 | 2039 | | |
2029 | 2040 | | |
2030 | 2041 | | |
2031 | | - | |
| 2042 | + | |
2032 | 2043 | | |
2033 | 2044 | | |
2034 | 2045 | | |
| |||
Lines changed: 9 additions & 0 deletions
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
47 | 47 | | |
48 | 48 | | |
49 | 49 | | |
| 50 | + | |
| 51 | + | |
| 52 | + | |
| 53 | + | |
| 54 | + | |
| 55 | + | |
| 56 | + | |
| 57 | + | |
| 58 | + | |
50 | 59 | | |
Lines changed: 55 additions & 0 deletions
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
609 | 609 | | |
610 | 610 | | |
611 | 611 | | |
| 612 | + | |
612 | 613 | | |
613 | 614 | | |
614 | 615 | | |
| |||
623 | 624 | | |
624 | 625 | | |
625 | 626 | | |
| 627 | + | |
| 628 | + | |
| 629 | + | |
| 630 | + | |
| 631 | + | |
| 632 | + | |
| 633 | + | |
| 634 | + | |
| 635 | + | |
| 636 | + | |
| 637 | + | |
| 638 | + | |
| 639 | + | |
| 640 | + | |
| 641 | + | |
| 642 | + | |
| 643 | + | |
| 644 | + | |
| 645 | + | |
| 646 | + | |
| 647 | + | |
| 648 | + | |
| 649 | + | |
| 650 | + | |
| 651 | + | |
| 652 | + | |
| 653 | + | |
| 654 | + | |
| 655 | + | |
| 656 | + | |
| 657 | + | |
| 658 | + | |
| 659 | + | |
| 660 | + | |
| 661 | + | |
| 662 | + | |
| 663 | + | |
| 664 | + | |
| 665 | + | |
| 666 | + | |
| 667 | + | |
| 668 | + | |
| 669 | + | |
| 670 | + | |
| 671 | + | |
| 672 | + | |
| 673 | + | |
| 674 | + | |
| 675 | + | |
| 676 | + | |
| 677 | + | |
| 678 | + | |
| 679 | + | |
| 680 | + | |
626 | 681 | | |
627 | 682 | | |
628 | 683 | | |
| |||
0 commit comments