From e12f7a1c0a704a01bde053fb8f447f1d3bb5bbec Mon Sep 17 00:00:00 2001 From: ashishdoneriya Date: Fri, 13 Feb 2015 17:33:57 +0530 Subject: [PATCH] Fixed bug JUM-77 :- Performance degradation of debugger jobs after instrumentation 1.Removed recursive invocation of method while instrumented logging in debugger. 2.Used inmemory loggig using MemoryMappedIO in log4j2.xml 2.Upgraded log4j2 apis to log4j2.1 --- assembly.xml | 8 +- .../common/utils/ConfigurationUtil.java | 2 +- .../org/jumbune/common/utils/Constants.java | 4 +- .../debugger/log/processing/LogAnalyzer.java | 5 +- .../log/processing/LogAnalyzerUtil.java | 6 +- .../jumbune/deploy/SessionEstablisher.java | 4 +- examples/debugger/bankdefaulters/pom.xml | 4 +- examples/debugger/clickstreamanalysis/pom.xml | 4 +- examples/debugger/pom.xml | 4 +- examples/debugger/usregionportouts/pom.xml | 4 +- examples/profiling/movierating/pom.xml | 4 +- examples/profiling/pom.xml | 4 +- examples/wordcount/pom.xml | 4 +- pom.xml | 4 +- remoting/remotingassembly.xml | 4 +- .../jumbune/remoting/server/JumbuneAgent.java | 6 +- .../main/java/org/jumbune/utils/LogUtil.java | 4 +- .../java/org/jumbune/utils/LoggerUtil.java | 93 +++++++++---------- 18 files changed, 81 insertions(+), 87 deletions(-) diff --git a/assembly.xml b/assembly.xml index 143ab8f8..e8dc5890 100644 --- a/assembly.xml +++ b/assembly.xml @@ -45,8 +45,8 @@ ${project.groupId}:jumbune-deploy com.jcraft:jsch:jar:0.1.51 - org.apache.logging.log4j:log4j-api:jar:2.0 - org.apache.logging.log4j:log4j-core:jar:2.0 + org.apache.logging.log4j:log4j-api:jar:2.1 + org.apache.logging.log4j:log4j-core:jar:2.1 @@ -85,8 +85,8 @@ io.netty:netty-common:jar:4.0.20.Final io.netty:netty-codec:jar:4.0.20.Final io.netty:netty-transport:jar:4.0.20.Final - org.apache.logging.log4j:log4j-api:jar:2.0 - org.apache.logging.log4j:log4j-core:jar:2.0 + org.apache.logging.log4j:log4j-api:jar:2.1 + org.apache.logging.log4j:log4j-core:jar:2.1 org.apache.poi:poi:jar:3.8: commons-logging:commons-logging:jar:1.2: commons-configuration:commons-configuration:jar:1.6: diff --git a/common/src/main/java/org/jumbune/common/utils/ConfigurationUtil.java b/common/src/main/java/org/jumbune/common/utils/ConfigurationUtil.java index efa27dd0..cebafb98 100644 --- a/common/src/main/java/org/jumbune/common/utils/ConfigurationUtil.java +++ b/common/src/main/java/org/jumbune/common/utils/ConfigurationUtil.java @@ -381,7 +381,7 @@ public static void updateXmlDocumentOnFile(Document doc, String filePath) throws */ public static ClasspathElement loadJumbuneSuppliedJarList() throws JumbuneException { ClasspathElement classpathElement = new ClasspathElement(); - String[] files = {"AGENT_HOMElib/jumbune-utils-1.4.1-SNAPSHOT.jar","AGENT_HOMElib/log4j-api-2.0.jar","AGENT_HOMElib/log4j-core-2.0.jar"}; + String[] files = {"AGENT_HOMElib/jumbune-utils-1.4.1-SNAPSHOT.jar","AGENT_HOMElib/log4j-api-2.1.jar","AGENT_HOMElib/log4j-core-2.1.jar"}; classpathElement.setFiles(files); classpathElement.setSource(-1); return classpathElement; diff --git a/common/src/main/java/org/jumbune/common/utils/Constants.java b/common/src/main/java/org/jumbune/common/utils/Constants.java index 26056882..ccf4f901 100644 --- a/common/src/main/java/org/jumbune/common/utils/Constants.java +++ b/common/src/main/java/org/jumbune/common/utils/Constants.java @@ -77,10 +77,10 @@ public interface Constants { String JOB_JARS_LOC = "jobJars/"; /** The LO g4 j2_ ap i_ jar. */ - String LOG4J2_API_JAR = "/lib/log4j-api-2.0.jar"; + String LOG4J2_API_JAR = "/lib/log4j-api-2.1.jar"; /** The LO g4 j2_ cor e_ jar. */ - String LOG4J2_CORE_JAR = "/lib/log4j-core-2.0.jar"; + String LOG4J2_CORE_JAR = "/lib/log4j-core-2.1.jar"; /** The echo agent home. */ String ECHO_AGENT_HOME = "echo $AGENT_HOME \n \n"; diff --git a/debugger/src/main/java/org/jumbune/debugger/log/processing/LogAnalyzer.java b/debugger/src/main/java/org/jumbune/debugger/log/processing/LogAnalyzer.java index 52dfc19f..3200b8b5 100644 --- a/debugger/src/main/java/org/jumbune/debugger/log/processing/LogAnalyzer.java +++ b/debugger/src/main/java/org/jumbune/debugger/log/processing/LogAnalyzer.java @@ -112,6 +112,9 @@ public Map analyzeLogs(final String nodeIP, while ((line = bufferedReader.readLine()) != null) { // parses the line and stores the result in lineMap + if(line==null || line.trim().isEmpty()){ + continue; + } parseLine(line,props); if ((LPConstants.NOT_AVAILABLE.equals(currentExpCounter)) @@ -1026,4 +1029,4 @@ private void addJobLevelCounters(AbstractLogAnalysisBean logAnalysisBean, logAnalysisBean.setTotalUnmatchedValues(totalUnmatchedValues); } -} \ No newline at end of file +} diff --git a/debugger/src/main/java/org/jumbune/debugger/log/processing/LogAnalyzerUtil.java b/debugger/src/main/java/org/jumbune/debugger/log/processing/LogAnalyzerUtil.java index 757ee532..d195587a 100644 --- a/debugger/src/main/java/org/jumbune/debugger/log/processing/LogAnalyzerUtil.java +++ b/debugger/src/main/java/org/jumbune/debugger/log/processing/LogAnalyzerUtil.java @@ -318,7 +318,7 @@ else if (LPConstants.JOB_CHAIN.equals(chainResult)) { String line = null; while (true) { line = bufferedReader.readLine(); - if (line == null) { + if (line == null || line.trim().isEmpty()) { break; } ChainingInfoBean chainingInfoBean = new ChainingInfoBean(); @@ -387,7 +387,7 @@ private Map>> makeJobWiseList(Map jars = new ArrayList(2); static { - jars.add("/lib/log4j-api-2.0.jar"); - jars.add("/lib/log4j-core-2.0.jar"); + jars.add("/lib/log4j-api-2.1.jar"); + jars.add("/lib/log4j-core-2.1.jar"); } public SessionEstablisher(Deployer deployer){ this.deployerInstance = deployer; diff --git a/examples/debugger/bankdefaulters/pom.xml b/examples/debugger/bankdefaulters/pom.xml index cbe44801..83580c4b 100644 --- a/examples/debugger/bankdefaulters/pom.xml +++ b/examples/debugger/bankdefaulters/pom.xml @@ -20,7 +20,7 @@ org.apache.logging.log4j log4j-api - 2.0 + 2.1 @@ -32,7 +32,7 @@ org.apache.logging.log4j log4j-core - 2.0 + 2.1 org.mockito diff --git a/examples/debugger/clickstreamanalysis/pom.xml b/examples/debugger/clickstreamanalysis/pom.xml index 04f87161..5933577a 100644 --- a/examples/debugger/clickstreamanalysis/pom.xml +++ b/examples/debugger/clickstreamanalysis/pom.xml @@ -20,7 +20,7 @@ org.apache.logging.log4j log4j-api - 2.0 + 2.1 @@ -32,7 +32,7 @@ org.apache.logging.log4j log4j-core - 2.0 + 2.1 org.mockito diff --git a/examples/debugger/pom.xml b/examples/debugger/pom.xml index b2bba325..e12d4a04 100644 --- a/examples/debugger/pom.xml +++ b/examples/debugger/pom.xml @@ -21,14 +21,14 @@ org.apache.logging.log4j log4j-api - 2.0 + 2.1 org.apache.logging.log4j log4j-core - 2.0 + 2.1 org.mockito diff --git a/examples/debugger/usregionportouts/pom.xml b/examples/debugger/usregionportouts/pom.xml index 1d9fa407..285837dd 100644 --- a/examples/debugger/usregionportouts/pom.xml +++ b/examples/debugger/usregionportouts/pom.xml @@ -20,14 +20,14 @@ org.apache.logging.log4j log4j-api - 2.0 + 2.1 org.apache.logging.log4j log4j-core - 2.0 + 2.1 junit diff --git a/examples/profiling/movierating/pom.xml b/examples/profiling/movierating/pom.xml index d5dae693..c3a0e5de 100644 --- a/examples/profiling/movierating/pom.xml +++ b/examples/profiling/movierating/pom.xml @@ -20,7 +20,7 @@ org.apache.logging.log4j log4j-api - 2.0 + 2.1 org.mockito @@ -30,7 +30,7 @@ org.apache.logging.log4j log4j-core - 2.0 + 2.1 commons-cli diff --git a/examples/profiling/pom.xml b/examples/profiling/pom.xml index dc4bce78..2679a7a6 100644 --- a/examples/profiling/pom.xml +++ b/examples/profiling/pom.xml @@ -21,14 +21,14 @@ org.apache.logging.log4j log4j-api - 2.0 + 2.1 org.apache.logging.log4j log4j-core - 2.0 + 2.1 org.mockito diff --git a/examples/wordcount/pom.xml b/examples/wordcount/pom.xml index 72377f17..d4f90036 100644 --- a/examples/wordcount/pom.xml +++ b/examples/wordcount/pom.xml @@ -20,14 +20,14 @@ org.apache.logging.log4j log4j-api - 2.0 + 2.1 org.apache.logging.log4j log4j-core - 2.0 + 2.1 org.mockito diff --git a/pom.xml b/pom.xml index b764e9aa..1329a2a2 100644 --- a/pom.xml +++ b/pom.xml @@ -248,14 +248,14 @@ org.apache.logging.log4j log4j-api - 2.0 + 2.1 org.apache.logging.log4j log4j-core - 2.0 + 2.1 diff --git a/remoting/remotingassembly.xml b/remoting/remotingassembly.xml index 4557f61c..9dc3593f 100644 --- a/remoting/remotingassembly.xml +++ b/remoting/remotingassembly.xml @@ -14,8 +14,8 @@ false - org.apache.logging.log4j:log4j-api:jar:2.0 - org.apache.logging.log4j:log4j-core:jar:2.0 + org.apache.logging.log4j:log4j-api:jar:2.1 + org.apache.logging.log4j:log4j-core:jar:2.1 io.netty:netty-handler:jar:4.0.20.Final io.netty:netty-buffer:jar:4.0.20.Final io.netty:netty-common:jar:4.0.20.Final diff --git a/remoting/src/main/java/org/jumbune/remoting/server/JumbuneAgent.java b/remoting/src/main/java/org/jumbune/remoting/server/JumbuneAgent.java index 59395984..7ffeb14a 100644 --- a/remoting/src/main/java/org/jumbune/remoting/server/JumbuneAgent.java +++ b/remoting/src/main/java/org/jumbune/remoting/server/JumbuneAgent.java @@ -107,8 +107,8 @@ public final class JumbuneAgent { private JumbuneAgent() { } static { - jars.add("/lib/log4j-api-2.0.jar"); - jars.add("/lib/log4j-core-2.0.jar"); + jars.add("/lib/log4j-api-2.1.jar"); + jars.add("/lib/log4j-core-2.1.jar"); } /** @@ -569,4 +569,4 @@ private static void shutTopCmdOnSlaves(BasicYamlConfig config) { } } -} \ No newline at end of file +} diff --git a/utilities/src/main/java/org/jumbune/utils/LogUtil.java b/utilities/src/main/java/org/jumbune/utils/LogUtil.java index ea77c0b0..118c8d72 100644 --- a/utilities/src/main/java/org/jumbune/utils/LogUtil.java +++ b/utilities/src/main/java/org/jumbune/utils/LogUtil.java @@ -319,12 +319,12 @@ private static void getLogMsg(Object... msgParts) { StringBuilder msg = new StringBuilder(); for (Object msgPart : msgParts) { - msg.append(separateMessage(msgPart)); + msg.append(DEFAULT_MESSAGE_SEPARATOR).append(msgPart); } // add fillers for (int i = MAX_VALUES_IN_LOG - msgParts.length; i > 0; i--) { - msg.append(separateMessage(UtilitiesConstants.EMPTY_STRING)); + msg.append(DEFAULT_MESSAGE_SEPARATOR).append(UtilitiesConstants.EMPTY_STRING); } logMessage(LoggerUtil.getMapReduceLogger(MapReduceExecutionUtil diff --git a/utilities/src/main/java/org/jumbune/utils/LoggerUtil.java b/utilities/src/main/java/org/jumbune/utils/LoggerUtil.java index 3026cb93..5d9e8959 100644 --- a/utilities/src/main/java/org/jumbune/utils/LoggerUtil.java +++ b/utilities/src/main/java/org/jumbune/utils/LoggerUtil.java @@ -17,7 +17,7 @@ import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.core.LoggerContext; -import org.apache.logging.log4j.core.appender.FileAppender; +import org.apache.logging.log4j.core.appender.MemoryMappedFileAppender; import org.apache.logging.log4j.core.config.AppenderRef; import org.apache.logging.log4j.core.config.Configuration; import org.apache.logging.log4j.core.config.LoggerConfig; @@ -72,14 +72,13 @@ public static void loadLogger(String logFileDir, String taskAttemptID) throws IO SAXException, TransformerException { LoggerContext ctx = (LoggerContext) LogManager.getContext(false); Configuration config = ctx.getConfiguration(); - FileAppender fileAppender = createFileAppender(config, LOG_APPENDER_NAME + taskAttemptID, logFileDir, taskAttemptID, 0); - fileAppender.start(); + MemoryMappedFileAppender memoryMappedfileAppender = createMemoryMappedFileAppender(config, LOG_APPENDER_NAME + taskAttemptID, logFileDir, taskAttemptID, 0); + memoryMappedfileAppender.start(); AppenderRef[] ar = new AppenderRef [1]; ar[0] = AppenderRef.createAppenderRef(LOG_APPENDER_NAME + taskAttemptID , Level.INFO, null); LoggerConfig lgf = LoggerConfig.createLogger("false",Level.INFO , LOG_CATEGORY + taskAttemptID , null, ar, null, config, null); config.addLogger(LOG_CATEGORY + taskAttemptID, lgf); - ctx.getLogger(LOG_CATEGORY + taskAttemptID).addAppender(fileAppender); - + ctx.getLogger(LOG_CATEGORY + taskAttemptID).addAppender(memoryMappedfileAppender); ctx.updateLoggers(); ctx.start(); mapReduceLoggers = new ArrayList(1); @@ -130,62 +129,54 @@ public static void loadChainLogger(String logFileDir, String taskAttemptID, int LoggerContext ctx = (LoggerContext) LogManager.getContext(false); Configuration config = ctx.getConfiguration(); for (int k = 0; k < numberOfLoggers; k++) { - FileAppender fileAppender = createFileAppender(config, LOG_APPENDER_NAME+taskAttemptID+k,logFileDir,taskAttemptID,k+1); - fileAppender.start(); - AppenderRef[] ar = new AppenderRef [1]; - ar[0] = AppenderRef.createAppenderRef(LOG_APPENDER_NAME + taskAttemptID + k, Level.INFO, null); - LoggerConfig lgf = LoggerConfig.createLogger("false",Level.INFO , LOG_CATEGORY + taskAttemptID + k, "includeLocation", ar, null, config, null); - config.addLogger(LOG_CATEGORY + taskAttemptID + k, lgf); - ctx.getLogger(LOG_CATEGORY + taskAttemptID + k).addAppender(fileAppender); - LOG.debug("Finished loading logger: " + k); + MemoryMappedFileAppender memoryMappedfileAppender = createMemoryMappedFileAppender(config, LOG_APPENDER_NAME + taskAttemptID+k, logFileDir, taskAttemptID, k+1); + memoryMappedfileAppender.start(); + AppenderRef[] ar = new AppenderRef [1]; + ar[0] = AppenderRef.createAppenderRef(LOG_APPENDER_NAME + taskAttemptID + k, Level.INFO, null); + LoggerConfig lgf = LoggerConfig.createLogger("false",Level.INFO , LOG_CATEGORY + taskAttemptID + k, "includeLocation", ar, null, config, null); + config.addLogger(LOG_CATEGORY + taskAttemptID + k, lgf); + ctx.getLogger(LOG_CATEGORY + taskAttemptID + k).addAppender(memoryMappedfileAppender); + LOG.debug("Finished loading logger: " + k); } + if (numberOfLoggers > 1) { - FileAppender fileAppender = createFileAppender(config, LOG_APPENDER_NAME_CHAIN + taskAttemptID, logFileDir, taskAttemptID, FILENAME_PREFIX_CHAIN_LOGGER); - fileAppender.start(); - AppenderRef[] ar = new AppenderRef [1]; - ar[0] = AppenderRef.createAppenderRef(LOG_APPENDER_NAME_CHAIN + taskAttemptID, Level.INFO, null); - LoggerConfig lgf = LoggerConfig.createLogger("false",Level.INFO , LOG_CATEGORY_CHAIN + taskAttemptID, "includeLocation", ar, null, config, null); - config.addLogger(LOG_CATEGORY_CHAIN + taskAttemptID, lgf); - ctx.getLogger(LOG_CATEGORY_CHAIN + taskAttemptID).addAppender(fileAppender); + MemoryMappedFileAppender memoryMappedfileAppender = createMemoryMappedFileAppender(config, LOG_APPENDER_NAME_CHAIN + taskAttemptID, logFileDir, taskAttemptID, FILENAME_PREFIX_CHAIN_LOGGER); + memoryMappedfileAppender.start(); + AppenderRef[] ar = new AppenderRef [1]; + ar[0] = AppenderRef.createAppenderRef(LOG_APPENDER_NAME_CHAIN + taskAttemptID, Level.INFO, null); + LoggerConfig lgf = LoggerConfig.createLogger("false",Level.INFO , LOG_CATEGORY_CHAIN + taskAttemptID, "includeLocation", ar, null, config, null); + config.addLogger(LOG_CATEGORY_CHAIN + taskAttemptID, lgf); + ctx.getLogger(LOG_CATEGORY_CHAIN + taskAttemptID).addAppender(memoryMappedfileAppender); LOG.debug("Finished loading logger: "); } ctx.updateLoggers(); ctx.start(); - - mapReduceLoggers = new ArrayList(numberOfLoggers); - for (int k = 0; k < numberOfLoggers; k++) { - mapReduceLoggers.add(LogManager.getLogger(LOG_CATEGORY + taskAttemptID + k)); + + mapReduceLoggers = new ArrayList(numberOfLoggers); + for (int k = 0; k < numberOfLoggers; k++) { + mapReduceLoggers.add(LogManager.getLogger(LOG_CATEGORY + taskAttemptID + k)); } + if (numberOfLoggers > 1) { - chainLogger = LogManager.getLogger(LOG_CATEGORY_CHAIN + taskAttemptID); + chainLogger = LogManager.getLogger(LOG_CATEGORY_CHAIN + taskAttemptID); } + } - /** - * Creates a File appender to log4j - * - * @param props - * existing log4j properties - * @param appenderName - * Appender name - * @param logFileDir - * Log file directory - * @param taskAttemptID - * The task attempt id - */ - private static FileAppender createFileAppender(Configuration config, String appenderName, String logFileDir, - String taskAttemptID, Object loggerNumber) { - StringBuilder logFileName = new StringBuilder(YamlUtil.getAndReplaceHolders(logFileDir)); - - if (!(loggerNumber instanceof Integer && (Integer) loggerNumber == 0)) { - logFileName.append(loggerNumber).append("-"); - } - logFileName.append(IPRetriever.getCurrentIP()).append(SEPARATOR_UNDERSCORE).append(taskAttemptID).append(LOG_FILE_EXT); - - // pattern layout - PatternLayout pl = PatternLayout.createLayout(LOG_PATTERN, config, null,Charsets.UTF_8 ,false, false, null, null); - return FileAppender.createAppender(logFileName.toString(), "append", null, appenderName, "true", null, null, null, pl, null, null, null, config); - - } + + + private static MemoryMappedFileAppender createMemoryMappedFileAppender(Configuration config, + String appenderName, String logFileDir, String taskAttemptID, Object loggerNumber) { + StringBuilder logFileName = new StringBuilder(YamlUtil.getAndReplaceHolders(logFileDir)); + + if (!(loggerNumber instanceof Integer && (Integer) loggerNumber == 0)) { + logFileName.append(loggerNumber).append("-"); + } + logFileName.append(IPRetriever.getCurrentIP()).append(SEPARATOR_UNDERSCORE).append(taskAttemptID).append(LOG_FILE_EXT); + // pattern layout + PatternLayout pl = PatternLayout.createLayout(LOG_PATTERN, config, null,Charsets.UTF_8 ,false, false, null, null); + return MemoryMappedFileAppender.createAppender(logFileName.toString(), "append", appenderName, "false", "33554432", null, pl, null, null, null, config); + } + /** * This method gets the chain loggger.