Skip to content

[bugfix](cancel) cancel message is printed too many times - #67344

Merged
HappenLee merged 3 commits into
apache:masterfrom
yiguolei:fix_repeat_cancel
Sep 1, 2026
Merged

[bugfix](cancel) cancel message is printed too many times#67344
HappenLee merged 3 commits into
apache:masterfrom
yiguolei:fix_repeat_cancel

Conversation

@yiguolei

Copy link
Copy Markdown
Contributor

What problem does this PR solve?

Issue Number: close #xxx

Related PR: #xxx

When a query times out, every pending pipeline task can close with the same error and call PipelineFragmentContext::cancel() before the fragment task count is drained. Each call previously repeated fragment cancellation logs, the full timeout task dump, stream-pipe cancellation, and dependency wakeups, causing severe log amplification.

Release note

None

Check List (For Author)

  • Test

    • Regression test
    • Unit Test
    • Manual test (add detailed scripts or steps below)
    • No need to test or manual test. Explain why:
      • This is a refactor/code format and no logic has been changed.
      • Previous test can cover this change.
      • No code files have been changed.
      • Other reason
  • Behavior changed:

    • No.
    • Yes.
  • Does this need documentation?

    • No.
    • Yes.

Check List (For Reviewer who merge this PR)

  • Confirm the release note
  • Confirm test cases
  • Confirm document
  • Add branch pick label

@hello-stephen

Copy link
Copy Markdown
Contributor

Thank you for your contribution to Apache Doris.
Don't know what should be done next? See How to process your PR.

Please clearly describe your PR:

  1. What problem was fixed (it's best to include specific error reporting information). How it was fixed.
  2. Which behaviors were modified. What was the previous behavior, what is it now, why was it modified, and what possible impacts might there be.
  3. What features were added. Why was this function added?
  4. Which code was refactored and why was this part of the code refactored?
  5. Which functions were optimized and what is the difference before and after the optimization?

@yiguolei

Copy link
Copy Markdown
Contributor Author

run buildall

@yiguolei

Copy link
Copy Markdown
Contributor Author

/review

@github-actions

Copy link
Copy Markdown
Contributor

Codex automated review failed and did not complete.

Error: Codex completed, but no new pull request review was submitted for the current head SHA.
Workflow run: https://github.com/apache/doris/actions/runs/33376261997

Please inspect the workflow logs and rerun the review after the underlying issue is resolved.

@yiguolei

Copy link
Copy Markdown
Contributor Author

run buildall

@yiguolei

Copy link
Copy Markdown
Contributor Author

/review

@github-actions github-actions Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Requesting changes for one cancellation/publication race.

  • Goal and scope: Centralizing first-error cancellation in QueryContext is a focused change that prevents repeated expensive PFC diagnostics and dependency fan-out for fragments already registered; the internal caller/signature migration is complete.
  • Concurrency and lifecycle: Scheduler, dependency wakeup, fragment prepare/publication, external cancellation, report, workload, and recursive rerun/close paths were traced. Map and task locks are released before cross-object cleanup, and no additional deadlock, UAF, or ownership cycle was found. The cancellation snapshot is not reconciled with later PFC publication, however; see the inline comment.
  • Parallel and error paths: Registered fragments retain one local cleanup pass, first-error precedence, stream/load metadata handling, and report fallbacks. Submit, task close/finalize, report failure, workload cancellation, and both scheduler variants did not produce a distinct issue.
  • Tests: No test changed. Existing injected-failure coverage proves only query failure, not once-only cleanup or the cancellation-versus-publication/early-FINAL_CLOSE ordering. The fix needs deterministic lifecycle coverage.
  • Compatibility, configuration, persistence, and data writes: No FE/BE protocol, rolling-upgrade, configuration, persisted-format, transaction, visibility, or storage-write change applies.
  • Performance and observability: The intended one-time O(fragments plus tasks/dependencies) fan-out is preserved for registered PFCs. The unchanged per-task warning is a non-blocking residual behavior.
  • User focus: No additional focus was provided.

Review completed for head 1cd7c5387ae53834bc24779266d86b826fb17bd7; one blocking inline issue remains.

// Copy the fragment contexts under the map lock, then cancel them after releasing it. Fragment
// cancellation may take task-level locks and must not run while holding the query map lock.
std::vector<std::weak_ptr<PipelineFragmentContext>> ctx_to_cancel;
{

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[P1] Reconcile cancellation with late fragment publication

The query error is published before this snapshot, while set_pipeline_context() can insert afterward without observing the terminal status. A concrete recursive case is a cancel RPC arriving after the last task-prepare cancellation check but before FragmentMgr publishes a need_notify_close PFC: cancellation snapshots/removes the current query state, and the parent's one-shot FINAL_CLOSE can see NotFound; the prepare worker can then publish and submit the PFC. Its scheduler close path now re-enters QueryContext::cancel() and loses the first-error guard, so fragment-local cancel()/notify_close() never runs and _close_fragment_instance() cannot remove the PFC, leaving it and its QueryContext/rerunnable state strongly retained. Please linearize registration with cancellation (or reject publication into a terminal query), keep PFC cleanup outside the map lock, and cover this post-prepare race plus early FINAL_CLOSE deterministically.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

not a problem. And I will review this logic and fix
all the problems.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

not a problem because,maybe fix in another PR。

@hello-stephen

Copy link
Copy Markdown
Contributor

BE Regression && UT Coverage Report

Increment line coverage 100% (0/0) 🎉

Increment coverage report
Complete coverage report

Category Coverage
Function Coverage 76.12% (34506/45333)
Line Coverage 61.10% (388837/636406)
Region Coverage 57.26% (326539/570300)
Branch Coverage 58.05% (148889/256470)

@hello-stephen

Copy link
Copy Markdown
Contributor
TPC-H: Total hot run time: 17021 ms
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit 1cd7c5387ae53834bc24779266d86b826fb17bd7, data reload: false

------ Round 1 ----------------------------------
============================================
q1	17649	3045	3050	3045
q2	2121	263	219	219
q3	10223	892	533	533
q4	4665	248	206	206
q5	7677	577	383	383
q6	135	114	98	98
q7	523	547	395	395
q8	9229	894	942	894
q9	3494	2427	2411	2411
q10	6551	894	712	712
q11	396	193	183	183
q12	613	267	202	202
q13	18134	1578	1180	1180
q14	157	148	138	138
q15	q16	434	396	374	374
q17	1320	858	830	830
q18	3179	2329	2330	2329
q19	1266	877	759	759
q20	370	284	198	198
q21	5575	1702	1891	1702
q22	337	271	230	230
Total cold run time: 94048 ms
Total hot run time: 17021 ms

----- Round 2, with runtime_filter_mode=off -----
============================================
q1	3396	3326	3336	3326
q2	524	405	367	367
q3	2277	2473	2328	2328
q4	1211	1180	897	897
q5	2220	2153	2153	2153
q6	174	120	86	86
q7	1038	949	889	889
q8	1596	1403	1418	1403
q9	3246	3213	3202	3202
q10	1917	1819	1667	1667
q11	366	281	258	258
q12	455	435	352	352
q13	1481	1526	1194	1194
q14	178	174	162	162
q15	q16	390	397	360	360
q17	3679	3470	3339	3339
q18	4960	4573	5068	4573
q19	948	846	844	844
q20	1040	977	847	847
q21	3877	3195	3203	3195
q22	393	339	313	313
Total cold run time: 35366 ms
Total hot run time: 31755 ms

@hello-stephen

Copy link
Copy Markdown
Contributor
TPC-DS: Total hot run time: 83040 ms
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpcds-tools
TPC-DS sf100 test result on commit 1cd7c5387ae53834bc24779266d86b826fb17bd7, data reload: false

query5	4272	413	325	325
query6	375	135	137	135
query7	5002	389	235	235
query8	292	129	121	121
query9	8690	2849	2861	2849
query10	373	225	180	180
query11	5385	1059	934	934
query12	122	70	71	70
query13	1197	450	329	329
query14	6152	2266	2140	2140
query14_1	2026	2002	2027	2002
query15	173	125	116	116
query16	927	379	359	359
query17	803	453	359	359
query18	2336	327	245	245
query19	164	142	107	107
query20	72	73	74	73
query21	204	100	86	86
query22	5659	5396	5301	5301
query23	6802	6360	6158	6158
query23_1	6181	6089	6411	6089
query24	7273	1137	787	787
query24_1	797	793	773	773
query25	438	302	263	263
query26	1226	237	128	128
query27	2780	418	260	260
query28	4694	1501	1500	1500
query29	940	444	364	364
query30	258	164	132	132
query31	822	415	337	337
query32	128	77	75	75
query33	476	222	189	189
query34	984	824	480	480
query35	426	409	355	355
query36	569	560	573	560
query37	125	85	74	74
query38	1034	868	846	846
query39	504	476	449	449
query39_1	450	465	468	465
query40	200	94	80	80
query41	58	56	56	56
query42	74	73	74	73
query43	242	248	213	213
query44	1052	538	551	538
query45	111	105	98	98
query46	753	818	531	531
query47	771	766	707	707
query48	292	310	236	236
query49	524	235	183	183
query50	705	257	199	199
query51	8002	8003	7975	7975
query52	66	65	58	58
query53	188	200	201	200
query54	218	177	169	169
query55	73	57	54	54
query56	193	157	149	149
query57	681	683	681	681
query58	220	156	153	153
query59	1243	1258	1129	1129
query60	229	187	178	178
query61	126	111	109	109
query62	349	203	173	173
query63	180	139	140	139
query64	2774	693	561	561
query65	1669	1642	1653	1642
query66	1794	266	196	196
query67	10125	9961	10811	9961
query68	2957	1263	764	764
query69	330	204	192	192
query70	658	616	601	601
query71	255	182	165	165
query72	2348	1724	1567	1567
query73	650	580	355	355
query74	1967	1254	1175	1175
query75	1190	1107	969	969
query76	2322	759	545	545
query77	245	258	219	219
query78	4130	3930	3301	3301
query79	2417	822	611	611
query80	1565	338	271	271
query81	495	154	139	139
query82	629	128	99	99
query83	279	211	196	196
query84	294	113	95	95
query85	823	363	306	306
query86	384	178	167	167
query87	1036	984	913	913
query88	2793	2117	2082	2082
query89	281	192	171	171
query90	2022	129	132	129
query91	138	125	97	97
query92	75	70	69	69
query93	1369	1107	702	702
query94	626	239	219	219
query95	532	345	240	240
query96	813	577	266	266
query97	1082	1078	1066	1066
query98	142	139	134	134
query99	423	332	306	306
Total cold run time: 178785 ms
Total hot run time: 83040 ms

@hello-stephen

Copy link
Copy Markdown
Contributor
ClickBench: Total hot run time: 14.8 s
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit 1cd7c5387ae53834bc24779266d86b826fb17bd7, data reload: false

query1	0.00	0.00	0.00
query2	0.08	0.04	0.03
query3	0.24	0.11	0.11
query4	1.60	0.10	0.09
query5	0.17	0.15	0.17
query6	1.26	0.69	0.67
query7	0.03	0.01	0.01
query8	0.04	0.03	0.02
query9	0.28	0.22	0.21
query10	0.34	0.36	0.36
query11	0.16	0.12	0.12
query12	0.15	0.12	0.12
query13	0.32	0.32	0.31
query14	0.46	0.46	0.44
query15	0.38	0.35	0.35
query16	0.21	0.23	0.22
query17	0.64	0.67	0.70
query18	0.19	0.17	0.17
query19	1.14	1.24	1.18
query20	0.02	0.01	0.01
query21	15.45	0.16	0.13
query22	5.06	0.04	0.04
query23	16.17	0.24	0.10
query24	3.02	0.34	0.25
query25	0.10	0.05	0.04
query26	0.78	0.17	0.11
query27	0.02	0.02	0.03
query28	3.69	0.55	0.29
query29	12.43	3.17	2.56
query30	0.25	0.11	0.12
query31	2.76	0.37	0.17
query32	3.52	0.32	0.24
query33	1.40	1.54	1.49
query34	15.34	2.28	1.81
query35	1.77	1.74	1.71
query36	0.45	0.30	0.27
query37	0.06	0.03	0.03
query38	0.04	0.03	0.03
query39	0.03	0.03	0.02
query40	0.12	0.08	0.08
query41	0.08	0.02	0.02
query42	0.03	0.02	0.02
query43	0.04	0.02	0.03
Total cold run time: 90.32 s
Total hot run time: 14.8 s

@HappenLee HappenLee left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@HappenLee
HappenLee merged commit feb9e04 into apache:master Sep 1, 2026
35 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants