Skip to content

[fix](be) Count the materialization push time once - #69579

Merged
morningman merged 1 commit into
apache:masterfrom
morningman:b2m-t37a-materialization-push-timer
Oct 26, 2026
Merged

morningman merged 1 commit into
apache:masterfrom
morningman:b2m-t37a-materialization-push-timer

Conversation

@morningman

Copy link
Copy Markdown
Contributor

What problem does this PR solve?

Issue Number: None

Related PR: #68690

Problem Summary:

In short. This ports the materialization timing fix of branch-4.1 #68690 to master. MaterializationOperator::push timed itself with the same ExecTime counter that the operator framework already uses around every push(), so the operator's ExecTime counted each push twice, including the synchronous row-fetch RPC wait. push() no longer opens its own timer.

Original author: @Gabriel39

Background. MaterializationOperator is the second phase of TopN lazy materialization: it collects row IDs from its child and fetches the remaining columns from the backends that own the rows, waiting for the fetch RPCs inside push(). It is a StatefulOperatorX, and StatefulOperatorX::get_block_impl already wraps every push() and pull() in SCOPED_TIMER(local_state.exec_time_counter()).

The problem, and what it cost. MaterializationOperator::push opened a second SCOPED_TIMER(local_state.exec_time_counter()). Both timers add their elapsed time to the same counter when they go out of scope, so the time of every push was added twice. Since the row-fetch RPC wait happens inside push(), the profile reported a materialization ExecTime up to twice the real time, which points at the wrong operator when a TopN lazy materialization query is slow. Only the profile is affected; results and the fetch itself are not.

How this PR fixes it. push() drops its own timer and leaves the ExecTime sample to the framework, with a comment explaining why. pull() never had the nested timer. #68690 also adds Lance row-fetch counters and a Lance query parallelism option; those belong to the Lance work and are not part of this PR.

Results.

ExecTime of one push
Before counted twice (framework timer + the nested one in push())
After counted once, by the framework

Release note

None

Check List (For Author)

  • Test
  • 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

### What problem does this PR solve?

Issue Number: None

Related PR: apache#68690

Problem Summary: MaterializationOperator is a StatefulOperatorX, whose
get_block_impl already wraps push() in SCOPED_TIMER(exec_time_counter()).
MaterializationOperator::push opened a second SCOPED_TIMER on the same
counter, so every push, including the synchronous row-fetch RPC wait of
the second phase of a TopN lazy materialization, was added to ExecTime
twice and the operator's profile overstated its execution time. This is
the timing fix of branch-4.1 apache#68690, which is otherwise about Lance; the
Lance parts follow with the Lance work. push() no longer opens its own
timer, and the framework counts it once.

### Release note

None

### Check List (For Author)

- Test: Unit Test
    - materialization_shared_state_test.cpp: 100 direct push() calls
      leave ExecTime unchanged; the framework owns the sample
- Behavior changed: No (profile counter only)
- Does this need documentation: No

Co-authored-by: Gabriel <liwenqiang@selectdb.com>
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
@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?

@morningman

Copy link
Copy Markdown
Contributor Author

run buildall

@morningman

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.

Static review of head 7ff57c15e00a6fa969145c0c75601235b9ecdaed found no actionable new defects in the complete two-file diff.

StatefulOperatorX::get_block_impl scopes ExecTime around push() and pull() independently (be/src/exec/operator/operator.cpp:743-772). Removing the nested timer leaves the synchronous row-fetch wait and early error returns accounted once, with child execution outside these scopes. MaxRpcTime and MergeResponseTime remain intact.

