Skip to content

[fix]Optimize debug logging#30995

Closed
ixzc wants to merge 6 commits intoapache:masterfrom
ixzc:modify_log_format
Closed

[fix]Optimize debug logging#30995
ixzc wants to merge 6 commits intoapache:masterfrom
ixzc:modify_log_format

Conversation

@ixzc
Copy link
Contributor

@ixzc ixzc commented Feb 8, 2024

Proposed changes

Issue Number: close #xxx

A conditional check is added to determine if debug level logging is required

Further comments

If this is a relatively large or complex change, kick off the discussion at dev@doris.apache.org by explaining why you chose the solution you did and what alternatives you considered, etc...

@doris-robot
Copy link

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

@CalvinKirs
Copy link
Member

run buildall

@doris-robot
Copy link

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

------ Round 1 ----------------------------------
q1	17715	4978	4843	4843
q2	2055	138	132	132
q3	10588	993	1000	993
q4	4652	952	962	952
q5	7687	3228	3269	3228
q6	195	138	130	130
q7	1299	777	750	750
q8	9233	2069	2043	2043
q9	7533	6660	6654	6654
q10	8313	2644	2632	2632
q11	417	222	219	219
q12	803	327	329	327
q13	18006	3653	3668	3653
q14	292	263	250	250
q15	593	509	554	509
q16	470	429	409	409
q17	923	884	870	870
q18	7455	6726	6551	6551
q19	1557	1502	1495	1495
q20	630	320	323	320
q21	6394	3888	3957	3888
q22	879	360	346	346
Total cold run time: 107689 ms
Total hot run time: 41194 ms

----- Round 2, with runtime_filter_mode=off -----
q1	4894	4829	4841	4829
q2	293	186	186	186
q3	3577	3555	3575	3555
q4	2519	2519	2538	2519
q5	5747	5727	5730	5727
q6	208	125	123	123
q7	2215	1677	1660	1660
q8	2996	3080	3079	3079
q9	8637	8670	8694	8670
q10	6778	4230	4227	4227
q11	558	412	413	412
q12	814	540	566	540
q13	4870	3399	3387	3387
q14	279	241	247	241
q15	593	501	510	501
q16	470	423	464	423
q17	1643	1609	1961	1609
q18	8296	7575	7557	7557
q19	1629	1642	1639	1639
q20	2093	1817	1835	1817
q21	6524	6164	6121	6121
q22	581	529	495	495
Total cold run time: 66214 ms
Total hot run time: 59317 ms

@doris-robot
Copy link

TPC-DS: Total hot run time: 180841 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 845bbc97e4b3df86e1142a9afec15734e2d207d2, data reload: false

query1	952	347	347	347
query2	6550	1830	1904	1830
query3	6709	208	209	208
query4	24674	22484	22608	22484
query5	4237	376	468	376
query6	256	159	163	159
query7	4602	298	288	288
query8	255	202	198	198
query9	8446	2836	2847	2836
query10	420	213	222	213
query11	16142	15610	15559	15559
query12	132	84	82	82
query13	1701	419	415	415
query14	9157	7660	7604	7604
query15	218	186	186	186
query16	7296	253	246	246
query17	1413	573	538	538
query18	1963	275	267	267
query19	189	148	151	148
query20	85	82	83	82
query21	190	115	122	115
query22	5054	4902	4847	4847
query23	32512	31673	31552	31552
query24	12650	3381	3400	3381
query25	626	372	364	364
query26	1817	152	162	152
query27	3048	303	304	303
query28	6616	1830	1824	1824
query29	1177	617	614	614
query30	278	139	143	139
query31	951	768	787	768
query32	94	55	55	55
query33	707	228	241	228
query34	1079	489	489	489
query35	943	829	832	829
query36	985	928	889	889
query37	127	59	63	59
query38	3479	3290	3353	3290
query39	1388	1327	1300	1300
query40	286	102	106	102
query41	37	35	34	34
query42	106	99	98	98
query43	477	440	457	440
query44	1080	688	710	688
query45	203	188	176	176
query46	1041	792	757	757
query47	1669	1578	1570	1570
query48	416	339	339	339
query49	1162	297	294	294
query50	785	381	374	374
query51	5382	5199	5149	5149
query52	103	89	92	89
query53	388	303	301	301
query54	310	217	228	217
query55	87	82	81	81
query56	220	204	215	204
query57	1057	984	954	954
query58	209	199	203	199
query59	2329	2292	2305	2292
query60	246	226	217	217
query61	85	85	87	85
query62	599	387	368	368
query63	318	286	281	281
query64	6363	3116	3159	3116
query65	3275	3260	3237	3237
query66	1372	342	333	333
query67	14688	14653	14093	14093
query68	5146	530	559	530
query69	521	350	355	350
query70	1274	1256	1253	1253
query71	431	260	252	252
query72	6392	2756	2642	2642
query73	697	316	308	308
query74	7108	6628	6737	6628
query75	3245	2564	2564	2564
query76	3254	1152	1210	1152
query77	371	242	230	230
query78	9380	8825	8760	8760
query79	956	504	495	495
query80	516	359	339	339
query81	441	209	204	204
query82	162	84	83	83
query83	141	120	123	120
query84	223	75	82	75
query85	1033	339	338	338
query86	297	297	293	293
query87	3676	3426	3437	3426
query88	2701	2276	2264	2264
query89	429	353	374	353
query90	1981	169	163	163
query91	157	126	127	126
query92	54	51	48	48
query93	967	509	491	491
query94	1142	182	181	181
query95	486	8517	365	365
query96	573	260	263	260
query97	4437	4301	4304	4301
query98	221	206	194	194
query99	1094	701	737	701
Total cold run time: 272917 ms
Total hot run time: 180841 ms

