LOG4J2-1297 throughput test improvements (added JUL, separated parameterized message from simple string logging)
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/f226b972 Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/f226b972 Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/f226b972 Branch: refs/heads/master Commit: f226b97225030a4dca658d5f7cd52b50aa21a721 Parents: 66cc0c8 Author: rpopma <[email protected]> Authored: Sun Apr 24 22:58:37 2016 +0900 Committer: Ralph Goers <[email protected]> Committed: Mon Apr 25 21:30:30 2016 -0700 ---------------------------------------------------------------------- .../log4j/perf/jmh/FileAppenderBenchmark.java | 92 +++++----- .../perf/jmh/FileAppenderParamsBenchmark.java | 170 +++++++++++++++++++ 2 files changed, 210 insertions(+), 52 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/f226b972/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/FileAppenderBenchmark.java ---------------------------------------------------------------------- diff --git a/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/FileAppenderBenchmark.java b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/FileAppenderBenchmark.java index 9bea11e..5fbac7e 100644 --- a/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/FileAppenderBenchmark.java +++ b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/FileAppenderBenchmark.java @@ -17,6 +17,11 @@ package org.apache.logging.log4j.perf.jmh; +import java.io.File; +import java.util.concurrent.TimeUnit; +import java.util.logging.FileHandler; +import java.util.logging.Level; + import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; import org.openjdk.jmh.annotations.Benchmark; @@ -29,43 +34,41 @@ import org.openjdk.jmh.annotations.State; import org.openjdk.jmh.annotations.TearDown; import org.slf4j.LoggerFactory; -import java.io.File; -import java.util.concurrent.TimeUnit; - /** - * Benchmarks Log4j 2, Log4j 1, and Logback using the DEBUG level which is enabled for this test. The configuration + * Benchmarks Log4j 2, Log4j 1, Logback and JUL using the DEBUG level which is enabled for this test. The configuration * for each uses a FileAppender */ // HOW TO RUN THIS TEST // java -jar target/benchmarks.jar ".*FileAppenderBenchmark.*" -f 1 -i 5 -wi 5 -bm sample -tu ns @State(Scope.Thread) public class FileAppenderBenchmark { + public static final String MESSAGE = "This is a debug message"; + private FileHandler julFileHandler; + Logger log4j2Logger; Logger log4j2RandomLogger; org.slf4j.Logger slf4jLogger; org.apache.log4j.Logger log4j1Logger; - int j; + java.util.logging.Logger julLogger; @Setup - public void setUp() { + public void setUp() throws Exception { System.setProperty("log4j.configurationFile", "log4j2-perf.xml"); System.setProperty("log4j.configuration", "log4j12-perf.xml"); System.setProperty("logback.configurationFile", "logback-perf.xml"); - File logbackFile = new File("target/testlogback.log"); - logbackFile.delete(); - File log4jFile = new File ("target/testlog4j.log"); - log4jFile.delete(); - File log4j2File = new File ("target/testlog4j2.log"); - log4j2File.delete(); - File log4j2RAF = new File ("target/testRandomlog4j2.log"); - log4j2RAF.delete(); + deleteLogFiles(); log4j2Logger = LogManager.getLogger(FileAppenderBenchmark.class); log4j2RandomLogger = LogManager.getLogger("TestRandom"); slf4jLogger = LoggerFactory.getLogger(FileAppenderBenchmark.class); log4j1Logger = org.apache.log4j.Logger.getLogger(FileAppenderBenchmark.class); - j = 0; + + julFileHandler = new FileHandler("target/testJulLog.log"); + julLogger = java.util.logging.Logger.getLogger(getClass().getName()); + julLogger.setUseParentHandlers(false); + julLogger.addHandler(julFileHandler); + julLogger.setLevel(Level.ALL); } @TearDown @@ -74,6 +77,10 @@ public class FileAppenderBenchmark { System.clearProperty("log4j.configuration"); System.clearProperty("logback.configurationFile"); + deleteLogFiles(); + } + + private void deleteLogFiles() { File logbackFile = new File("target/testlogback.log"); logbackFile.delete(); File log4jFile = new File ("target/testlog4j.log"); @@ -82,63 +89,44 @@ public class FileAppenderBenchmark { log4jRandomFile.delete(); File log4j2File = new File ("target/testlog4j2.log"); log4j2File.delete(); + File julFile = new File("target/testJulLog.log"); + julFile.delete(); } @BenchmarkMode(Mode.Throughput) - @OutputTimeUnit(TimeUnit.MILLISECONDS) - @Benchmark - public boolean baseline() { - ++j; - return true; - } - - @BenchmarkMode(Mode.Throughput) - @OutputTimeUnit(TimeUnit.MILLISECONDS) - @Benchmark - public void log4j2RAFStringConcatenation() { - log4j2RandomLogger.debug("This is a debug [" + ++j + "] message"); - } - - - @BenchmarkMode(Mode.Throughput) - @OutputTimeUnit(TimeUnit.MILLISECONDS) + @OutputTimeUnit(TimeUnit.SECONDS) @Benchmark - public void log4j2StringConcatenation() { - log4j2Logger.debug("This is a debug [" + ++j + "] message"); + public void log4j2RAF() { + log4j2RandomLogger.debug(MESSAGE); } - @BenchmarkMode(Mode.Throughput) - @OutputTimeUnit(TimeUnit.MILLISECONDS) - @Benchmark - public void slf4jStringConcatenation() { - slf4jLogger.debug("This is a debug [" + ++j + "] message"); - } @BenchmarkMode(Mode.Throughput) - @OutputTimeUnit(TimeUnit.MILLISECONDS) + @OutputTimeUnit(TimeUnit.SECONDS) @Benchmark - public void log4j1StringConcatenation() { - log4j1Logger.debug("This is a debug [" + ++j + "] message"); + public void log4j2File() { + log4j2Logger.debug(MESSAGE); } @BenchmarkMode(Mode.Throughput) - @OutputTimeUnit(TimeUnit.MILLISECONDS) + @OutputTimeUnit(TimeUnit.SECONDS) @Benchmark - public void log4j2RAFParameterizedString() { - log4j2RandomLogger.debug("This is a debug [{}] message", ++j); + public void logbackFile() { + slf4jLogger.debug(MESSAGE); } @BenchmarkMode(Mode.Throughput) - @OutputTimeUnit(TimeUnit.MILLISECONDS) + @OutputTimeUnit(TimeUnit.SECONDS) @Benchmark - public void log4j2ParameterizedString() { - log4j2Logger.debug("This is a debug [{}] message", ++j); + public void log4j1File() { + log4j1Logger.debug(MESSAGE); } @BenchmarkMode(Mode.Throughput) - @OutputTimeUnit(TimeUnit.MILLISECONDS) + @OutputTimeUnit(TimeUnit.SECONDS) @Benchmark - public void slf4jParameterizedString() { - slf4jLogger.debug("This is a debug [{}] message", ++j); + public void julFile() { + // must specify sourceClass or JUL will look it up by walking the stack trace! + julLogger.logp(Level.INFO, getClass().getName(), "julFile", MESSAGE); } } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/f226b972/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/FileAppenderParamsBenchmark.java ---------------------------------------------------------------------- diff --git a/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/FileAppenderParamsBenchmark.java b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/FileAppenderParamsBenchmark.java new file mode 100644 index 0000000..6865381 --- /dev/null +++ b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/FileAppenderParamsBenchmark.java @@ -0,0 +1,170 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache license, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the license for the specific language governing permissions and + * limitations under the license. + */ + +package org.apache.logging.log4j.perf.jmh; + +import java.io.File; +import java.util.concurrent.TimeUnit; +import java.util.logging.FileHandler; +import java.util.logging.Level; + +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; +import org.openjdk.jmh.annotations.Benchmark; +import org.openjdk.jmh.annotations.BenchmarkMode; +import org.openjdk.jmh.annotations.Mode; +import org.openjdk.jmh.annotations.OutputTimeUnit; +import org.openjdk.jmh.annotations.Scope; +import org.openjdk.jmh.annotations.Setup; +import org.openjdk.jmh.annotations.State; +import org.openjdk.jmh.annotations.TearDown; +import org.slf4j.LoggerFactory; + +import static org.apache.logging.log4j.util.Unbox.*; + +/** + * Benchmarks Log4j 2, Log4j 1, Logback and JUL using the DEBUG level which is enabled for this test. The configuration + * for each uses a FileAppender + */ +// HOW TO RUN THIS TEST +// java -jar target/benchmarks.jar ".*FileAppenderParamsBenchmark.*" -f 1 -i 5 -wi 5 -bm sample -tu ns +@State(Scope.Thread) +public class FileAppenderParamsBenchmark { + private FileHandler julFileHandler; + Logger log4j2Logger; + Logger log4j2RandomLogger; + org.slf4j.Logger slf4jLogger; + org.apache.log4j.Logger log4j1Logger; + java.util.logging.Logger julLogger; + int j, k, m; + + @Setup + public void setUp() throws Exception { + System.setProperty("log4j.configurationFile", "log4j2-perf.xml"); + System.setProperty("log4j.configuration", "log4j12-perf.xml"); + System.setProperty("logback.configurationFile", "logback-perf.xml"); + + deleteLogFiles(); + + log4j2Logger = LogManager.getLogger(getClass()); + log4j2RandomLogger = LogManager.getLogger("TestRandom"); + slf4jLogger = LoggerFactory.getLogger(getClass()); + log4j1Logger = org.apache.log4j.Logger.getLogger(getClass()); + + julFileHandler = new FileHandler("target/testJulLog.log"); + julLogger = java.util.logging.Logger.getLogger(getClass().getName()); + julLogger.setUseParentHandlers(false); + julLogger.addHandler(julFileHandler); + julLogger.setLevel(Level.ALL); + j = 0; + } + + @TearDown + public void tearDown() { + System.clearProperty("log4j.configurationFile"); + System.clearProperty("log4j.configuration"); + System.clearProperty("logback.configurationFile"); + + deleteLogFiles(); + } + + private void deleteLogFiles() { + File logbackFile = new File("target/testlogback.log"); + logbackFile.delete(); + File log4jFile = new File ("target/testlog4j.log"); + log4jFile.delete(); + File log4jRandomFile = new File ("target/testRandomlog4j2.log"); + log4jRandomFile.delete(); + File log4j2File = new File ("target/testlog4j2.log"); + log4j2File.delete(); + File julFile = new File("target/testJulLog.log"); + julFile.delete(); + } + + @BenchmarkMode(Mode.Throughput) + @OutputTimeUnit(TimeUnit.SECONDS) + @Benchmark + public void param1Log4j1Concat() { + log4j1Logger.debug("This is a debug [" + ++j + "] message"); + } + + @BenchmarkMode(Mode.Throughput) + @OutputTimeUnit(TimeUnit.SECONDS) + @Benchmark + public void param3Log4j1Concat() { + log4j1Logger.debug("Val1=" + ++j + ", val2=" + ++k + ", val3=" + ++m); + } + + @BenchmarkMode(Mode.Throughput) + @OutputTimeUnit(TimeUnit.SECONDS) + @Benchmark + public void param1Log4j2RAF() { + log4j2RandomLogger.debug("This is a debug [{}] message", box(++j)); + } + + @BenchmarkMode(Mode.Throughput) + @OutputTimeUnit(TimeUnit.SECONDS) + @Benchmark + public void param3Log4j2RAF() { + log4j2RandomLogger.debug("Val1={}, val2={}, val3={}", box(++j), box(++k), box(++m)); + } + + @BenchmarkMode(Mode.Throughput) + @OutputTimeUnit(TimeUnit.SECONDS) + @Benchmark + public void param1Log4j2File() { + log4j2Logger.debug("This is a debug [{}] message", box(++j)); + } + + @BenchmarkMode(Mode.Throughput) + @OutputTimeUnit(TimeUnit.SECONDS) + @Benchmark + public void param3Log4j2File() { + log4j2Logger.debug("Val1={}, val2={}, val3={}", box(++j), box(++k), box(++m)); + } + + @BenchmarkMode(Mode.Throughput) + @OutputTimeUnit(TimeUnit.SECONDS) + @Benchmark + public void param1LogbackFile() { + slf4jLogger.debug("This is a debug [{}] message", ++j); + } + + @BenchmarkMode(Mode.Throughput) + @OutputTimeUnit(TimeUnit.SECONDS) + @Benchmark + public void param3LogbackFile() { + slf4jLogger.debug("Val1={}, val2={}, val3={}", (++j), (++k), (++m)); + } + + @BenchmarkMode(Mode.Throughput) + @OutputTimeUnit(TimeUnit.SECONDS) + @Benchmark + public void param1JulFile() { + // must specify sourceClass or JUL will look it up by walking the stack trace! + julLogger.logp(Level.INFO, getClass().getName(), "param1JulFile", "This is a debug [{}] message", ++j); + } + + @BenchmarkMode(Mode.Throughput) + @OutputTimeUnit(TimeUnit.SECONDS) + @Benchmark + public void param3JulFile() { + // must specify sourceClass or JUL will look it up by walking the stack trace! + julLogger.logp(Level.INFO, getClass().getName(), "param3JulFile", "Val1={}, val2={}, val3={}", + new Object[]{++j, ++k, ++m}); + } +}