Critical checkpoint Conclusion
Goal and supporting test The change corrects duplicate materialization timing. The new test checks that 100 direct empty, non-EOS pushes add no second ExecTime sample; its assertions match that path.
Scope and clarity One redundant production timer is removed, with an accurate explanatory comment and a focused test.
Concurrency and locks No new thread, lock scope, lock order, atomic, or dependency change. Framework timers use task-local state; existing RPC callback/countdown coordination is preserved.
Lifecycle and static initialization Tuple lookup, factory creation, local-state registration and ownership were traced. Default destructors and non-owning profile child pointers make this empty fixture's teardown valid. No new static initialization or ownership cycle.
Configuration No additions or dynamic configuration changes.
Compatibility and rolling upgrades No function signatures, storage formats, wire contracts or new libc dependencies change.
Thrift/protobuf definitions No gensrc change; cross-branch field-id comparison is not applicable.
Parallel paths Production materialization uses the inherited timed dispatcher; no bypassing production push caller was found. Pull already has no duplicate local timer.
Conditions and comments No production condition changes; the new comment correctly explains timer ownership and duplicate RPC-wait accounting.
Test coverage Existing BE-UT discovery and private-access conventions cover the added test. Its initialized-RPC flag and empty input deliberately avoid expressions and network calls. Nonempty/EOS/error wrapper paths were checked statically.
Changed expected results No golden files changed; unchanged-counter equality is appropriate for the exercised direct-call path.
Observability ExecTime attribution is corrected; dedicated RPC/merge metrics remain. No additional logging or counters are needed.
Transactions, persistence and failover No affected transaction, EditLog, version, bitmap or persistence logic.
Data writes and atomicity No write, crash-recovery or atomicity behavior changes.
FE-BE variables No transmitted variables or send paths change.
Performance and memory Removes redundant stopwatch reads/counter updates; adds no production allocation. Test objects have bounded RAII/ObjectPool ownership.
Other issues and core invariants Data visibility, version/delete-bitmap consistency, Status propagation, reservations and nullable/const handling remain unchanged. No additional substantiated issue found.

No additional user focus was supplied. There are no existing inline findings to carry forward, and no unresolved code candidates or uncovered changed files remain after the complete review and separate fixture-risk review.

Validation limits: static review only, as required by this runner. No build, test execution, runtime timing measurement or ELF audit was performed. The new test does not establish distributed RPC timing or positive framework timing empirically; the unchanged framework scopes were inspected in code.

Review converged after 2 round(s).

@hello-stephen

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

------ Round 1 ----------------------------------
============================================
q1	17599	5112	5048	5048
q2	2149	339	252	252
q3	10216	1369	809	809
q4	4678	462	335	335
q5	7413	795	538	538
q6	181	186	151	151
q7	739	789	598	598
q8	9244	1341	1071	1071
q9	5474	4189	4154	4154
q10	6818	1276	1012	1012
q11	420	248	225	225
q12	625	393	281	281
q13	18105	3499	3017	3017
q14	266	269	244	244
q15	q16	711	703	666	666
q17	1188	755	575	575
q18	7003	6122	6113	6113
q19	1100	950	598	598
q20	404	332	221	221
q21	5418	2153	2297	2153
q22	348	300	248	248
Total cold run time: 100099 ms
Total hot run time: 28309 ms

----- Round 2, with runtime_filter_mode=off -----
============================================
q1	5603	5615	5608	5608
q2	663	556	582	556
q3	5258	5398	4906	4906
q4	1985	2157	1533	1533
q5	5282	5129	5550	5129
q6	270	201	151	151
q7	2292	2063	1909	1909
q8	2998	2678	2711	2678
q9	7939	7989	7838	7838
q10	3710	3654	3222	3222
q11	613	431	410	410
q12	854	704	522	522
q13	3468	3755	3262	3262
q14	306	341	276	276
q15	q16	700	735	701	701
q17	8315	7563	6821	6821
q18	13002	12194	12968	12194
q19	899	767	774	767
q20	2132	2149	1913	1913
q21	5603	4600	4661	4600
q22	481	435	429	429
Total cold run time: 72373 ms
Total hot run time: 65425 ms

@hello-stephen

Copy link
Copy Markdown
Contributor
TPC-DS: Total hot run time: 150671 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 7ff57c15e00a6fa969145c0c75601235b9ecdaed, data reload: false