@doris-robot
Copy link

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

query1	0.03	0.03	0.02
query2	0.06	0.03	0.02
query3	0.23	0.07	0.07
query4	1.64	0.08	0.08
query5	0.49	0.48	0.48
query6	1.39	0.61	0.61
query7	0.02	0.01	0.01
query8	0.04	0.02	0.02
query9	0.53	0.45	0.45
query10	0.49	0.50	0.51
query11	0.13	0.09	0.09
query12	0.11	0.10	0.10
query13	0.59	0.59	0.59
query14	0.78	0.79	0.79
query15	0.85	0.81	0.78
query16	0.32	0.33	0.34
query17	0.90	0.92	0.89
query18	0.16	0.18	0.19
query19	1.74	1.68	1.69
query20	0.01	0.01	0.01
query21	15.39	0.62	0.60
query22	3.13	3.62	2.53
query23	17.69	1.08	1.05
query24	1.99	0.60	0.36
query25	0.65	0.06	0.06
query26	0.17	0.14	0.15
query27	0.06	0.04	0.04
query28	11.99	0.81	0.78
query29	12.51	3.43	3.27
query30	0.51	0.49	0.47
query31	2.77	0.35	0.38
query32	3.34	0.48	0.48
query33	3.13	3.12	3.19
query34	15.56	4.52	4.49
query35	4.48	4.51	4.52
query36	1.06	0.94	0.94
query37	0.06	0.05	0.05
query38	0.04	0.03	0.03
query39	0.01	0.01	0.02
query40	0.17	0.15	0.14
query41	0.08	0.02	0.01
query42	0.03	0.02	0.02
query43	0.03	0.02	0.02
Total cold run time: 105.36 s
Total hot run time: 31.17 s

@doris-robot
Copy link

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

Load test result on commit 845bbc97e4b3df86e1142a9afec15734e2d207d2 with default session variables
Stream load json:         19 seconds loaded 2358488459 Bytes, about 118 MB/s
Stream load orc:          60 seconds loaded 1101869774 Bytes, about 17 MB/s
Stream load parquet:      31 seconds loaded 861443392 Bytes, about 26 MB/s
Insert into select:       13.5 seconds inserted 10000000 Rows, about 740K ops/s

@CalvinKirs
Copy link
Member

run buildall

@doris-robot
Copy link

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

------ Round 1 ----------------------------------
q1	17625	4947	4829	4829
q2	2035	138	131	131
q3	10587	1034	991	991
q4	4661	963	972	963
q5	7700	3192	3237	3192
q6	199	141	128	128
q7	1271	780	756	756
q8	9266	2070	2066	2066
q9	7570	6616	6645	6616
q10	8304	2621	2653	2621
q11	410	204	205	204
q12	793	320	330	320
q13	17974	3647	3656	3647
q14	296	267	255	255
q15	579	509	524	509
q16	473	397	407	397
q17	916	874	845	845
q18	7464	6718	6766	6718
q19	1565	1505	1499	1499
q20	625	339	318	318
q21	6520	3888	3946	3888
q22	863	355	342	342
Total cold run time: 107696 ms
Total hot run time: 41235 ms

----- Round 2, with runtime_filter_mode=off -----
q1	4826	4822	4820	4820
q2	291	183	190	183
q3	3610	3575	3595	3575
q4	2519	2513	2511	2511
q5	5711	5697	5717	5697
q6	211	127	128	127
q7	2218	1638	1640	1638
q8	2975	3059	3056	3056
q9	8632	8630	8644	8630
q10	6768	4232	4246	4232
q11	526	368	375	368
q12	770	534	541	534
q13	4944	3414	3405	3405
q14	259	250	240	240
q15	630	527	492	492
q16	491	462	471	462
q17	1661	1606	1609	1606
q18	8272	7510	7551	7510
q19	1643	1637	1638	1637
q20	2104	1839	1819	1819
q21	6582	6159	6100	6100
q22	593	527	518	518
Total cold run time: 66236 ms
Total hot run time: 59160 ms

@doris-robot
Copy link

TPC-DS: Total hot run time: 180610 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 ed9a601866fb076ea61be7223d06f7975c08ca86, data reload: false

query1	951	343	345	343
query2	6532	1856	1882	1856
query3	6693	211	213	211
query4	24784	22476	22398	22398
query5	4287	470	461	461
query6	263	169	164	164
query7	4613	302	296	296
query8	263	201	202	201
query9	8459	2814	2811	2811
query10	417	216	223	216
query11	16213	15641	15490	15490
query12	146	88	86	86
query13	1712	423	427	423
query14	9104	7676	7749	7676
query15	216	180	196	180
query16	7465	257	251	251
query17	1425	564	544	544
query18	1964	271	262	262
query19	193	146	148	146
query20	92	84	87	84
query21	191	119	117	117
query22	4977	4713	4720	4713
query23	32375	31566	31447	31447
query24	12753	3416	3394	3394
query25	651	365	361	361
query26	1824	154	166	154
query27	3049	305	313	305
query28	6652	1800	1791	1791
query29	1137	621	604	604
query30	274	138	145	138
query31	950	753	757	753
query32	100	57	56	56
query33	721	235	242	235
query34	1066	489	493	489
query35	926	831	851	831
query36	1028	919	867	867
query37	132	59	60	59
query38	3464	3284	3327	3284
query39	1383	1296	1298	1296
query40	289	109	103	103
query41	36	35	36	35
query42	104	101	109	101
query43	482	466	459	459
query44	1072	682	689	682
query45	194	195	175	175
query46	1036	809	778	778
query47	1624	1570	1527	1527
query48	418	336	346	336
query49	1178	313	307	307
query50	784	374	375	374
query51	5246	5227	5158	5158
query52	105	92	99	92
query53	401	301	308	301
query54	313	225	224	224
query55	84	80	84	80
query56	227	208	211	208
query57	1023	932	932	932
query58	223	208	190	190
query59	2323	2210	2215	2210
query60	251	226	238	226
query61	86	94	81	81
query62	612	376	357	357
query63	328	289	285	285
query64	6387	3139	3166	3139
query65	3279	3251	3261	3251
query66	1340	331	320	320
query67	14707	14398	14287	14287
query68	5154	569	570	569
query69	652	360	371	360
query70	1292	1227	1242	1227
query71	417	255	261	255
query72	6470	2781	2618	2618
query73	703	317	310	310
query74	7016	6640	6573	6573
query75	3249	2567	2546	2546
query76	3345	1125	1190	1125
query77	361	246	249	246
query78	9492	8797	8741	8741
query79	969	520	514	514
query80	527	363	345	345
query81	434	210	206	206
query82	169	81	82	81
query83	152	127	121	121
query84	225	77	78	77
query85	1021	337	337	337
query86	312	318	305	305
query87	3532	3429	3422	3422
query88	2696	2272	2271	2271
query89	446	364	380	364
query90	1938	174	166	166
query91	156	126	128	126
query92	55	51	50	50
query93	1007	499	513	499
query94	1126	183	177	177
query95	489	8766	373	373
query96	582	259	263	259
query97	4393	4232	4253	4232
query98	231	212	196	196
query99	1077	708	719	708
Total cold run time: 273285 ms
Total hot run time: 180610 ms

@doris-robot
Copy link

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

