LOG4J2-1283 Provide ThreadLocal-based gc-free caching mechanism in DatePatternConverter for non-webapps
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/c023a91a Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/c023a91a Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/c023a91a Branch: refs/heads/LOG4J2-1278-gc-free-logger Commit: c023a91a9df9dd8e707d05f04ca7946840cfda1c Parents: d353e3f Author: rpopma <[email protected]> Authored: Tue Feb 23 20:40:58 2016 +0900 Committer: rpopma <[email protected]> Committed: Tue Feb 23 20:40:58 2016 +0900 ---------------------------------------------------------------------- .../core/pattern/DatePatternConverter.java | 80 ++++++++++++++++++-- .../core/pattern/DatePatternConverterTest.java | 27 +++++++ src/changes/changes.xml | 4 + 3 files changed, 105 insertions(+), 6 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/c023a91a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/DatePatternConverter.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/DatePatternConverter.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/DatePatternConverter.java index 8af403b..9fdfcd8 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/DatePatternConverter.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/DatePatternConverter.java @@ -16,6 +16,7 @@ */ package org.apache.logging.log4j.core.pattern; +import java.util.Arrays; import java.util.Date; import java.util.Objects; import java.util.TimeZone; @@ -23,6 +24,7 @@ import java.util.concurrent.atomic.AtomicReference; import org.apache.logging.log4j.core.LogEvent; import org.apache.logging.log4j.core.config.plugins.Plugin; +import org.apache.logging.log4j.core.util.Constants; import org.apache.logging.log4j.core.util.datetime.FastDateFormat; import org.apache.logging.log4j.core.util.datetime.FixedDateFormat; import org.apache.logging.log4j.core.util.datetime.FixedDateFormat.FixedFormat; @@ -35,8 +37,12 @@ import org.apache.logging.log4j.core.util.datetime.FixedDateFormat.FixedFormat; public final class DatePatternConverter extends LogEventPatternConverter implements ArrayPatternConverter { private abstract static class Formatter { + long previousTime; // for ThreadLocal caching mode + abstract String format(long timeMillis); + abstract void formatToBuffer(long timeMillis, StringBuilder destination); + public String toPattern() { return null; } @@ -45,6 +51,9 @@ public final class DatePatternConverter extends LogEventPatternConverter impleme private static final class PatternFormatter extends Formatter { private final FastDateFormat fastDateFormat; + // this field is only used in ThreadLocal caching mode + private final StringBuilder cachedBuffer = new StringBuilder(64); + PatternFormatter(final FastDateFormat fastDateFormat) { this.fastDateFormat = fastDateFormat; } @@ -55,6 +64,15 @@ public final class DatePatternConverter extends LogEventPatternConverter impleme } @Override + void formatToBuffer(final long timeMillis, final StringBuilder destination) { + if (previousTime != timeMillis) { + cachedBuffer.setLength(0); + fastDateFormat.format(timeMillis, cachedBuffer); + } + destination.append(cachedBuffer); + } + + @Override public String toPattern() { return fastDateFormat.toPattern(); } @@ -63,6 +81,10 @@ public final class DatePatternConverter extends LogEventPatternConverter impleme private static final class FixedFormatter extends Formatter { private final FixedDateFormat fixedDateFormat; + // below fields are only used in ThreadLocal caching mode + private char[] cachedBuffer = new char[64]; // max length of formatted date-time in any format < 64 + private int length = 0; + FixedFormatter(final FixedDateFormat fixedDateFormat) { this.fixedDateFormat = fixedDateFormat; } @@ -73,6 +95,14 @@ public final class DatePatternConverter extends LogEventPatternConverter impleme } @Override + void formatToBuffer(final long timeMillis, final StringBuilder destination) { + if (previousTime != timeMillis) { + length = fixedDateFormat.format(timeMillis, cachedBuffer, 0); + } + destination.append(cachedBuffer, 0, length); + } + + @Override public String toPattern() { return fixedDateFormat.getFormat(); } @@ -84,6 +114,11 @@ public final class DatePatternConverter extends LogEventPatternConverter impleme String format(final long timeMillis) { return Long.toString(timeMillis / 1000); } + + @Override + void formatToBuffer(final long timeMillis, final StringBuilder destination) { + destination.append(timeMillis / 1000); // no need for caching + } } private static final class UnixMillisFormatter extends Formatter { @@ -92,6 +127,11 @@ public final class DatePatternConverter extends LogEventPatternConverter impleme String format(final long timeMillis) { return Long.toString(timeMillis); } + + @Override + void formatToBuffer(final long timeMillis, final StringBuilder destination) { + destination.append(timeMillis); // no need for caching + } } private final class CachedTime { @@ -114,6 +154,8 @@ public final class DatePatternConverter extends LogEventPatternConverter impleme */ private static final String UNIX_MILLIS_FORMAT = "UNIX_MILLIS"; + private final String[] options; + private ThreadLocal<Formatter> threadLocalFormatter = new ThreadLocal<>(); private final AtomicReference<CachedTime> cachedTime; private final Formatter formatter; @@ -124,14 +166,18 @@ public final class DatePatternConverter extends LogEventPatternConverter impleme */ private DatePatternConverter(final String[] options) { super("Date", "date"); + this.options = options == null ? null : Arrays.copyOf(options, options.length); + this.formatter = createFormatter(options); + cachedTime = new AtomicReference<>(new CachedTime(System.currentTimeMillis())); + } + private Formatter createFormatter(final String[] options) { final FixedDateFormat fixedDateFormat = FixedDateFormat.createIfSupported(options); if (fixedDateFormat != null) { - formatter = createFormatter(fixedDateFormat); + return createFixedFormatter(fixedDateFormat); } else { - formatter = createFormatter(options); + return createNonFixedFormatter(options); } - cachedTime = new AtomicReference<>(new CachedTime(System.currentTimeMillis())); } /** @@ -144,11 +190,11 @@ public final class DatePatternConverter extends LogEventPatternConverter impleme return new DatePatternConverter(options); } - private static Formatter createFormatter(final FixedDateFormat fixedDateFormat) { + private static Formatter createFixedFormatter(final FixedDateFormat fixedDateFormat) { return new FixedFormatter(fixedDateFormat); } - private static Formatter createFormatter(final String[] options) { + private static Formatter createNonFixedFormatter(final String[] options) { // if we get here, options is a non-null array with at least one element (first of which non-null) Objects.requireNonNull(options); if (options.length == 0) { @@ -179,7 +225,7 @@ public final class DatePatternConverter extends LogEventPatternConverter impleme LOGGER.warn("Could not instantiate FastDateFormat with pattern " + pattern, e); // default to the DEFAULT format - return createFormatter(FixedDateFormat.create(FixedFormat.DEFAULT)); + return createFixedFormatter(FixedDateFormat.create(FixedFormat.DEFAULT)); } } @@ -202,6 +248,28 @@ public final class DatePatternConverter extends LogEventPatternConverter impleme } public void format(final long timestampMillis, final StringBuilder output) { + if (Constants.ENABLE_THREADLOCALS) { + formatWithoutAllocation(timestampMillis, output); + } else { + formatWithoutThreadLocals(timestampMillis, output); + } + } + + private void formatWithoutAllocation(final long timestampMillis, final StringBuilder output) { + final Formatter formatter = getThreadLocalFormatter(); + formatter.formatToBuffer(timestampMillis, output); + } + + private Formatter getThreadLocalFormatter() { + Formatter result = threadLocalFormatter.get(); + if (result == null) { + result = createFormatter(options); + threadLocalFormatter.set(result); + } + return result; + } + + private void formatWithoutThreadLocals(final long timestampMillis, final StringBuilder output) { CachedTime cached = cachedTime.get(); if (timestampMillis != cached.timestampMillis) { final CachedTime newTime = new CachedTime(timestampMillis); http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/c023a91a/log4j-core/src/test/java/org/apache/logging/log4j/core/pattern/DatePatternConverterTest.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/test/java/org/apache/logging/log4j/core/pattern/DatePatternConverterTest.java b/log4j-core/src/test/java/org/apache/logging/log4j/core/pattern/DatePatternConverterTest.java index 5bd40df..2b572b1 100644 --- a/log4j-core/src/test/java/org/apache/logging/log4j/core/pattern/DatePatternConverterTest.java +++ b/log4j-core/src/test/java/org/apache/logging/log4j/core/pattern/DatePatternConverterTest.java @@ -16,18 +16,26 @@ */ package org.apache.logging.log4j.core.pattern; +import java.lang.reflect.Field; +import java.lang.reflect.Modifier; import java.text.SimpleDateFormat; +import java.util.Arrays; import java.util.Calendar; +import java.util.Collection; import java.util.Date; import java.util.TimeZone; import org.apache.logging.log4j.core.AbstractLogEvent; import org.apache.logging.log4j.core.LogEvent; +import org.apache.logging.log4j.core.util.Constants; import org.apache.logging.log4j.core.util.datetime.FixedDateFormat; import org.junit.Test; +import org.junit.runner.RunWith; +import org.junit.runners.Parameterized; import static org.junit.Assert.*; +@RunWith(Parameterized.class) public class DatePatternConverterTest { /** @@ -42,6 +50,25 @@ public class DatePatternConverterTest { private static final String[] ISO8601_FORMAT_OPTIONS = {ISO8601_FORMAT}; + @Parameterized.Parameters + public static Collection<Object[]> data() { + return Arrays.asList(new Object[][]{{Boolean.TRUE}, {Boolean.FALSE}}); + } + + public DatePatternConverterTest(Boolean threadLocalEnabled) throws Exception { + // Setting the system property does not work: the Constant field has already been initialized... + //System.setProperty("log4j2.enable.threadlocals", threadLocalEnabled.toString()); + + final Field field = Constants.class.getDeclaredField("ENABLE_THREADLOCALS"); + field.setAccessible(true); // make non-private + + final Field modifiersField = Field.class.getDeclaredField("modifiers"); + modifiersField.setAccessible(true); + modifiersField.setInt(field, field.getModifiers() & ~Modifier.FINAL); // make non-final + + field.setBoolean(null, threadLocalEnabled.booleanValue()); + } + @Test public void testNewInstanceAllowsNullParameter() { DatePatternConverter.newInstance(null); // no errors http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/c023a91a/src/changes/changes.xml ---------------------------------------------------------------------- diff --git a/src/changes/changes.xml b/src/changes/changes.xml index a50600c..d70d8a3 100644 --- a/src/changes/changes.xml +++ b/src/changes/changes.xml @@ -24,8 +24,12 @@ </properties> <body> <release version="2.6" date="2016-MM-DD" description="GA Release 2.6"> + <action issue="LOG4J2-1283" dev="rpopma" type="update"> + Provide ThreadLocal-based gc-free caching mechanism in DatePatternConverter for non-webapps. + </action> <action issue="LOG4J2-1293" dev="rpopma" type="add"> Add interface StringBuilderFormattable to enable converting Messages and parameters to text without allocating temporary objects. + ParameterizedMessage, ObjectMessage, SimpleMessage and ThreadDumpMessage now implement StringBuilderFormattable. </action> <action issue="LOG4J2-1291" dev="rpopma" type="update"> Update PatternLayout to utilize gc-free mechanism for LogEvent processing.