query5	4319	589	432	432
query6	433	215	196	196
query7	4806	433	227	227
query8	349	172	158	158
query9	8785	3108	3125	3108
query10	465	325	258	258
query11	5984	3873	3566	3566
query12	148	94	88	88
query13	1261	445	323	323
query14	6124	3958	3656	3656
query14_1	3488	3445	3443	3443
query15	208	196	181	181
query16	968	440	404	404
query17	874	660	535	535
query18	2423	434	324	324
query19	202	161	138	138
query20	86	87	88	87
query21	211	135	109	109
query22	12891	13089	12830	12830
query23	13705	12837	12483	12483
query23_1	12600	12500	12575	12500
query24	7364	832	461	461
query24_1	484	483	475	475
query25	539	420	363	363
query26	1264	266	142	142
query27	2737	436	270	270
query28	4624	1955	1949	1949
query29	1567	607	460	460
query30	304	229	185	185
query31	1008	939	809	809
query32	138	95	94	94
query33	536	309	252	252
query34	876	845	517	517
query35	760	748	652	652
query36	814	812	743	743
query37	131	102	81	81
query38	1778	1723	1690	1690
query39	795	802	767	767
query39_1	732	717	729	717
query40	225	122	104	104
query41	72	68	70	68
query42	88	84	86	84
query43	345	370	313	313
query44	1281	685	683	683
query45	179	173	168	168
query46	843	977	576	576
query47	3017	3091	2804	2804
query48	311	316	231	231
query49	585	432	295	295
query50	681	267	216	216
query51	10485	10622	10312	10312
query52	78	86	70	70
query53	201	217	151	151
query54	245	194	174	174
query55	76	72	66	66
query56	224	223	204	204
query57	1639	1622	1559	1559
query58	287	256	257	256
query59	2044	2138	1909	1909
query60	281	238	222	222
query61	146	144	144	144
query62	453	356	309	309
query63	191	153	158	153
query64	2764	943	786	786
query65	3320	3263	3290	3263
query66	1787	421	302	302
query67	20254	20175	19854	19854
query68	2944	996	612	612
query69	407	292	246	246
query70	856	758	761	758
query71	297	234	217	217
query72	2653	2560	2211	2211
query73	503	530	299	299
query74	4621	4492	4334	4334
query75	2314	2294	1898	1898
query76	2332	1030	566	566
query77	341	383	267	267
query78	9714	9678	9166	9166
query79	1055	843	514	514
query80	1226	425	357	357
query81	591	318	273	273
query82	579	132	106	106
query83	294	203	175	175
query84	305	118	101	101
query85	873	424	360	360
query86	399	249	229	229
query87	1995	1938	1822	1822
query88	3697	2662	2631	2631
query89	334	275	240	240
query90	1880	168	163	163
query91	165	149	127	127
query92	101	89	89	89
query93	1119	999	568	568
query94	632	309	269	269
query95	577	321	371	321
query96	650	488	234	234
query97	2445	2439	2340	2340
query98	165	154	149	149
query99	773	774	648	648
Total cold run time: 235487 ms
Total hot run time: 150671 ms

@hello-stephen

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

query1	0.00	0.00	0.00
query2	0.09	0.05	0.06
query3	0.27	0.09	0.09
query4	1.62	0.10	0.10
query5	0.28	0.25	0.25
query6	1.18	0.69	0.69
query7	0.04	0.01	0.00
query8	0.05	0.04	0.03
query9	0.40	0.34	0.34
query10	0.58	0.62	0.61
query11	0.20	0.14	0.15
query12	0.18	0.15	0.15
query13	0.49	0.50	0.50
query14	1.03	1.02	1.00
query15	0.62	0.60	0.59
query16	0.35	0.36	0.36
query17	1.18	1.16	1.12
query18	0.21	0.20	0.19
query19	2.11	1.94	2.01
query20	0.02	0.01	0.01
query21	15.50	0.20	0.14
query22	4.85	0.06	0.06
query23	16.28	0.32	0.12
query24	3.12	0.56	0.42
query25	0.13	0.07	0.04
query26	0.86	0.24	0.15
query27	0.05	0.05	0.03
query28	2.60	0.76	0.40
query29	12.49	4.16	3.30
query30	0.28	0.13	0.11
query31	2.76	0.55	0.33
query32	3.22	0.60	0.50
query33	3.14	3.23	3.29
query34	15.26	3.98	3.38
query35	3.34	3.35	3.33
query36	0.55	0.45	0.41
query37	0.10	0.06	0.07
query38	0.06	0.04	0.04
query39	0.04	0.03	0.04
query40	0.18	0.16	0.14
query41	0.08	0.04	0.03
query42	0.03	0.02	0.02
query43	0.05	0.03	0.03
Total cold run time: 95.87 s
Total hot run time: 24.46 s

@hello-stephen

Copy link
Copy Markdown
Contributor

BE UT Coverage Report

Increment line coverage 🎉

