Skip to content

[fix](profile) Nereids Optimize Time shows N/A when MV pre-rewrite is skipped - #67532

Open
xy720 wants to merge 1 commit into
apache:masterfrom
xy720:profile-bug
Open

[fix](profile) Nereids Optimize Time shows N/A when MV pre-rewrite is skipped#67532
xy720 wants to merge 1 commit into
apache:masterfrom
xy720:profile-bug

Conversation

@xy720

@xy720 xy720 commented Sep 4, 2026

Copy link
Copy Markdown
Member

getPrettyNereidsOptimizeTime computes the elapsed time as optimizeFinish - preRewriteByMvFinish,

But preRewriteByMvFinish is only set at the tail of preMaterializedViewRewrite, which early-exits whenever pre-rewrite is not needed.

The start marker stays at -1, getPrettyTime sees -1 and returns "N/A" — even though CBO did run and optimizeFinish is set.

This misleads users on any query that skips MV pre-rewrite:
1.MV refresh,
2.INSERT, large joins using DpHyper,
3.Sessions with enable_materialized_view_rewrite=false,
4.Queries that don't touch any MV at all

Example:
an MV refresh with
Rewrite Time: 4ms,
Translate Time:239ms
still prints Optimize Time: N/A, misleading anyone reading the profile into thinking CBO was skipped.

Fall back the start marker through earlier phase finish times (preRewriteByMv -> collectTablePartition -> rewrite) so the elapsed time is shown whenever the upstream phase actually finished.

What problem does this PR solve?

Issue Number: close #xxx

Related PR: #xxx

Problem Summary:

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

… skipped

`getPrettyNereidsOptimizeTime` computes the elapsed time as `optimizeFinish - preRewriteByMvFinish`,
but `preRewriteByMvFinish` is only set at the tail of `preMaterializedViewRewrite`, which early-exits whenever pre-rewrite is not needed.
The start marker stays at -1, `getPrettyTime` sees -1 and returns "N/A" — even though CBO did run and `optimizeFinish` is set.

This misleads users on any query that skips MV pre-rewrite:
1.MV refresh,
2.INSERT, large joins using DpHyper,
3.Sessions with `enable_materialized_view_rewrite=false`,
4.Queries that don't touch any MV at all

Example:
an MV refresh with
`Rewrite Time: 4ms`,
`Translate Time:239ms`
 still prints `Optimize Time: N/A`, misleading anyone reading the profile into thinking CBO was skipped.

Fall back the start marker through earlier phase finish times
(`preRewriteByMv -> collectTablePartition -> rewrite`) so the elapsed
time is shown whenever the upstream phase actually finished.
@xy720

xy720 commented Sep 4, 2026

Copy link
Copy Markdown
Member Author

run buildall

1 similar comment
@xy720

xy720 commented Sep 4, 2026

Copy link
Copy Markdown
Member Author

run buildall

@hello-stephen

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

------ Round 1 ----------------------------------
============================================
q1	17562	3089	3098	3089
q2	2099	260	248	248
q3	10209	917	517	517
q4	4669	250	204	204
q5	7675	549	386	386
q6	137	117	99	99
q7	535	496	379	379
q8	9233	906	954	906
q9	3463	2423	2416	2416
q10	6521	855	694	694
q11	392	215	182	182
q12	614	257	201	201
q13	18131	1541	1155	1155
q14	160	149	139	139
q15	q16	435	392	371	371
q17	1311	851	775	775
q18	3129	2284	2280	2280
q19	1270	898	816	816
q20	388	296	203	203
q21	5604	1665	1830	1665
q22	325	265	232	232
Total cold run time: 93862 ms
Total hot run time: 16957 ms

----- Round 2, with runtime_filter_mode=off -----
============================================
q1	3492	3399	3405	3399
q2	514	385	371	371
q3	2184	2315	2233	2233
q4	1202	1178	907	907
q5	2185	2119	2119	2119
q6	170	123	87	87
q7	1044	937	851	851
q8	1627	1441	1442	1441
q9	3183	3123	3109	3109
q10	1848	1816	1642	1642
q11	362	274	254	254
q12	463	434	347	347
q13	1499	1555	1161	1161
q14	177	167	163	163
q15	q16	397	400	359	359
q17	3609	3332	3239	3239
q18	4833	4422	4763	4422
q19	981	880	846	846
q20	995	968	821	821
q21	3894	3260	3276	3260
q22	392	365	326	326
Total cold run time: 35051 ms
Total hot run time: 31357 ms

@hello-stephen

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