query1	0.03	0.02	0.02
query2	0.07	0.02	0.03
query3	0.23	0.08	0.06
query4	1.63	0.07	0.08
query5	0.48	0.48	0.48
query6	1.37	0.60	0.62
query7	0.02	0.02	0.02
query8	0.04	0.03	0.02
query9	0.52	0.45	0.45
query10	0.49	0.49	0.50
query11	0.13	0.10	0.09
query12	0.12	0.10	0.10
query13	0.59	0.59	0.58
query14	0.77	0.79	0.78
query15	0.80	0.79	0.79
query16	0.33	0.33	0.32
query17	0.91	0.94	0.93
query18	0.19	0.18	0.18
query19	1.82	1.72	1.70
query20	0.02	0.01	0.01
query21	15.41	0.62	0.60
query22	3.57	3.35	2.80
query23	17.58	1.12	1.08
query24	2.24	0.52	0.12
query25	0.46	0.07	0.06
query26	0.15	0.13	0.14
query27	0.06	0.05	0.06
query28	12.12	0.88	0.82
query29	12.50	3.23	3.29
query30	0.51	0.48	0.51
query31	2.77	0.34	0.36
query32	3.33	0.48	0.48
query33	3.18	3.13	3.15
query34	15.35	4.50	4.48
query35	4.47	4.52	4.48
query36	1.06	0.96	0.94
query37	0.08	0.05	0.05
query38	0.04	0.02	0.02
query39	0.02	0.02	0.01
query40	0.17	0.15	0.16
query41	0.08	0.02	0.01
query42	0.03	0.02	0.01
query43	0.02	0.01	0.02
Total cold run time: 105.76 s
Total hot run time: 31.19 s

@doris-robot
Copy link

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

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

@CalvinKirs
Copy link
Member

run buildall

@doris-robot
Copy link

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

------ Round 1 ----------------------------------
q1	17690	5157	5025	5025
q2	2053	153	139	139
q3	10567	1028	1010	1010
q4	4656	976	993	976
q5	7724	3266	3249	3249
q6	201	140	133	133
q7	1260	789	766	766
q8	9246	2073	2055	2055
q9	7587	6745	6698	6698
q10	8327	2643	2637	2637
q11	424	211	209	209
q12	740	334	340	334
q13	17988	3697	3728	3697
q14	300	264	269	264
q15	606	546	548	546
q16	499	422	432	422
q17	926	864	800	800
q18	7530	6663	6592	6592
q19	1569	1497	1507	1497
q20	651	350	364	350
q21	6947	4099	4044	4044
q22	896	373	353	353
Total cold run time: 108387 ms
Total hot run time: 41796 ms

----- Round 2, with runtime_filter_mode=off -----
q1	4990	5026	5017	5017
q2	303	188	183	183
q3	3642	3633	3620	3620
q4	2599	2604	2612	2604
q5	5785	5783	5773	5773
q6	217	137	131	131
q7	2272	1640	1667	1640
q8	3065	3110	3130	3110
q9	8750	8819	8771	8771
q10	6795	4270	4266	4266
q11	519	404	380	380
q12	805	560	569	560
q13	5096	3450	3474	3450
q14	272	242	243	242
q15	648	508	509	508
q16	480	450	462	450
q17	1680	1636	1630	1630
q18	8325	7855	7709	7709
q19	1654	1657	1651	1651
q20	2133	1841	1831	1831
q21	6689	6342	6320	6320
q22	623	535	556	535
Total cold run time: 67342 ms
Total hot run time: 60381 ms

@doris-robot
Copy link

TPC-DS: Total hot run time: 183501 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 ca80c39def87ab0b08f1d75ad87cb67024db81bd, data reload: false