Increment coverage report
Complete coverage report

Category Coverage
Function Coverage 66.58% (31992/48047)
Line Coverage 51.39% (337523/656794)
Region Coverage 46.76% (273147/584184)
Branch Coverage 48.49% (128727/265484)

@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 77.35% (36008/46552)
Line Coverage 62.63% (406971/649757)
Region Coverage 59.05% (343713/582074)
Branch Coverage 60.07% (159077/264835)

morningman added a commit to morningman/doris that referenced this pull request Oct 26, 2026
### What problem does this PR solve?

Issue Number: None

Related PR: apache#65730 apache#66608 apache#66805 apache#66841 apache#66999 apache#67005 apache#67011 apache#67110 apache#67268 apache#67289 apache#67325 apache#67650 apache#67921 apache#68028 apache#68335 apache#68375 apache#68615 apache#68690

Problem Summary:

Port the Lance BE read path of branch-4.1/4.2 (as of branch-4.2
cabcf45) to master. Master links liblance_c but has no Lance reader:
file_scan_operator keeps FORMAT_LANCE off FileScannerV2 and V1 has no
Lance path, so every FORMAT_LANCE scan fails today. This change is BE
only. The FE connector plugin and the regression suites follow
separately, so nothing on master plans a Lance scan yet and the BE unit
tests carry the proof.

- Reader: be/src/format_v2/lance/* and format_v2/table/lance_reader.*
  (plain scans, vector and full-text search, Substrait and runtime
  filter pushdown, scalar index segments, COUNT(*) from metadata, LIMIT,
  profiles), copied from branch-4.2 except one local renamed for
  -Wshadow.
- Hooks: FileFormat::LANCE and its exhaustive switches, FileScannerV2
  dispatch, and fetch_table_schema for FORMAT_LANCE. Lance queries use
  FileScannerV2 whatever enable_file_scanner_v2 says, as ADBC and fluss
  do: there is no V1 Lance reader. The second phase of TopN lazy
  materialization reads Lance rows through dataset take_rows.
- Row locations: GlobalRowLoacationV2 gets a version 1 layout with a
  64-bit Lance row id (the version 0 layout is unchanged),
  PRequestBlockDesc.row_id becomes uint64 (varint, wire compatible), and
  the materialization operator and RowIdStorageReader decode and
  validate by version.
- Thrift: the external search request body, TLanceFileDesc 4-6 and
  TExternalSearchRequest 2-4 with the branch-4.1/4.2 ids.
- Core: PTypeDesc keeps NULL_TYPE for a NULL literal type, and the
  nullable serde reads an Arrow Null array as NULLs.
- Nine lance_* BE configs, a BE-wide Lance session with an optional
  Foyer data cache and 10 lance_session_* metrics; macOS links IOKit.
- Tests: the Lance BE unit tests and their fixtures, including the
  docker fixture all_types.lance that one of them reads. Under master's
  -ffile-prefix-map the session test locates its fixture from the
  repository root, and the reader tests shrink the data cache to 64 MiB
  under the UT temp dir: the default 100 GiB disk tier is 51200 block
  files that stay open for the rest of the test process.

Not included: the MaterializationOperator::push timer fix (apache#69579), the
Lance index metadata scanner, the FE side, regression suites, and the
4.x changes after cabcf45 (apache#68707, apache#68813, apache#68815).

### Release note

Add nine lance_* BE configs and lance_session_* BE metrics. They take
effect once the FE can plan Lance scans.

### Check List (For Author)

- Test: Unit Test
    - BE UT: the Lance reader, nested Null, runtime filter and session
      suites, plus the row-location protocol and FileScannerV2 cases
- Behavior changed: Yes. PRequestBlockDesc.row_id is uint64, and the
  second phase of TopN lazy materialization rejects row locations of an
  unknown version or size.
- Does this need documentation: No (documented with the FE connector)

Co-authored-by: zhangstar333 <zhangsida@selectdb.com>
Co-authored-by: Gabriel <liwenqiang@selectdb.com>
Co-authored-by: zhaobo wang <wangzhaobo957@gmail.com>
Co-authored-by: jay <qingfengyouchen@163.com>
Co-authored-by: FANNG <fanng@apache.org>
Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
@morningman
morningman merged commit c560d93 into apache:master Oct 26, 2026
38 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