High CPU usage (140%) with 2.0.25/26

[myifeng]

Bug description

• v2.0.25 v2.0.26 CPU usage is too high, 140%
• v2.0.24 CPU uage is ok, 1%

To Reproduce

Steps to reproduce the behavior:

When deploying with Docker, the container running apecloud/ape-dts:2.0.24 shows normal CPU consumption. However, after switching to either apecloud/ape-dts:2.0.25 or apecloud/ape-dts:2.0.26-alpha.19, the CPU usage spikes to ~140% (as observed via docker stats). This regression makes the newer images unusable in production environments.

Expected behavior

Screenshots

Environment

• OS: Ubuntu 20.04
• apt-dts version: 2.0.25

Additional context

[caiq1nyu]

could you provide the task configuration?

[caiq1nyu]

after some investigation, we believe this may be caused by a previous optimization to the async runtime. It appears to trigger high-frequency idle spinning under certain conditions, even when CPU usage is low. We’ll continue investigating, prepare a fix internally, and include it in v2.0.25. v2.0.26 hasn’t been released yet and is currently planned for next month.

[gnolong]

after testing, with same task config, got:

Image Tag	Pod	Max CPU Usage
v2.0.25	dts-bench-benchmark-msd5c	2546m (3.781 cores)
v2.0.24	dts-bench-benchmark-xdkj9	2310m (2.310 cores)
v2.0.26-alpha.21	dts-bench-benchmark-bw6vk	1775m (1.775 cores)

[gnolong]

Updated analysis with the tokio-console data in a clearer format. This uses main branch for the current main branch sample, and relates the result to the flame graph evidence in #524.

Tokio-console comparison

Version	Task location	Role	State	Total	Busy	Sched	Idle	Polls	What it means
v2.0.25	dt-task/src/task_runner.rs#L429-L431	extractor task	SCHED/DONE	3m08s-3m12s	52s-53s	33s-34s	1m41s-1m45s	78.1M-83.5M	Primary scheduling storm. This is the abnormal signal.
v2.0.25	dt-task/src/task_runner.rs#L434-L436	pipeline task	IDLE/DONE	3m09s-3m12s	about 8s	196ms-383ms	3m01s-3m03s	34.5k-40k	Some polling exists, but it is much smaller than the extractor task.
v2.0.25	dt-task/src/task_runner.rs#L445-L448	monitor flush task	IDLE/DONE	about 3m08s	319ms-584ms	about 2s	about 3m06s	about 1.7k	Not the CPU root cause.
v2.0.24	dt-task/src/task_runner.rs#L457-L459	extractor task	DONE	about 3m12s	31s	15s	2m26s	51k-52k	Same broad bottleneck area, but far less severe than v2.0.25.
v2.0.24	dt-task/src/task_runner.rs#L462-L464	pipeline task	DONE	about 3m13s	about 7s	410ms-588ms	3m04s-3m05s	615-626	Normal compared with v2.0.25 extractor polling.
v2.0.24	dt-task/src/task_runner.rs#L468-L470	monitor flush task	DONE	about 3m13s	63ms-77ms	about 1s	about 3m12s	191	Not the CPU root cause.
main branch	dt-connector/src/extractor/snapshot_dispatcher.rs#L61-L68	snapshot worker tasks	DONE	3m14s-3m20s	26s-27s	8s-11s	2m39s-2m42s	1.9k-2.0k	Looks like real snapshot extraction work, not idle scheduler spin.
main branch	dt-task/src/task_runner.rs#L678-L681	extractor worker	IDLE	3m21s	137ms	167ms	3m20s	288k	Many polls, but very low busy and scheduled time. Not comparable to v2.0.25 extractor CPU cost.
main branch	dt-task/src/task_runner.rs#L686-L689	pipeline worker	IDLE	3m21s	32s	632ms	2m48s	252k	Some pipeline polling remains, but scheduled time is far below v2.0.25 extractor scheduling.

Why v2.0.25 is abnormal

