From bcf103e9936975948f66886b5ffa30af377240fd Mon Sep 17 00:00:00 2001 From: caiconghui <55968745+caiconghui@users.noreply.github.com> Date: Wed, 14 Jun 2023 15:16:04 +0800 Subject: [PATCH] [enhancement](log4j) support high performance mode for log4j to escape potential bottleneck for doris read and write (#20759) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- conf/fe.conf | 3 ++ .../java/org/apache/doris/common/Config.java | 15 +++++-- .../main/java/org/apache/doris/DorisFE.java | 1 + .../org/apache/doris/common/Log4jConfig.java | 44 +++++++++++++++---- .../httpv2/controller/LogController.java | 17 +++---- fe/pom.xml | 6 +++ 6 files changed, 66 insertions(+), 20 deletions(-) diff --git a/conf/fe.conf b/conf/fe.conf index e5a097d974..b654b1613d 100644 --- 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 index 4c2d309b9f..dc0839d300 100644 --- 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 index 3a83a25e39..7d87091120 100755 --- 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 class DorisFE { } 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 index 7bf38fd786..7163a58418 100644 --- 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 { + " \n" + " " + " \n" - + " %d{yyyy-MM-dd HH:mm:ss,SSS} %p (%t|%tid) [%C{1}.%M():%L] %m%n\n" + + " %d{yyyy-MM-dd HH:mm:ss,SSS} %p (%t|%tid)%m%n\n" + " \n" + " " + " \n" + " \n" - + " %d{yyyy-MM-dd HH:mm:ss,SSS} %p (%t|%tid) [%C{1}.%M():%L] %m%n\n" + + " %d{yyyy-MM-dd HH:mm:ss,SSS} %p (%t|%tid)%m%n\n" + " \n" + " \n" + " \n" @@ -64,7 +64,7 @@ public class Log4jConfig extends XmlConfiguration { + " \n" + " \n" + " \n" - + " %d{yyyy-MM-dd HH:mm:ss,SSS} %p (%t|%tid) [%C{1}.%M():%L] %m%n\n" + + " %d{yyyy-MM-dd HH:mm:ss,SSS} %p (%t|%tid)%m%n\n" + " \n" + " \n" + " \n" @@ -94,7 +94,7 @@ public class Log4jConfig extends XmlConfiguration { + " \n" + " \n" + " \n" - + " \n" + + " \n" + " \n" + " \n" + " \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 @@ public class Log4jConfig extends XmlConfiguration { 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 @@ public class Log4jConfig extends XmlConfiguration { newXmlConfTemplate = newXmlConfTemplate.replaceAll("", sb.toString()); + if (sysLogMode.equalsIgnoreCase("NORMAL")) { + newXmlConfTemplate = newXmlConfTemplate.replaceAll("", + " [%C{1}.%M():%L] "); + } else { + newXmlConfTemplate = newXmlConfTemplate.replaceAll("", " "); + if (sysLogMode.equalsIgnoreCase("ASYNC")) { + newXmlConfTemplate = newXmlConfTemplate.replaceAll("Root", "AsyncRoot"); + } + } + if (foreground) { StringBuilder consoleLogger = new StringBuilder(); consoleLogger.append("\n"); @@ -193,6 +210,8 @@ public class Log4jConfig extends XmlConfiguration { 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 class Log4jConfig extends XmlConfiguration { return logXmlConfTemplate; } - public static class Tuple { + public static class Tuple { 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,6 +260,7 @@ public class Log4jConfig extends XmlConfiguration { 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; @@ -246,13 +268,17 @@ public class Log4jConfig extends XmlConfiguration { reconfig(); } - public static synchronized Tuple updateLogging( - String level, String[] verboseNames, String[] auditNames) throws IOException { + public static synchronized Tuple 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 class Log4jConfig extends XmlConfiguration { 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 index 9c3f114fb8..dc7878b757 100644 --- 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 @@ import javax.servlet.http.HttpServletRequest; 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 @@ public class LogController { Map map = new HashMap<>(); try { - Log4jConfig.Tuple configs = Log4jConfig.updateLogging(null, null, null); + Log4jConfig.Tuple configs = + Log4jConfig.updateLogging(null, null, null, null); if (!Strings.isNullOrEmpty(addVerboseName)) { addVerboseName = addVerboseName.trim(); - List verboseNames = Lists.newArrayList(configs.y); + List 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 @@ public class LogController { List 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 @@ public class LogController { 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 index 4d7b077ab8..b479dc3d57 100644 --- a/fe/pom.xml +++ b/fe/pom.xml @@ -308,6 +308,7 @@ under the License. 3.0.0 0.4.0-incubating + 3.3.4 @@ -711,6 +712,11 @@ under the License. log4j-api ${log4j2.version} + + com.lmax + disruptor + ${disruptor.version} + io.dropwizard.metrics