[enhancement](log4j) support high performance mode for log4j to escap…

…e potential bottleneck for doris read and write (apache#20759) As we know, log4j2 some times may be bottleneck in doris fe when there are many logs to be output in sync mode while asynchronous logging has a better performance， and we find that capturing caller location has a similar impact across all logging libraries, and slows down asynchronous logging by about 30-100x. so, here we provide three log mode for log4j2 to meet the needs of different users. refer to https://logging.apache.org/log4j/2.x/performance.html
jackwener · Jun 14, 2023 · bcf103e · bcf103e
1 parent f707dc9
commit bcf103e
Show file tree

Hide file tree

Showing 6 changed files with 66 additions and 20 deletions.
diff --git a/conf/fe.conf b/conf/fe.conf
@@ -38,6 +38,9 @@ JAVA_OPTS_FOR_JDK_9="-Xss4m -Xmx8192m -XX:SurvivorRatio=8 -XX:MaxTenuringThresho
 # INFO, WARN, ERROR, FATAL
 sys_log_level = INFO
 
+# NORMAL, BRIEF, ASYNC
+sys_log_mode = NORMAL
+
 # store metadata, must be created before start FE.
 # Default value is ${DORIS_HOME}/doris-meta
 # meta_dir = ${DORIS_HOME}/doris-meta

diff --git a/fe/fe-common/src/main/java/org/apache/doris/common/Config.java b/fe/fe-common/src/main/java/org/apache/doris/common/Config.java
@@ -34,10 +34,10 @@ public class Config extends ConfigBase {
      * sys_log_dir:
      *      This specifies FE log dir. FE will produces 2 log files:
      *      fe.log:      all logs of FE process.
-     *      fe.warn.log  all WARNING and ERROR log of FE process.
+     *      fe.warn.log  all WARN and ERROR log of FE process.
      *
      * sys_log_level:
-     *      INFO, WARNING, ERROR, FATAL
+     *      INFO, WARN, ERROR, FATAL
      *
      * sys_log_roll_num:
      *      Maximal FE log files to be kept within an sys_log_roll_interval.
@@ -65,9 +65,18 @@ public class Config extends ConfigBase {
             "The path of the FE log file, used to store fe.log"})
     public static String sys_log_dir = System.getenv("DORIS_HOME") + "/log";
 
-    @ConfField(description = {"FE 日志的级别", "The level of FE log"}, options = {"INFO", "WARNING", "ERROR", "FATAL"})
+    @ConfField(description = {"FE 日志的级别", "The level of FE log"}, options = {"INFO", "WARN", "ERROR", "FATAL"})
     public static String sys_log_level = "INFO";
 
+    @ConfField(description = {"FE 日志的输出模式，其中 NORMAL 为默认的输出模式，日志同步输出且包含位置信息，"
+            + "BRIEF 模式是日志同步输出但不包含位置信息，ASYNC 模式是日志异步输出且不包含位置信息，三种日志输出模式的性能依次递增",
+            "The output mode of FE log, and NORMAL mode is the default output mode, which means the logs are "
+                    + "synchronized and contain location information. BRIEF mode is synchronized and does not contain"
+                    + " location information. ASYNC mode is asynchronous and does not contain location information."
+                    + " The performance of the three log output modes increases in sequence"},
+            options = {"NORMAL", "BRIEF", "ASYNC"})
+    public static String sys_log_mode = "NORMAL";
+
     @ConfField(description = {"FE 日志文件的最大数量。超过这个数量后，最老的日志文件会被删除",
             "The maximum number of FE log files. After exceeding this number, the oldest log file will be deleted"})
     public static int sys_log_roll_num = 10;

diff --git a/fe/fe-core/src/main/java/org/apache/doris/DorisFE.java b/fe/fe-core/src/main/java/org/apache/doris/DorisFE.java
@@ -114,6 +114,7 @@ public static void start(String dorisHomeDir, String pidDir, String[] args, Star
             }
 
             Log4jConfig.initLogging(dorisHomeDir + "/conf/");
+            Runtime.getRuntime().addShutdownHook(new Thread(LogManager::shutdown));
 
             // set dns cache ttl
             java.security.Security.setProperty("networkaddress.cache.ttl", "60");

diff --git a/fe/fe-core/src/main/java/org/apache/doris/common/Log4jConfig.java b/fe/fe-core/src/main/java/org/apache/doris/common/Log4jConfig.java
@@ -44,12 +44,12 @@ public class Log4jConfig extends XmlConfiguration {
             + "  <Appenders>\n"
             + "    <Console name=\"Console\" target=\"SYSTEM_OUT\">"
             + "      <PatternLayout charset=\"UTF-8\">\n"
-            + "        <Pattern>%d{yyyy-MM-dd HH:mm:ss,SSS} %p (%t|%tid) [%C{1}.%M():%L] %m%n</Pattern>\n"
+            + "        <Pattern>%d{yyyy-MM-dd HH:mm:ss,SSS} %p (%t|%tid)<!--REPLACED BY LOG FORMAT-->%m%n</Pattern>\n"
             + "      </PatternLayout>\n"
             + "    </Console>"
             + "    <RollingFile name=\"Sys\" fileName=\"${sys_log_dir}/fe.log\" filePattern=\"${sys_log_dir}/fe.log.${sys_file_pattern}-%i\">\n"
             + "      <PatternLayout charset=\"UTF-8\">\n"
-            + "        <Pattern>%d{yyyy-MM-dd HH:mm:ss,SSS} %p (%t|%tid) [%C{1}.%M():%L] %m%n</Pattern>\n"
+            + "        <Pattern>%d{yyyy-MM-dd HH:mm:ss,SSS} %p (%t|%tid)<!--REPLACED BY LOG FORMAT-->%m%n</Pattern>\n"
             + "      </PatternLayout>\n"
             + "      <Policies>\n"
             + "        <TimeBasedTriggeringPolicy/>\n"
@@ -64,7 +64,7 @@ public class Log4jConfig extends XmlConfiguration {
             + "    </RollingFile>\n"
             + "    <RollingFile name=\"SysWF\" fileName=\"${sys_log_dir}/fe.warn.log\" filePattern=\"${sys_log_dir}/fe.warn.log.${sys_file_pattern}-%i\">\n"
             + "      <PatternLayout charset=\"UTF-8\">\n"
-            + "        <Pattern>%d{yyyy-MM-dd HH:mm:ss,SSS} %p (%t|%tid) [%C{1}.%M():%L] %m%n</Pattern>\n"
+            + "        <Pattern>%d{yyyy-MM-dd HH:mm:ss,SSS} %p (%t|%tid)<!--REPLACED BY LOG FORMAT-->%m%n</Pattern>\n"
             + "      </PatternLayout>\n"
             + "      <Policies>\n"
             + "        <TimeBasedTriggeringPolicy/>\n"
@@ -94,7 +94,7 @@ public class Log4jConfig extends XmlConfiguration {
             + "    </RollingFile>\n"
             + "  </Appenders>\n"
             + "  <Loggers>\n"
-            + "    <Root level=\"${sys_log_level}\">\n"
+            + "    <Root level=\"${sys_log_level}\" includeLocation=\"${include_location_flag}\" immediateFlush=\"${immediate_flush_flag}\">\n"
             + "      <AppenderRef ref=\"Sys\"/>\n"
             + "      <AppenderRef ref=\"SysWF\" level=\"WARN\"/>\n"
             + "      <!--REPLACED BY Console Logger-->\n"
@@ -109,6 +109,7 @@ public class Log4jConfig extends XmlConfiguration {
 
     private static StrSubstitutor strSub;
     private static String sysLogLevel;
+    private static String sysLogMode;
     private static String[] verboseModules;
     private static String[] auditModules;
     // save the generated xml conf template
@@ -139,6 +140,12 @@ private static void reconfig() throws IOException {
             throw new IOException("sys_log_level config error");
         }
 
+        if (!(sysLogMode.equalsIgnoreCase("NORMAL")
+                || sysLogMode.equalsIgnoreCase("BRIEF")
+                || sysLogMode.equalsIgnoreCase("ASYNC"))) {
+            throw new IOException("sys_log_mode config error");
+        }
+
         String sysLogRollPattern = "%d{yyyyMMdd}";
         String sysRollMaxSize = String.valueOf(Config.log_roll_size_mb);
         if (Config.sys_log_roll_interval.equals("HOUR")) {
@@ -174,6 +181,16 @@ private static void reconfig() throws IOException {
         newXmlConfTemplate = newXmlConfTemplate.replaceAll("<!--REPLACED BY AUDIT AND VERBOSE MODULE NAMES-->",
                 sb.toString());
 
+        if (sysLogMode.equalsIgnoreCase("NORMAL")) {
+            newXmlConfTemplate = newXmlConfTemplate.replaceAll("<!--REPLACED BY LOG FORMAT-->",
+                    " [%C{1}.%M():%L] ");
+        } else {
+            newXmlConfTemplate = newXmlConfTemplate.replaceAll("<!--REPLACED BY LOG FORMAT-->", " ");
+            if (sysLogMode.equalsIgnoreCase("ASYNC")) {
+                newXmlConfTemplate = newXmlConfTemplate.replaceAll("Root", "AsyncRoot");
+            }
+        }
+
         if (foreground) {
             StringBuilder consoleLogger = new StringBuilder();
             consoleLogger.append("<AppenderRef ref=\"Console\"/>\n");
@@ -193,6 +210,8 @@ private static void reconfig() throws IOException {
         properties.put("audit_roll_maxsize", auditRollMaxSize);
         properties.put("audit_roll_num", auditRollNum);
         properties.put("audit_log_delete_age", auditDeleteAge);
+        properties.put("include_location_flag", sysLogMode.equalsIgnoreCase("NORMAL") ? "true" : "false");
+        properties.put("immediate_flush_flag", sysLogMode.equalsIgnoreCase("ASYNC") ? "false" : "true");
 
         strSub = new StrSubstitutor(new Interpolator(properties));
         newXmlConfTemplate = strSub.replace(newXmlConfTemplate);
@@ -216,15 +235,17 @@ public static String getLogXmlConfTemplate() {
         return logXmlConfTemplate;
     }
 
-    public static class Tuple<X, Y, Z> {
+    public static class Tuple<X, Y, Z, U> {
         public final X x;
         public final Y y;
         public final Z z;
+        public final U u;
 
-        public Tuple(X x, Y y, Z z) {
+        public Tuple(X x, Y y, Z z, U u) {
             this.x = x;
             this.y = y;
             this.z = z;
+            this.u = u;
         }
     }
 
@@ -239,20 +260,25 @@ public Log4jConfig(final ConfigurationSource configSource) {
 
     public static synchronized void initLogging(String dorisConfDir) throws IOException {
         sysLogLevel = Config.sys_log_level;
+        sysLogMode = Config.sys_log_mode;
         verboseModules = Config.sys_log_verbose_modules;
         auditModules = Config.audit_log_modules;
         confDir = dorisConfDir;
         customConfDir = Config.custom_config_dir;
         reconfig();
     }
 
-    public static synchronized Tuple<String, String[], String[]> updateLogging(
-            String level, String[] verboseNames, String[] auditNames) throws IOException {
+    public static synchronized Tuple<String, String, String[], String[]> updateLogging(
+            String level, String mode, String[] verboseNames, String[] auditNames) throws IOException {
         boolean toReconfig = false;
         if (level != null) {
             sysLogLevel = level;
             toReconfig = true;
         }
+        if (mode != null) {
+            sysLogMode = mode;
+            toReconfig = true;
+        }
         if (verboseNames != null) {
             verboseModules = verboseNames;
             toReconfig = true;
@@ -264,6 +290,6 @@ public static synchronized Tuple<String, String[], String[]> updateLogging(
         if (toReconfig) {
             reconfig();
         }
-        return new Tuple<>(sysLogLevel, verboseModules, auditModules);
+        return new Tuple<>(sysLogLevel, sysLogMode, verboseModules, auditModules);
     }
 }
diff --git a/fe/fe-core/src/main/java/org/apache/doris/httpv2/controller/LogController.java b/fe/fe-core/src/main/java/org/apache/doris/httpv2/controller/LogController.java
@@ -45,7 +45,7 @@
 public class LogController {
 
     private static final Logger LOG = LogManager.getLogger(LogController.class);
-    private static long WEB_LOG_BYTES = 1024 * 1024;  // 1MB
+    private static final long WEB_LOG_BYTES = 1024 * 1024;  // 1MB
 
     private String addVerboseName;
     private String delVerboseName;
@@ -76,14 +76,15 @@ private void appendLogConf(Map<String, Map<String, String>> content) {
         Map<String, String> map = new HashMap<>();
 
         try {
-            Log4jConfig.Tuple<String, String[], String[]> configs = Log4jConfig.updateLogging(null, null, null);
+            Log4jConfig.Tuple<String, String, String[], String[]> configs =
+                    Log4jConfig.updateLogging(null, null, null, null);
             if (!Strings.isNullOrEmpty(addVerboseName)) {
                 addVerboseName = addVerboseName.trim();
-                List<String> verboseNames = Lists.newArrayList(configs.y);
+                List<String> verboseNames = Lists.newArrayList(configs.z);
                 if (!verboseNames.contains(addVerboseName)) {
                     verboseNames.add(addVerboseName);
-                    configs = Log4jConfig.updateLogging(null, verboseNames.toArray(new String[verboseNames.size()]),
-                            null);
+                    configs = Log4jConfig.updateLogging(null, null,
+                            verboseNames.toArray(new String[verboseNames.size()]), null);
                     readEnvironment.reinitializeLoggingSystem();
                 }
             }
@@ -92,8 +93,8 @@ private void appendLogConf(Map<String, Map<String, String>> content) {
                 List<String> verboseNames = Lists.newArrayList(configs.y);
                 if (verboseNames.contains(delVerboseName)) {
                     verboseNames.remove(delVerboseName);
-                    configs = Log4jConfig.updateLogging(null, verboseNames.toArray(new String[verboseNames.size()]),
-                            null);
+                    configs = Log4jConfig.updateLogging(null, null,
+                            verboseNames.toArray(new String[verboseNames.size()]), null);
                     readEnvironment.reinitializeLoggingSystem();
                 }
             }
@@ -118,7 +119,7 @@ private void appendLogInfo(Map<String, Map<String, String>> content) {
             raf = new RandomAccessFile(logPath, "r");
             long fileSize = raf.length();
             long startPos = fileSize < WEB_LOG_BYTES ? 0L : fileSize - WEB_LOG_BYTES;
-            long webContentLength = fileSize < WEB_LOG_BYTES ? fileSize : WEB_LOG_BYTES;
+            long webContentLength = Math.min(fileSize, WEB_LOG_BYTES);
             raf.seek(startPos);
             map.put("showingLast", webContentLength + " bytes of log");
             StringBuilder sb = new StringBuilder();

diff --git a/fe/pom.xml b/fe/pom.xml
@@ -308,6 +308,7 @@ under the License.
         <vesoft.client.version>3.0.0</vesoft.client.version>
         <!-- paimon -->
         <paimon.version>0.4.0-incubating</paimon.version>
+        <disruptor.version>3.3.4</disruptor.version>
     </properties>
     <profiles>
         <profile>
@@ -711,6 +712,11 @@ under the License.
                 <artifactId>log4j-api</artifactId>
                 <version>${log4j2.version}</version>
             </dependency>
+            <dependency>
+                <groupId>com.lmax</groupId>
+                <artifactId>disruptor</artifactId>
+                <version>${disruptor.version}</version>
+            </dependency>
             <!-- https://mvnrepository.com/artifact/io.dropwizard.metrics/metrics-core -->
             <dependency>
                 <groupId>io.dropwizard.metrics</groupId>