query1	937	363	347	347
query2	6521	1871	1818	1818
query3	6696	217	217	217
query4	24648	22562	22550	22550
query5	4313	483	392	392
query6	272	190	180	180
query7	4624	318	318	318
query8	259	204	205	204
query9	8425	3021	3000	3000
query10	433	254	236	236
query11	16187	15666	15823	15666
query12	144	87	86	86
query13	1740	472	453	453
query14	9201	7925	7801	7801
query15	214	191	195	191
query16	7359	276	268	268
query17	1395	574	541	541
query18	1979	287	275	275
query19	199	154	152	152
query20	86	86	87	86
query21	192	126	119	119
query22	4983	4783	4848	4783
query23	32489	31723	31664	31664
query24	12722	3449	3430	3430
query25	647	389	379	379
query26	1877	175	161	161
query27	3040	335	335	335
query28	6588	1967	1956	1956
query29	1194	657	626	626
query30	288	140	159	140
query31	931	772	778	772
query32	100	61	57	57
query33	737	247	257	247
query34	1020	517	536	517
query35	964	846	872	846
query36	1023	911	909	909
query37	179	62	61	61
query38	3442	3304	3323	3304
query39	1383	1350	1322	1322
query40	289	108	109	108
query41	39	37	36	36
query42	109	105	103	103
query43	539	474	478	474
query44	1084	748	752	748
query45	201	193	183	183
query46	1071	797	784	784
query47	1701	1592	1662	1592
query48	444	375	379	375
query49	1217	315	315	315
query50	807	416	404	404
query51	5405	5249	5174	5174
query52	122	98	100	98
query53	403	316	306	306
query54	307	232	236	232
query55	90	92	85	85
query56	231	213	213	213
query57	1068	1004	970	970
query58	223	207	234	207
query59	2327	2194	2307	2194
query60	256	231	244	231
query61	88	88	89	88
query62	607	380	389	380
query63	327	300	297	297
query64	6464	3114	3203	3114
query65	3317	3305	3258	3258
query66	1338	345	330	330
query67	14750	14691	14213	14213
query68	5147	606	628	606
query69	554	401	397	397
query70	1364	1293	1270	1270
query71	434	270	271	270
query72	6384	2939	2729	2729
query73	750	350	346	346
query74	7292	6815	6780	6780
query75	3233	2592	2568	2568
query76	3280	1157	1215	1157
query77	375	256	243	243
query78	9585	8914	8777	8777
query79	994	540	536	536
query80	541	369	364	364
query81	439	207	212	207
query82	162	88	90	88
query83	153	134	125	125
query84	232	87	84	84
query85	1045	377	368	368
query86	311	321	317	317
query87	3612	3471	3456	3456
query88	2891	2505	2502	2502
query89	446	380	371	371
query90	1930	174	175	174
query91	178	146	151	146
query92	62	50	49	49
query93	1018	535	540	535
query94	1105	196	189	189
query95	503	8556	394	394
query96	604	281	282	281
query97	4439	4267	4314	4267
query98	220	234	207	207
query99	1047	777	781	777
Total cold run time: 274585 ms
Total hot run time: 183501 ms

@doris-robot
Copy link

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

query1	0.03	0.03	0.02
query2	0.06	0.03	0.03
query3	0.23	0.08	0.07
query4	1.63	0.09	0.08
query5	0.50	0.47	0.49
query6	1.38	0.63	0.63
query7	0.02	0.01	0.02
query8	0.04	0.03	0.02
query9	0.54	0.47	0.46
query10	0.49	0.51	0.50
query11	0.13	0.09	0.10
query12	0.13	0.10	0.10
query13	0.63	0.60	0.59
query14	0.77	0.80	0.80
query15	0.84	0.83	0.81
query16	0.32	0.32	0.33
query17	0.93	0.91	0.90
query18	0.20	0.17	0.18
query19	1.80	1.65	1.71
query20	0.02	0.01	0.02
query21	15.42	0.67	0.63
query22	3.23	4.52	1.84
query23	17.64	1.10	1.03
query24	2.26	0.34	0.55
query25	0.62	0.08	0.07
query26	0.17	0.15	0.15
query27	0.06	0.05	0.06
query28	11.65	0.89	0.84
query29	12.79	3.42	3.52
query30	0.56	0.54	0.49
query31	2.79	0.38	0.38
query32	3.26	0.48	0.48
query33	3.17	3.19	3.20
query34	15.35	4.57	4.52
query35	4.55	4.53	4.54
query36	1.09	0.95	0.95
query37	0.08	0.06	0.06
query38	0.04	0.03	0.03
query39	0.02	0.01	0.02
query40	0.17	0.15	0.14
query41	0.07	0.02	0.02
query42	0.03	0.02	0.01
query43	0.03	0.02	0.03
Total cold run time: 105.74 s
Total hot run time: 30.93 s

@doris-robot
Copy link

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

Load test result on commit ca80c39def87ab0b08f1d75ad87cb67024db81bd with default session variables
Stream load json:         19 seconds loaded 2358488459 Bytes, about 118 MB/s
Stream load orc:          63 seconds loaded 1101869774 Bytes, about 16 MB/s
Stream load parquet:      33 seconds loaded 861443392 Bytes, about 24 MB/s
Insert into select:       13.6 seconds inserted 10000000 Rows, about 735K ops/s

@ixzc
Copy link
Contributor Author

ixzc commented Feb 18, 2024

run buildall

@ixzc ixzc closed this Feb 19, 2024
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.

3 participants