You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@logging.apache.org by rp...@apache.org on 2016/03/04 15:23:27 UTC
[49/50] [abbrv] logging-log4j2 git commit: LOG4J2-1274 fixed
performance bug in TextEncoderHelper.copy(), added TextEncoderHelperBenchmark
LOG4J2-1274 fixed performance bug in TextEncoderHelper.copy(), added TextEncoderHelperBenchmark
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/963f9654
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/963f9654
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/963f9654
Branch: refs/heads/LOG4J2-1278-gc-free-logger
Commit: 963f9654ecf6edd0476a9968d2336729359dc21d
Parents: 463c9ea
Author: rpopma <rp...@apache.org>
Authored: Fri Mar 4 23:10:56 2016 +0900
Committer: rpopma <rp...@apache.org>
Committed: Fri Mar 4 23:10:56 2016 +0900
----------------------------------------------------------------------
.../log4j/core/layout/TextEncoderHelper.java | 19 +-
.../perf/jmh/TextEncoderHelperBenchmark.java | 243 +++++++++++++++++++
2 files changed, 256 insertions(+), 6 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/963f9654/log4j-core/src/main/java/org/apache/logging/log4j/core/layout/TextEncoderHelper.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/layout/TextEncoderHelper.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/layout/TextEncoderHelper.java
index c8533d7..0da19b5 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/layout/TextEncoderHelper.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/layout/TextEncoderHelper.java
@@ -48,7 +48,7 @@ public class TextEncoderHelper {
this.cachedCharBuffer = CharBuffer.wrap(new char[bufferSize]);
}
- public void encodeText(final CharSequence text, final ByteBufferDestination destination) {
+ public void encodeText(final StringBuilder text, final ByteBufferDestination destination) {
charsetEncoder.reset();
ByteBuffer byteBuf = destination.getByteBuffer();
final CharBuffer charBuf = getCachedCharBuffer();
@@ -67,6 +67,12 @@ public class TextEncoderHelper {
} while (!endOfInput);
}
+ public void encodeText(final CharBuffer charBuf, final ByteBufferDestination destination) {
+ charsetEncoder.reset();
+ final ByteBuffer byteBuf = destination.getByteBuffer();
+ encode(charBuf, true, destination, byteBuf);
+ }
+
private ByteBuffer encode(final CharBuffer charBuf, final boolean endOfInput,
final ByteBufferDestination destination, ByteBuffer byteBuf) {
try {
@@ -116,17 +122,18 @@ public class TextEncoderHelper {
}
/**
- * Copies characters from the CharSequence into the CharBuffer,
+ * Copies characters from the StringBuilder into the CharBuffer,
* starting at the specified offset and ending when either all
* characters have been copied or when the CharBuffer is full.
*
* @return the number of characters that were copied
*/
- static int copy(final CharSequence source, final int offset, final CharBuffer destination) {
+ static int copy(final StringBuilder source, final int offset, final CharBuffer destination) {
final int length = Math.min(source.length() - offset, destination.remaining());
- for (int i = offset; i < offset + length; i++) {
- destination.put(source.charAt(i));
- }
+ final char[] array = destination.array();
+ final int start = destination.position();
+ source.getChars(offset, offset + length, array, start);
+ destination.position(start + length);
return length;
}
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/963f9654/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/TextEncoderHelperBenchmark.java
----------------------------------------------------------------------
diff --git a/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/TextEncoderHelperBenchmark.java b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/TextEncoderHelperBenchmark.java
new file mode 100644
index 0000000..bab01ff
--- /dev/null
+++ b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/TextEncoderHelperBenchmark.java
@@ -0,0 +1,243 @@
+/*
+ * 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.nio.ByteBuffer;
+import java.nio.CharBuffer;
+import java.nio.charset.Charset;
+import java.util.Map;
+import java.util.concurrent.TimeUnit;
+
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.Marker;
+import org.apache.logging.log4j.ThreadContext.ContextStack;
+import org.apache.logging.log4j.core.LogEvent;
+import org.apache.logging.log4j.core.impl.Log4jLogEvent;
+import org.apache.logging.log4j.core.layout.ByteBufferDestination;
+import org.apache.logging.log4j.core.layout.PatternLayout;
+import org.apache.logging.log4j.core.layout.TextEncoderHelper;
+import org.apache.logging.log4j.message.Message;
+import org.apache.logging.log4j.message.SimpleMessage;
+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.State;
+
+/**
+ * Tests Log4j2 TextEncoderHelper performance.
+ */
+// ============================== HOW TO RUN THIS TEST: ====================================
+//
+// single thread:
+// java -Dfile.encoding=ISO-8859-1 -Dlog4j2.is.webapp=false -Dlog4j2.enable.threadlocals=true -jar log4j-perf/target/benchmarks.jar ".*TextEncoderHelper.*" -f 1 -wi 5 -i 10
+// java -Dfile.encoding=UTF8 -Dlog4j2.is.webapp=false -Dlog4j2.enable.threadlocals=true -jar log4j-perf/target/benchmarks.jar ".*TextEncoderHelper.*" -f 1 -wi 5 -i 10
+//
+// Usage help:
+// java -jar log4j-perf/target/benchmarks.jar -help
+//
+@State(Scope.Thread)
+public class TextEncoderHelperBenchmark {
+
+ final static String STR = "AB!(%087936DZYXQWEIOP$#^~-=/><nb"; // length=32
+ final static String STR_TEXT = "20:01:59.9876 INFO [org.apache.logging.log4j.perf.jmh.TextEncoderHelperBenchmark] AB!(%087936DZYXQWEIOP$#^~-=/><nb"; // length=32
+ final static StringBuilder BUFF_TEXT = new StringBuilder(STR_TEXT);
+ final static CharBuffer CHAR_BUFFER = CharBuffer.wrap(STR.toCharArray());
+
+ final static LogEvent EVENT = createLogEvent();
+ private static final Charset CHARSET_DEFAULT = Charset.defaultCharset();
+ private final PatternLayout PATTERN_M_C_D = PatternLayout.createLayout("%d %c %m%n", null, null, null, CHARSET_DEFAULT, false, true, null, null);
+ private final Destination destination = new Destination();
+
+ class Destination implements ByteBufferDestination {
+ long count = 0;
+ ByteBuffer buffer = ByteBuffer.wrap(new byte[256*1024]);
+
+ @Override
+ public ByteBuffer getByteBuffer() {
+ return buffer;
+ }
+
+ @Override
+ public ByteBuffer drain(ByteBuffer buf) {
+ buf.flip();
+ count += buf.limit();
+ buf.clear();
+ return buf;
+ }
+ }
+
+ private static LogEvent createLogEvent() {
+ final Marker marker = null;
+ final String fqcn = "com.mycom.myproject.mypackage.MyClass";
+ final Level level = Level.DEBUG;
+ final Message message = new SimpleMessage(STR);
+ final Throwable t = null;
+ final Map<String, String> mdc = null;
+ final ContextStack ndc = null;
+ final String threadName = null;
+ final StackTraceElement location = null;
+ final long timestamp = 12345678;
+
+ return Log4jLogEvent.newBuilder() //
+ .setLoggerName("name(ignored)") //
+ .setMarker(marker) //
+ .setLoggerFqcn(fqcn) //
+ .setLevel(level) //
+ .setMessage(message) //
+ .setThrown(t) //
+ .setContextMap(mdc) //
+ .setContextStack(ndc) //
+ .setThreadName(threadName) //
+ .setSource(location) //
+ .setTimeMillis(timestamp) //
+ .build();
+ }
+
+ @Benchmark
+ @BenchmarkMode(Mode.SampleTime)
+ @OutputTimeUnit(TimeUnit.NANOSECONDS)
+ public byte[] stringGetBytes() {
+ return STR_TEXT.getBytes();
+ }
+
+ private static final ThreadLocal<TextEncoderHelper> textEncoderHelper = new ThreadLocal<>();
+ private TextEncoderHelper getCachedTextEncoderHelper() {
+ TextEncoderHelper result = textEncoderHelper.get();
+ if (result == null) {
+ result = new TextEncoderHelper(CHARSET_DEFAULT);
+ textEncoderHelper.set(result);
+ }
+ return result;
+ }
+
+ @Benchmark
+ @BenchmarkMode(Mode.SampleTime)
+ @OutputTimeUnit(TimeUnit.NANOSECONDS)
+ public long textEncoderEncode() {
+ final TextEncoderHelper helper = getCachedTextEncoderHelper();
+ helper.encodeText(BUFF_TEXT, destination);
+
+ return destination.count;
+ }
+
+ @Benchmark
+ @BenchmarkMode(Mode.SampleTime)
+ @OutputTimeUnit(TimeUnit.NANOSECONDS)
+ public long charBufferEncode() {
+ final TextEncoderHelper helper = getCachedTextEncoderHelper();
+ CHAR_BUFFER.limit(CHAR_BUFFER.capacity());
+ CHAR_BUFFER.position(0);
+ helper.encodeText(CHAR_BUFFER, destination);
+
+ return destination.count;
+ }
+
+ @Benchmark
+ @BenchmarkMode(Mode.SampleTime)
+ @OutputTimeUnit(TimeUnit.NANOSECONDS)
+ public long charBufferCopyAndEncode() {
+ final TextEncoderHelper helper = getCachedTextEncoderHelper();
+ CHAR_BUFFER.clear();
+ CHAR_BUFFER.put(STR);
+ CHAR_BUFFER.flip();
+ helper.encodeText(CHAR_BUFFER, destination);
+
+ return destination.count;
+ }
+
+ @Benchmark
+ @BenchmarkMode(Mode.SampleTime)
+ @OutputTimeUnit(TimeUnit.NANOSECONDS)
+ public long textHelperCopyAndEncode() {
+ final TextEncoderHelper helper = getCachedTextEncoderHelper();
+ CHAR_BUFFER.clear();
+ copy(BUFF_TEXT, 0, CHAR_BUFFER);
+ CHAR_BUFFER.flip();
+ helper.encodeText(CHAR_BUFFER, destination);
+
+ return destination.count;
+ }
+
+ /**
+ * Copies characters from the CharSequence into the CharBuffer,
+ * starting at the specified offset and ending when either all
+ * characters have been copied or when the CharBuffer is full.
+ *
+ * @return the number of characters that were copied
+ */
+ private static int copy(final StringBuilder source, final int offset, final CharBuffer destination) {
+ final int length = Math.min(source.length() - offset, destination.remaining());
+ final char[] array = destination.array();
+ final int start = destination.position();
+ source.getChars(offset, offset+length, array, start);
+ destination.position(start + length);
+ return length;
+ }
+
+ @Benchmark
+ @BenchmarkMode(Mode.SampleTime)
+ @OutputTimeUnit(TimeUnit.NANOSECONDS)
+ public long byteArrayMCD() {
+ byte[] data = PATTERN_M_C_D.toByteArray(EVENT);
+ ByteBuffer buff = destination.getByteBuffer();
+ if (buff.remaining() < data.length) {
+ buff = destination.drain(buff);
+ }
+ buff.put(data);
+ return destination.count;
+ }
+
+ @Benchmark
+ @BenchmarkMode(Mode.SampleTime)
+ @OutputTimeUnit(TimeUnit.NANOSECONDS)
+ public long serializableMCD() {
+ String str = PATTERN_M_C_D.toSerializable(EVENT);
+ byte[] data = str.getBytes(CHARSET_DEFAULT);
+ ByteBuffer buff = destination.getByteBuffer();
+ if (buff.remaining() < data.length) {
+ buff = destination.drain(buff);
+ }
+ buff.put(data);
+ return destination.count;
+ }
+
+// @Benchmark
+// @BenchmarkMode(Mode.SampleTime)
+// @OutputTimeUnit(TimeUnit.NANOSECONDS)
+// public StringBuilder toTextMCD() {
+// StringBuilder str = PATTERN_M_C_D.toText(EVENT);
+// return str;
+// }
+
+ @Benchmark
+ @BenchmarkMode(Mode.SampleTime)
+ @OutputTimeUnit(TimeUnit.NANOSECONDS)
+ public String toStringMCD() {
+ String str = PATTERN_M_C_D.toSerializable(EVENT);
+ return str;
+ }
+
+ @Benchmark
+ @BenchmarkMode(Mode.SampleTime)
+ @OutputTimeUnit(TimeUnit.NANOSECONDS)
+ public long encodeMCD() {
+ PATTERN_M_C_D.encode(EVENT, destination);
+ return destination.count;
+ }
+}