You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by rg...@apache.org on 2016/04/26 07:48:38 UTC
[28/38] logging-log4j2 git commit: LOG4J2-1297 throughput test
improvements (added JUL,
separated parameterized message from simple string logging)
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 <rp...@apache.org>
Authored: Sun Apr 24 22:58:37 2016 +0900
Committer: Ralph Goers <rg...@nextiva.com>
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});
+ }
+}