query5	4262	429	350	350
query6	396	149	135	135
query7	4887	436	230	230
query8	302	131	123	123
query9	8700	2908	2934	2908
query10	401	236	188	188
query11	5381	1045	933	933
query12	123	71	73	71
query13	1210	449	314	314
query14	6128	2263	2143	2143
query14_1	2026	2038	2048	2038
query15	171	124	115	115
query16	914	390	347	347
query17	1069	485	376	376
query18	2617	347	240	240
query19	168	137	112	112
query20	126	71	72	71
query21	203	101	89	89
query22	5489	5488	5465	5465
query23	6887	6417	6016	6016
query23_1	6171	6147	6259	6147
query24	7279	1102	793	793
query24_1	806	796	789	789
query25	437	315	267	267
query26	1242	224	130	130
query27	2791	425	259	259
query28	4634	1539	1504	1504
query29	947	440	366	366
query30	252	153	134	134
query31	811	402	346	346
query32	140	83	80	80
query33	468	216	187	187
query34	996	814	498	498
query35	420	395	352	352
query36	580	568	550	550
query37	125	86	72	72
query38	1010	849	841	841
query39	495	497	466	466
query39_1	460	478	473	473
query40	208	95	79	79
query41	60	60	55	55
query42	74	76	72	72
query43	247	250	216	216
query44	1061	561	554	554
query45	119	104	130	104
query46	790	865	550	550
query47	776	773	708	708
query48	319	306	231	231
query49	535	240	187	187
query50	778	257	196	196
query51	8244	8489	8102	8102
query52	66	66	57	57
query53	196	204	148	148
query54	218	167	156	156
query55	72	65	56	56
query56	212	155	171	155
query57	682	686	660	660
query58	217	191	165	165
query59	1254	1274	1097	1097
query60	235	183	181	181
query61	138	113	120	113
query62	354	205	180	180
query63	173	142	142	142
query64	2684	709	603	603
query65	1664	1597	1591	1591
query66	1710	274	206	206
query67	9926	9726	9619	9619
query68	2738	1212	781	781
query69	334	231	200	200
query70	661	612	612	612
query71	256	176	171	171
query72	2335	1754	1541	1541
query73	650	595	358	358
query74	1586	1255	1159	1159
query75	1167	1106	957	957
query76	2297	736	545	545
query77	249	273	217	217
query78	4003	3676	3260	3260
query79	3036	843	577	577
query80	1613	333	271	271
query81	510	154	138	138
query82	1016	132	101	101
query83	267	207	189	189
query84	253	108	92	92
query85	842	367	296	296
query86	502	177	175	175
query87	1037	966	880	880
query88	3510	2123	2131	2123
query89	282	194	176	176
query90	2181	134	126	126
query91	134	122	99	99
query92	106	72	69	69
query93	3352	1023	660	660
query94	674	255	236	236
query95	514	315	260	260
query96	831	580	277	277
query97	1070	1044	1035	1035
query98	186	133	138	133
query99	430	351	313	313
Total cold run time: 182572 ms
Total hot run time: 82927 ms

@hello-stephen

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

query1	0.00	0.00	0.00
query2	0.08	0.04	0.04
query3	0.24	0.11	0.11
query4	1.60	0.09	0.10
query5	0.18	0.16	0.16
query6	1.26	0.72	0.72
query7	0.03	0.01	0.00
query8	0.05	0.03	0.03
query9	0.29	0.21	0.23
query10	0.35	0.33	0.34
query11	0.16	0.13	0.11
query12	0.15	0.12	0.13
query13	0.33	0.31	0.31
query14	0.45	0.46	0.45
query15	0.36	0.35	0.38
query16	0.21	0.24	0.23
query17	0.65	0.73	0.66
query18	0.19	0.16	0.17
query19	1.22	1.15	1.19
query20	0.02	0.01	0.01
query21	15.45	0.17	0.12
query22	5.02	0.05	0.04
query23	16.19	0.26	0.10
query24	3.11	0.33	0.26
query25	0.10	0.04	0.03
query26	0.73	0.17	0.14
query27	0.04	0.02	0.03
query28	3.62	0.54	0.26
query29	12.44	3.20	2.59
query30	0.25	0.11	0.14
query31	2.76	0.38	0.17
query32	3.52	0.31	0.24
query33	1.37	1.52	1.39
query34	15.38	2.18	1.75
query35	1.78	1.74	1.74
query36	0.48	0.29	0.29
query37	0.06	0.04	0.04
query38	0.04	0.02	0.02
query39	0.03	0.03	0.02
query40	0.12	0.09	0.08
query41	0.07	0.02	0.03
query42	0.03	0.02	0.02
query43	0.03	0.03	0.02
Total cold run time: 90.44 s
Total hot run time: 14.71 s

@hello-stephen

Copy link
Copy Markdown
Contributor

FE UT Coverage Report

Increment line coverage 80.00% (8/10) 🎉
Increment coverage report
Complete coverage report

@hello-stephen

Copy link
Copy Markdown
Contributor

FE Regression Coverage Report

Increment line coverage 80.00% (8/10) 🎉
Increment coverage report
Complete coverage report

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants