Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[opt](log) refine the BE logger #35942

Merged
merged 3 commits into from
Jun 6, 2024
Merged

Conversation

morningman
Copy link
Contributor

@morningman morningman commented Jun 5, 2024

Followup #35679

Background

Previously, BE logs were written to files. The main FE logs include be.INFO, be.WARNING, be.out, be.gc.log and jni.log.
In a K8s deployment environment, logs usually need to be output to standard output, and then other components process the log stream.

Solution

This PR made the following changes:

  1. Modified the glog config:

    • When started with --daemon, logs are still written to various files, and the format remains unchanged.

    • When started with --console, be.INFO's log is output to standard output and marked with prefix RuntimeLogger.

      Examples are as follows:

       RuntimeLogger I20240605 23:41:20.426553 4137369 runtime_query_statistics_mgr.cpp:245] Report profile thread stopped
      
  2. Added a new BE config: enable_file_logger

    Defaults to true. Indicates that logs will be recorded to files regardless of the startup method. For example, if it is started with --console, the log will be output to both the file and the standard output. If it is false, the log will not be recorded in the file regardless of the startup method.

TODO

  • Need to handle jni.log in next PR

@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

Since 2024-03-18, the Document has been moved to doris-website.
See Doris Document.

Copy link
Contributor

github-actions bot commented Jun 5, 2024

sh-checker report

To get the full details, please check in the job output.

shellcheck errors
'shellcheck ' found no issues.

shfmt errors

'shfmt ' returned error 1 finding the following formatting issues:

----------
--- bin/start_be.sh.orig
+++ bin/start_be.sh
@@ -111,11 +111,11 @@
     local IFS=$'\n'
 
     if ! command -v "${java_cmd}" >/dev/null; then
-        echo "ERROR: invalid java_cmd ${java_cmd}" >> "${STDOUT_LOGGER}"
+        echo "ERROR: invalid java_cmd ${java_cmd}" >>"${STDOUT_LOGGER}"
         result=no_java
         return 1
     else
-        echo "INFO: java_cmd ${java_cmd}" >> "${STDOUT_LOGGER}"
+        echo "INFO: java_cmd ${java_cmd}" >>"${STDOUT_LOGGER}"
         local version
         # remove \r for Cygwin
         version="$("${java_cmd}" -Xms32M -Xmx32M -version 2>&1 | tr '\r' '\n' | grep version | awk '{print $3}')"
@@ -125,7 +125,7 @@
         else
             result="$(echo "${version}" | awk -F '.' '{print $1}')"
         fi
-        echo "INFO: jdk_version ${result}" >> "${STDOUT_LOGGER}"
+        echo "INFO: jdk_version ${result}" >>"${STDOUT_LOGGER}"
     fi
     echo "${result}"
     return 0
@@ -263,7 +263,7 @@
     log "The JAVA_HOME environment variable is not set correctly"
     log "This environment variable is required to run this program"
     log "Note: JAVA_HOME should point to a JDK and not a JRE"
-    log  "You can set JAVA_HOME in the be.conf configuration file"
+    log "You can set JAVA_HOME in the be.conf configuration file"
     exit 1
 fi
 
----------

You can reformat the above files to meet shfmt's requirements by typing:

  shfmt  -w filename


Copy link
Contributor

github-actions bot commented Jun 5, 2024

clang-tidy review says "All clean, LGTM! 👍"

@morningman
Copy link
Contributor Author

run buildall

Copy link
Contributor

github-actions bot commented Jun 5, 2024

clang-tidy review says "All clean, LGTM! 👍"

1 similar comment
Copy link
Contributor

github-actions bot commented Jun 5, 2024

clang-tidy review says "All clean, LGTM! 👍"

@doris-robot
Copy link

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

------ Round 1 ----------------------------------
q1	17623	4450	4369	4369
q2	2027	201	195	195
q3	10460	1247	1173	1173
q4	10194	831	863	831
q5	7485	2765	2776	2765
q6	230	135	136	135
q7	1001	647	618	618
q8	9216	2186	2152	2152
q9	9345	6729	6773	6729
q10	9316	3908	3919	3908
q11	432	245	256	245
q12	456	252	246	246
q13	17372	3253	3313	3253
q14	282	221	223	221
q15	528	473	476	473
q16	511	404	396	396
q17	1011	699	635	635
q18	8435	7834	7937	7834
q19	6470	1363	1427	1363
q20	665	324	321	321
q21	5196	4124	4071	4071
q22	409	336	339	336
Total cold run time: 118664 ms
Total hot run time: 42269 ms

----- Round 2, with runtime_filter_mode=off -----
q1	4654	4517	4477	4477
q2	382	271	272	271
q3	3194	3009	2853	2853
q4	1968	1673	1749	1673
q5	5548	5533	5509	5509
q6	219	130	132	130
q7	2195	1882	1817	1817
q8	3246	3393	3453	3393
q9	8700	8650	8829	8650
q10	4134	3744	3720	3720
q11	594	495	484	484
q12	815	660	651	651
q13	16443	3167	3168	3167
q14	314	286	272	272
q15	543	499	479	479
q16	522	427	426	426
q17	1842	1534	1511	1511
q18	7856	7515	7340	7340
q19	1701	1562	1566	1562
q20	2062	1797	1805	1797
q21	8239	4906	4668	4668
q22	632	515	520	515
Total cold run time: 75803 ms
Total hot run time: 55365 ms

@doris-robot
Copy link

TPC-DS: Total hot run time: 174027 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 09efd163ab2e13156b76c6964dba10752eb28586, data reload: false

query1	941	379	383	379
query2	6441	2390	2375	2375
query3	6648	213	211	211
query4	19954	17304	17373	17304
query5	4139	476	476	476
query6	260	165	168	165
query7	4593	308	292	292
query8	310	283	279	279
query9	8745	2375	2365	2365
query10	444	311	284	284
query11	10614	10099	9897	9897
query12	136	86	86	86
query13	1639	382	360	360
query14	9987	7874	7831	7831
query15	241	197	186	186
query16	7803	269	266	266
query17	1832	558	535	535
query18	1904	279	279	279
query19	205	174	157	157
query20	98	84	88	84
query21	220	138	135	135
query22	4301	4029	3979	3979
query23	33834	33020	32919	32919
query24	11081	2891	2900	2891
query25	621	349	365	349
query26	999	169	157	157
query27	2302	343	324	324
query28	6510	2033	2027	2027
query29	888	625	609	609
query30	272	153	154	153
query31	997	760	728	728
query32	91	55	58	55
query33	808	284	285	284
query34	978	493	489	489
query35	732	623	617	617
query36	1082	930	934	930
query37	139	69	76	69
query38	2879	2780	2743	2743
query39	866	802	812	802
query40	203	125	129	125
query41	57	51	56	51
query42	117	102	106	102
query43	566	571	534	534
query44	1259	749	760	749
query45	199	162	162	162
query46	1090	736	746	736
query47	1847	1763	1756	1756
query48	387	304	313	304
query49	1131	417	437	417
query50	794	388	405	388
query51	6855	6715	6694	6694
query52	108	95	89	89
query53	364	298	303	298
query54	937	462	447	447
query55	78	72	76	72
query56	279	258	265	258
query57	1159	1067	1065	1065
query58	258	237	241	237
query59	3343	3329	3235	3235
query60	291	272	278	272
query61	108	134	100	100
query62	651	467	456	456
query63	328	299	295	295
query64	8859	2243	1727	1727
query65	3160	3123	3153	3123
query66	771	345	339	339
query67	15367	14827	14787	14787
query68	4526	565	569	565
query69	499	361	303	303
query70	1166	1123	1135	1123
query71	396	276	279	276
query72	7039	5887	5553	5553
query73	770	332	330	330
query74	6077	5479	5525	5479
query75	3387	2646	2663	2646
query76	2238	1023	990	990
query77	510	332	310	310
query78	10181	9923	9746	9746
query79	2292	526	524	524
query80	2334	479	469	469
query81	575	232	216	216
query82	1070	108	107	107
query83	315	173	172	172
query84	264	92	89	89
query85	1213	296	315	296
query86	456	315	373	315
query87	3293	3114	3109	3109
query88	3365	2454	2452	2452
query89	484	415	397	397
query90	1730	191	193	191
query91	129	101	98	98
query92	70	51	49	49
query93	1901	524	508	508
query94	1206	191	185	185
query95	415	317	327	317
query96	604	280	274	274
query97	3205	3044	3111	3044
query98	223	204	193	193
query99	1179	851	812	812
Total cold run time: 270212 ms
Total hot run time: 174027 ms

@doris-robot
Copy link

TeamCity be ut coverage result:
Function Coverage: 36.38% (8985/24697)
Line Coverage: 27.91% (73410/263009)
Region Coverage: 27.34% (38011/139012)
Branch Coverage: 23.94% (19288/80578)
Coverage Report: http://coverage.selectdb-in.cc/coverage/09efd163ab2e13156b76c6964dba10752eb28586_09efd163ab2e13156b76c6964dba10752eb28586/report/index.html

@doris-robot
Copy link

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

query1	0.03	0.02	0.03
query2	0.08	0.04	0.04
query3	0.23	0.04	0.05
query4	1.67	0.08	0.09
query5	0.49	0.48	0.49
query6	1.12	0.73	0.73
query7	0.02	0.01	0.02
query8	0.05	0.04	0.04
query9	0.54	0.49	0.48
query10	0.54	0.55	0.55
query11	0.15	0.12	0.11
query12	0.15	0.12	0.12
query13	0.59	0.59	0.60
query14	0.78	0.78	0.80
query15	0.82	0.81	0.82
query16	0.37	0.36	0.39
query17	1.03	0.98	0.99
query18	0.23	0.24	0.26
query19	1.77	1.73	1.70
query20	0.02	0.01	0.00
query21	15.43	0.69	0.70
query22	4.52	6.73	2.30
query23	18.35	1.37	1.30
query24	2.11	0.22	0.21
query25	0.16	0.08	0.09
query26	0.26	0.17	0.18
query27	0.08	0.08	0.08
query28	13.19	1.04	1.00
query29	13.25	3.48	3.40
query30	0.24	0.06	0.06
query31	2.87	0.38	0.39
query32	3.30	0.47	0.47
query33	2.87	2.90	2.92
query34	17.09	4.41	4.46
query35	4.51	4.49	4.66
query36	0.65	0.45	0.46
query37	0.17	0.14	0.15
query38	0.14	0.13	0.13
query39	0.05	0.03	0.04
query40	0.16	0.14	0.14
query41	0.10	0.05	0.05
query42	0.05	0.05	0.04
query43	0.04	0.03	0.03
Total cold run time: 110.27 s
Total hot run time: 31.11 s

@morningman morningman changed the title [opt](log) refine the FE logger [opt](log) refine the BE logger Jun 6, 2024
Copy link

@intelligentfu intelligentfu left a comment

Choose a reason for hiding this comment

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

done

Copy link
Contributor

github-actions bot commented Jun 6, 2024

PR approved by anyone and no changes requested.

Copy link
Contributor

github-actions bot commented Jun 6, 2024

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

@github-actions github-actions bot added the approved Indicates a PR has been approved by one committer. label Jun 6, 2024
@morningman morningman merged commit 6cd0669 into apache:master Jun 6, 2024
27 of 30 checks passed
morningman added a commit to morningman/doris that referenced this pull request Jun 6, 2024
Followup apache#35679

Previously, BE logs were written to files. The main FE logs include
be.INFO, be.WARNING, be.out, be.gc.log and jni.log.
In a K8s deployment environment, logs usually need to be output to
standard output, and then other components process the log stream.

This PR made the following changes:

1. Modified the glog config:

- When started with `--daemon`, logs are still written to various files,
and the format remains unchanged.
- When started with `--console`, be.INFO's log is output to standard
output and marked with prefix `RuntimeLogger`.

		Examples are as follows:

		```
RuntimeLogger I20240605 23:41:20.426553 4137369
runtime_query_statistics_mgr.cpp:245] Report profile thread stopped
		```

2. Added a new BE config: `enable_file_logger`

Defaults to true. Indicates that logs will be recorded to files
regardless of the startup method. For example, if it is started with
`--console`, the log will be output to both the file and the standard
output. If it is `false`, the log will not be recorded in the file
regardless of the startup method.

- Need to handle jni.log in next PR
morningman added a commit that referenced this pull request Jun 6, 2024
dataroaring pushed a commit that referenced this pull request Jun 7, 2024
Followup #35679

## Background

Previously, BE logs were written to files. The main FE logs include
be.INFO, be.WARNING, be.out, be.gc.log and jni.log.
In a K8s deployment environment, logs usually need to be output to
standard output, and then other components process the log stream.

## Solution

This PR made the following changes:

1. Modified the glog config:

- When started with `--daemon`, logs are still written to various files,
and the format remains unchanged.
- When started with `--console`, be.INFO's log is output to standard
output and marked with prefix `RuntimeLogger`.
		
		Examples are as follows:
		
		```
RuntimeLogger I20240605 23:41:20.426553 4137369
runtime_query_statistics_mgr.cpp:245] Report profile thread stopped
		```

2. Added a new BE config: `enable_file_logger`

Defaults to true. Indicates that logs will be recorded to files
regardless of the startup method. For example, if it is started with
`--console`, the log will be output to both the file and the standard
output. If it is `false`, the log will not be recorded in the file
regardless of the startup method.

## TODO

- Need to handle jni.log in next PR
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants