doris icon indicating copy to clipboard operation
doris copied to clipboard

[enhancement](Nereids) show process time when execute explain plan in nereids

Open 924060929 opened this issue 1 year ago • 6 comments

Proposed changes

show process time when execute explain plan xxx by nereids

example:

mysql> explain plan select * from tt;
+---------------------------------------------------------------------------------------------------------------+
| Explain String(Nereids Planner)                                                                               |
+---------------------------------------------------------------------------------------------------------------+
| ========== PARSED PLAN (time: 3ms) ==========                                                                 |
| UnboundResultSink[3] (  )                                                                                     |
| +--LogicalProject[2] ( distinct=false, projects=[*], excepts=[] )                                             |
|    +--LogicalCheckPolicy (  )                                                                                 |
|       +--UnboundRelation ( id=RelationId#0, nameParts=tt )                                                    |
|                                                                                                               |
| ========== ANALYZED PLAN (time: 6ms) ==========                                                               |
| LogicalResultSink[11] ( outputExprs=[id#0, name#1] )                                                          |
| +--LogicalProject[9] ( distinct=false, projects=[id#0, name#1], excepts=[] )                                  |
|    +--LogicalOlapScan ( qualified=test.tt, indexName=<index_not_selected>, selectedIndexId=10361, preAgg=ON ) |
|                                                                                                               |
| ========== REWRITTEN PLAN (time: 0ms)==========                                                               |
| LogicalResultSink[11] ( outputExprs=[id#0, name#1] )                                                          |
| +--LogicalProject[9] ( distinct=false, projects=[id#0, name#1], excepts=[] )                                  |
|    +--LogicalOlapScan ( qualified=test.tt, indexName=<index_not_selected>, selectedIndexId=10361, preAgg=ON ) |
|                                                                                                               |
| ========== OPTIMIZED PLAN (time: 2ms) ==========                                                              |
| PhysicalResultSink[56] ( outputExprs=[id#0, name#1] )                                                         |
| +--PhysicalDistribute[53]@1 ( stats=2, distributionSpec=DistributionSpecGather )                              |
|    +--PhysicalProject[50]@1 ( stats=2, projects=[id#0, name#1] )                                              |
|       +--PhysicalOlapScan[tt]@0 ( stats=2 )                                                                   |
+---------------------------------------------------------------------------------------------------------------+
21 rows in set (0.01 sec)

924060929 avatar Feb 23 '24 10:02 924060929

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

doris-robot avatar Feb 23 '24 10:02 doris-robot

run buildall

924060929 avatar Feb 23 '24 10:02 924060929

run buildall

924060929 avatar Feb 23 '24 11:02 924060929

run buildall

924060929 avatar Feb 23 '24 11:02 924060929

run buildall

924060929 avatar Feb 23 '24 11:02 924060929

run buildall

924060929 avatar Feb 23 '24 12:02 924060929

PR approved by at least one committer and no changes requested.

github-actions[bot] avatar Feb 26 '24 07:02 github-actions[bot]

PR approved by anyone and no changes requested.

github-actions[bot] avatar Feb 26 '24 07:02 github-actions[bot]

run buildall

924060929 avatar Feb 27 '24 06:02 924060929

run buildall

924060929 avatar Feb 27 '24 07:02 924060929

TPC-H: Total hot run time: 37460 ms
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit 353a718830f2cbebc027fd8d7c6b015df082652b, data reload: false

------ Round 1 ----------------------------------
q1	17721	3988	4012	3988
q2	2044	142	131	131
q3	10578	982	919	919
q4	4666	929	924	924
q5	7624	2853	2960	2853
q6	181	121	119	119
q7	1218	748	742	742
q8	9262	1995	2000	1995
q9	7113	6232	6255	6232
q10	8155	2472	2494	2472
q11	426	217	205	205
q12	720	306	309	306
q13	17933	3221	3199	3199
q14	270	256	255	255
q15	538	480	485	480
q16	477	412	399	399
q17	918	894	839	839
q18	6675	5850	6105	5850
q19	1532	1503	1502	1502
q20	550	266	266	266
q21	6448	3500	3546	3500
q22	802	290	284	284
Total cold run time: 105851 ms
Total hot run time: 37460 ms

----- Round 2, with runtime_filter_mode=off -----
q1	4004	3991	4013	3991
q2	307	214	212	212
q3	2965	2910	2941	2910
q4	1852	1794	1842	1794
q5	5047	5083	5081	5081
q6	196	114	114	114
q7	2117	1706	1683	1683
q8	3096	3164	3175	3164
q9	8193	8217	8197	8197
q10	6061	3636	3646	3636
q11	518	438	418	418
q12	685	541	510	510
q13	12247	3073	3039	3039
q14	271	253	245	245
q15	540	488	487	487
q16	486	463	477	463
q17	1676	1662	1668	1662
q18	7848	7352	7353	7352
q19	1667	1617	1622	1617
q20	2093	1888	1892	1888
q21	4706	4505	4572	4505
q22	488	427	413	413
Total cold run time: 67063 ms
Total hot run time: 53381 ms

doris-robot avatar Feb 27 '24 07:02 doris-robot

TPC-DS: Total hot run time: 169034 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 353a718830f2cbebc027fd8d7c6b015df082652b, data reload: false

query1	944	335	337	335
query2	6522	1705	1681	1681
query3	6699	203	203	203
query4	23200	20573	20515	20515
query5	4215	356	352	352
query6	272	170	169	169
query7	4597	297	295	295
query8	265	183	207	183
query9	8500	2279	2264	2264
query10	419	208	215	208
query11	14569	14217	14121	14121
query12	137	83	82	82
query13	1629	428	440	428
query14	8647	6608	6239	6239
query15	201	181	178	178
query16	7091	256	263	256
query17	1036	520	506	506
query18	1910	270	272	270
query19	190	147	147	147
query20	86	83	90	83
query21	190	128	127	127
query22	4809	4610	4650	4610
query23	30361	29776	29817	29776
query24	11892	3096	3120	3096
query25	655	351	352	351
query26	1819	150	164	150
query27	3003	310	323	310
query28	6994	1826	1815	1815
query29	1182	565	549	549
query30	282	132	141	132
query31	839	670	697	670
query32	98	60	54	54
query33	711	226	232	226
query34	1043	480	484	480
query35	834	754	733	733
query36	944	862	869	862
query37	166	60	62	60
query38	3093	2981	3046	2981
query39	1296	1255	1252	1252
query40	280	97	100	97
query41	37	36	35	35
query42	101	97	101	97
query43	443	439	405	405
query44	1067	703	716	703
query45	185	175	172	172
query46	1038	801	787	787
query47	1491	1404	1406	1404
query48	421	341	345	341
query49	1151	308	286	286
query50	766	371	375	371
query51	4337	4209	4334	4209
query52	97	87	93	87
query53	330	263	260	260
query54	281	221	229	221
query55	88	80	78	78
query56	217	208	196	196
query57	982	842	875	842
query58	210	187	195	187
query59	2080	2107	2095	2095
query60	254	214	209	209
query61	86	86	84	84
query62	591	362	366	362
query63	282	263	254	254
query64	6560	2995	3144	2995
query65	3228	3195	3194	3194
query66	1450	318	325	318
query67	14695	14143	14161	14143
query68	4973	543	568	543
query69	530	384	366	366
query70	1219	1202	1239	1202
query71	359	242	248	242
query72	6275	2812	2658	2658
query73	709	316	319	316
query74	6303	6039	6044	6039
query75	3052	2408	2420	2408
query76	2818	994	1095	994
query77	348	231	230	230
query78	8896	8714	8537	8537
query79	958	513	518	513
query80	551	371	354	354
query81	451	194	194	194
query82	162	86	86	86
query83	245	122	120	120
query84	279	78	74	74
query85	1045	348	353	348
query86	310	271	295	271
query87	3237	3113	3106	3106
query88	2720	2348	2351	2348
query89	370	353	334	334
query90	1943	164	158	158
query91	151	125	122	122
query92	54	49	47	47
query93	1014	519	499	499
query94	1104	183	174	174
query95	432	332	341	332
query96	572	266	266	266
query97	4257	4124	4151	4124
query98	224	194	195	194
query99	1008	654	674	654
Total cold run time: 260657 ms
Total hot run time: 169034 ms

doris-robot avatar Feb 27 '24 07:02 doris-robot

ClickBench: Total hot run time: 31.9 s
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit 353a718830f2cbebc027fd8d7c6b015df082652b, data reload: false

query1	0.04	0.03	0.03
query2	0.06	0.03	0.03
query3	0.23	0.07	0.06
query4	1.68	0.10	0.10
query5	0.52	0.52	0.51
query6	1.33	0.67	0.66
query7	0.01	0.02	0.01
query8	0.03	0.02	0.02
query9	0.55	0.50	0.52
query10	0.56	0.55	0.54
query11	0.12	0.10	0.10
query12	0.13	0.10	0.09
query13	0.62	0.62	0.61
query14	0.80	0.79	0.82
query15	0.85	0.82	0.82
query16	0.35	0.39	0.38
query17	0.95	0.98	0.97
query18	0.28	0.26	0.26
query19	1.82	1.74	1.72
query20	0.02	0.01	0.01
query21	15.40	0.68	0.68
query22	3.25	3.85	2.03
query23	17.68	0.99	1.04
query24	2.13	0.31	0.58
query25	0.47	0.11	0.09
query26	0.18	0.16	0.17
query27	0.05	0.04	0.05
query28	12.01	0.83	0.82
query29	12.59	3.26	3.37
query30	0.53	0.54	0.45
query31	2.78	0.35	0.36
query32	3.36	0.49	0.49
query33	3.18	3.23	3.21
query34	15.35	4.80	4.73
query35	4.75	4.76	4.79
query36	1.15	1.07	1.07
query37	0.07	0.05	0.05
query38	0.04	0.02	0.02
query39	0.02	0.01	0.02
query40	0.16	0.12	0.13
query41	0.07	0.02	0.02
query42	0.02	0.02	0.01
query43	0.03	0.02	0.02
Total cold run time: 106.22 s
Total hot run time: 31.9 s

doris-robot avatar Feb 27 '24 08:02 doris-robot

Load test result on machine: 'aliyun_ecs.c7a.8xlarge_32C64G'

Load test result on commit 353a718830f2cbebc027fd8d7c6b015df082652b with default session variables
Stream load json:         19 seconds loaded 2358488459 Bytes, about 118 MB/s
Stream load orc:          59 seconds loaded 1101869774 Bytes, about 17 MB/s
Stream load parquet:      32 seconds loaded 861443392 Bytes, about 25 MB/s
Insert into select:       16.6 seconds inserted 10000000 Rows, about 602K ops/s

doris-robot avatar Feb 27 '24 08:02 doris-robot

PR approved by at least one committer and no changes requested.

github-actions[bot] avatar Feb 27 '24 09:02 github-actions[bot]