The v2.0.25 extractor task maps to extractor.extract().await in task_runner.rs#L429-L431. The likely hot path is queue backpressure in DtQueue::push: dt-common/src/meta/dt_queue.rs#L46-L54.

In v2.0.25, when the queue is full or the byte limit is reached, the producer does this:

• check full condition
• call yield_now().await
• get scheduled again very quickly
• poll again
• find the queue still full
• repeat

That loop does not wait for a consumer-side notification. Under sustained backpressure it turns into a scheduler churn loop. The tokio-console numbers match this: 78M-83M polls over about 188-192 seconds is roughly 400k+ polls per second for each affected extractor task.

Why v2.0.24 is less severe

v2.0.24 has a similar queue backpressure shape, but it uses a 1ms sleep instead of yield_now: dt-common/src/meta/dt_queue.rs#L42-L50.

That is still polling, so it can still add overhead. But it caps the poll rate. The shared v2.0.24 data shows about 51k polls in roughly 3 minutes for the extractor task, while v2.0.25 shows about 80M polls in a similar runtime. That is about three orders of magnitude more polling in v2.0.25.

Why main branch is different

The main branch queue implementation uses event-driven wakeup instead of a busy yield_now loop. push waits on not_full.notified().await when the queue or memory budget is full: dt-common/src/meta/dt_queue.rs#L61-L81. pop wakes one producer after freeing queue capacity: dt-common/src/meta/dt_queue.rs#L84-L105.

The main branch still has a yield_now().await in the pipeline loop: dt-pipeline/src/base_pipeline.rs#L127-L184. However, the shared tokio-console data shows the main branch pipeline worker with about 252k polls and only 632ms scheduled time. That is much smaller than the v2.0.25 extractor task with 80M+ polls and 33s-34s scheduled time.

Conclusion

The data is sufficient to explain the scheduling-heavy CPU regression in v2.0.25. The strongest signal is the extractor task at v2.0.25 task_runner.rs#L429-L431, which points to the yield_now based queue backpressure loop in v2.0.25 dt_queue.rs#L46-L54.

A practical fix direction is to backport the main branch Notify based queue backpressure implementation to the v2.0.25 line. The same change would also remove the remaining 1ms polling behavior in v2.0.24, although v2.0.24 is much less severe than v2.0.25.

[gnolong]

Follow-up validation after applying the DtQueue backpressure fix on the v2.0.25 profiling branch.

The new image was built successfully from commit b97e1ef2fd6bd48f3c269f5c1eae3d770e1a1a2b:

• Image tag: apecloud-registry.cn-zhangjiakou.cr.aliyuncs.com/apecloud/ape-dts:2.0.25-profile-console-dtqueue-notify-amd64
• GitHub Actions run: https://github.com/apecloud/ape-dts/actions/runs/28651736489

The tokio-console data after the change shows the expected result.

Version	Task location	Busy	Sched	Polls	Result
v2.0.25 before fix	dt-task/src/task_runner.rs:429 extractor task	52s-53s	33s-34s	78M-83M	Abnormal scheduler churn
v2.0.25 after fix	dt-task/src/task_runner.rs:429 extractor task, ID 39	31s	13s	2,449	Poll storm removed
v2.0.25 after fix	dt-task/src/task_runner.rs:429 extractor task, ID 36	33s	13s	115,532	Much lower than before; no 80M-level busy-yield loop
v2.0.25 after fix	dt-task/src/task_runner.rs:434 pipeline task, ID 40	8s	85ms	119,585	Remaining polling is in the pipeline path and has very low scheduled time

This confirms the original high CPU signal was mainly caused by the yield_now().await backpressure loop in DtQueue::push. After replacing that busy-yield loop with Notify based producer wakeup, the extractor task no longer shows the 80M+ poll pattern.

There is still some polling in the pipeline loop, but its scheduled time is low compared with the original extractor problem. So the v2.0.25 DtQueue patch reaches the expected goal for this CPU issue.