LOG4J2-1271 Add MessageFactory that avoid allocation by reusing a cached ParameterizedMessage instance.
* Added class ReusableParameterizedMessageFactory * AbstractLogger uses this new factory if Constants.ENABLE_THREADLOCALS is true (needed to copy some log4j-core logic to log4j-api here...) * Added interface ReusableMessage * ParameterizedMessage now implements ReusableMessage so downstream components can determine if the Message instance can safely be passed on to another thread or not * AsyncLogger will not call getFormattedMessage on a reused ReusableMessage any more * RingBufferLogEvent will copy the content of a reused ReusableMessage instead of holding a reference to that Message * RingBufferLogEvent.FACTORY will pre-allocate a 128-char StringBuilder on each slot in the ring buffer if Constants.ENABLE_THREADLOCALS is true * DisruptorUtil will use a smaller ring buffer size (8*1024 instead of 256*1024) if Constants.ENABLE_THREADLOCALS is true * MessagePatternConverter now avoids calling toString on the Message if it implements StringBuilderFormattable Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/15d95ecb Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/15d95ecb Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/15d95ecb Branch: refs/heads/LOG4J2-1278-gc-free-logger Commit: 15d95ecba419b14a456e2b1aa69b4d93f92c4489 Parents: 63c3a54 Author: rpopma <[email protected]> Authored: Wed Feb 24 05:36:40 2016 +0900 Committer: rpopma <[email protected]> Committed: Wed Feb 24 05:36:40 2016 +0900 ---------------------------------------------------------------------- .../log4j/message/ParameterizedMessage.java | 23 +++++- .../logging/log4j/message/ReusableMessage.java | 34 +++++++++ .../ReusableParameterizedMessageFactory.java | 66 ++++++++++++++++ .../logging/log4j/spi/AbstractLogger.java | 31 +++++++- .../logging/log4j/core/async/AsyncLogger.java | 8 +- .../logging/log4j/core/async/DisruptorUtil.java | 4 +- .../log4j/core/async/RingBufferLogEvent.java | 80 ++++++++++++++++++-- .../core/pattern/MessagePatternConverter.java | 18 +++++ src/changes/changes.xml | 3 + 9 files changed, 251 insertions(+), 16 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/15d95ecb/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterizedMessage.java ---------------------------------------------------------------------- diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterizedMessage.java b/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterizedMessage.java index d315c13..2e37f73 100644 --- a/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterizedMessage.java +++ b/log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterizedMessage.java @@ -34,7 +34,7 @@ import org.apache.logging.log4j.util.StringBuilderFormattable; * licensed under the LGPL. It has been relicensed here with his permission providing that this attribution remain. * </p> */ -public class ParameterizedMessage implements Message, StringBuilderFormattable { +public class ParameterizedMessage implements ReusableMessage { /** * Prefix for recursion. @@ -75,13 +75,14 @@ public class ParameterizedMessage implements Message, StringBuilderFormattable { private static ThreadLocal<SimpleDateFormat> threadLocalSimpleDateFormat = new ThreadLocal<>(); private static ThreadLocal<Object[]> threadLocalUnrolledArgs = new ThreadLocal<>(); - private final String messagePattern; - private final int argCount; + private String messagePattern; + private int argCount; private StringBuilder formattedMessage; private transient Object[] argArray; private boolean isThrowableInitialized; private transient Throwable throwable; + private boolean reused; /** * Creates a parameterized message. @@ -157,6 +158,22 @@ public class ParameterizedMessage implements Message, StringBuilderFormattable { this.argCount = 2; } + public boolean isReused() { + return reused; + } + + void setReused(boolean reused) { + this.reused = reused; + } + + void set(String messagePattern, Object... arguments) { + this.messagePattern = messagePattern; + this.argArray = arguments; + this.argCount = arguments == null ? 0 : arguments.length; + this.isThrowableInitialized = false; + this.formattedMessage = null; + } + private static Object[] unrolledArgs() { Object[] result = threadLocalUnrolledArgs.get(); if (result == null) { http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/15d95ecb/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableMessage.java ---------------------------------------------------------------------- diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableMessage.java b/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableMessage.java new file mode 100644 index 0000000..46e94f2 --- /dev/null +++ b/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableMessage.java @@ -0,0 +1,34 @@ +/* + * 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.message; + +import org.apache.logging.log4j.util.StringBuilderFormattable; + +/** + * Messages implementing this interface may or may not be reused. + * <p> + * If a Message is reused, downstream components should not hand over this instance to another thread, but extract its + * content (via the {@link StringBuilderFormattable#formatTo(StringBuilder)} method) instead. + * </p> + */ +public interface ReusableMessage extends Message, StringBuilderFormattable { + /** + * Returns {@code true} if this instance is and will be reused + * @return whether this is a reused instance + */ + boolean isReused(); +} http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/15d95ecb/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessageFactory.java ---------------------------------------------------------------------- diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessageFactory.java b/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessageFactory.java new file mode 100644 index 0000000..568f5bc --- /dev/null +++ b/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessageFactory.java @@ -0,0 +1,66 @@ +/* + * 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.message; + +/** + * Enables use of <code>{}</code> parameter markers in message strings. + * <p> + * Reuses a ThreadLocal {@link ParameterizedMessage} instance for {@link #newMessage(String, Object...)}. + * </p> + * <p> + * This class is immutable. + * </p> + */ +public final class ReusableParameterizedMessageFactory extends AbstractMessageFactory { + + /** + * Instance of StringFormatterMessageFactory. + */ + public static final ReusableParameterizedMessageFactory INSTANCE = new ReusableParameterizedMessageFactory(); + + private static final long serialVersionUID = -8970940216592525651L; + private static ThreadLocal<ParameterizedMessage> threadLocalMessage = new ThreadLocal<>(); + + /** + * Constructs a message factory. + */ + public ReusableParameterizedMessageFactory() { + super(); + } + + /** + * Creates {@link ParameterizedMessage} instances. + * + * @param message The message pattern. + * @param params The message parameters. + * @return The Message. + * + * @see MessageFactory#newMessage(String, Object...) + */ + @Override + public Message newMessage(final String message, final Object... params) { + ParameterizedMessage result = threadLocalMessage.get(); + if (result == null) { + result = new ParameterizedMessage(message, params); + result.setReused(true); + threadLocalMessage.set(result); + } else { + result.set(message, params); + } + return result; + } +} http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/15d95ecb/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java ---------------------------------------------------------------------- diff --git a/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java b/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java index f0d1466..6a50c8d 100644 --- a/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java +++ b/log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java @@ -27,6 +27,7 @@ import org.apache.logging.log4j.message.FlowMessageFactory; import org.apache.logging.log4j.message.Message; import org.apache.logging.log4j.message.MessageFactory; import org.apache.logging.log4j.message.ParameterizedMessageFactory; +import org.apache.logging.log4j.message.ReusableParameterizedMessageFactory; import org.apache.logging.log4j.message.StringFormattedMessage; import org.apache.logging.log4j.status.StatusLogger; import org.apache.logging.log4j.util.LambdaUtil; @@ -75,7 +76,8 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { * The default MessageFactory class. */ public static final Class<? extends MessageFactory> DEFAULT_MESSAGE_FACTORY_CLASS = - createClassForProperty("log4j2.messageFactory", ParameterizedMessageFactory.class); + createClassForProperty("log4j2.messageFactory", ReusableParameterizedMessageFactory.class, + ParameterizedMessageFactory.class); /** * The default FlowMessageFactory class. @@ -179,12 +181,33 @@ public abstract class AbstractLogger implements ExtendedLogger, Serializable { } private static Class<? extends MessageFactory> createClassForProperty(final String property, - final Class<ParameterizedMessageFactory> defaultMessageFactoryClass) { + final Class<ReusableParameterizedMessageFactory> reusableParameterizedMessageFactoryClass, + final Class<ParameterizedMessageFactory> parameterizedMessageFactoryClass) { try { - final String clsName = PropertiesUtil.getProperties().getStringProperty(property, defaultMessageFactoryClass.getName()); + final boolean IS_WEB_APP = PropertiesUtil.getProperties().getBooleanProperty( + "log4j2.is.webapp", isClassAvailable("javax.servlet.Servlet")); + final boolean ENABLE_THREADLOCALS = !IS_WEB_APP && PropertiesUtil.getProperties().getBooleanProperty( + "log4j2.enable.threadlocals", true); + final String fallback = ENABLE_THREADLOCALS ? reusableParameterizedMessageFactoryClass.getName() + : parameterizedMessageFactoryClass.getName(); + final String clsName = PropertiesUtil.getProperties().getStringProperty(property, fallback); return LoaderUtil.loadClass(clsName).asSubclass(MessageFactory.class); } catch (final Throwable t) { - return defaultMessageFactoryClass; + return parameterizedMessageFactoryClass; + } + } + + /** + * Determines if a named Class can be loaded or not. + * + * @param className The class name. + * @return {@code true} if the class could be found or {@code false} otherwise. + */ + private static boolean isClassAvailable(final String className) { + try { + return Class.forName(className) != null; + } catch (final Throwable e) { + return false; } } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/15d95ecb/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java index 048f04d..d1c9e06 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java @@ -34,6 +34,7 @@ import org.apache.logging.log4j.core.util.Constants; import org.apache.logging.log4j.core.util.NanoClock; import org.apache.logging.log4j.message.Message; import org.apache.logging.log4j.message.MessageFactory; +import org.apache.logging.log4j.message.ReusableMessage; import org.apache.logging.log4j.message.TimestampMessage; import org.apache.logging.log4j.status.StatusLogger; @@ -158,12 +159,17 @@ public class AsyncLogger extends Logger implements EventTranslatorVararg<RingBuf // Implementation note: this method is tuned for performance. MODIFY WITH CARE! - if (!Constants.FORMAT_MESSAGES_IN_BACKGROUND) { // LOG4J2-898: user may choose + // if the Message instance is reused, there is no point in freezing its message here + if (!isReused(message) && !Constants.FORMAT_MESSAGES_IN_BACKGROUND) { // LOG4J2-898: user may choose message.getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters } logInBackground(fqcn, level, marker, message, thrown); } + private boolean isReused(final Message message) { + return message instanceof ReusableMessage && ((ReusableMessage) message).isReused(); + } + /** * Enqueues the specified log event data for logging in a background thread. * http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/15d95ecb/log4j-core/src/main/java/org/apache/logging/log4j/core/async/DisruptorUtil.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/DisruptorUtil.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/DisruptorUtil.java index a610b95..00311a0 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/DisruptorUtil.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/DisruptorUtil.java @@ -24,6 +24,7 @@ import java.util.concurrent.TimeUnit; import com.lmax.disruptor.*; import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.core.util.Constants; import org.apache.logging.log4j.core.util.Integers; import org.apache.logging.log4j.status.StatusLogger; import org.apache.logging.log4j.util.PropertiesUtil; @@ -35,6 +36,7 @@ final class DisruptorUtil { private static final Logger LOGGER = StatusLogger.getLogger(); private static final int RINGBUFFER_MIN_SIZE = 128; private static final int RINGBUFFER_DEFAULT_SIZE = 256 * 1024; + private static final int RINGBUFFER_NO_GC_DEFAULT_SIZE = 4 * 1024; private DisruptorUtil() { } @@ -69,7 +71,7 @@ final class DisruptorUtil { } static int calculateRingBufferSize(final String propertyName) { - int ringBufferSize = RINGBUFFER_DEFAULT_SIZE; + int ringBufferSize = Constants.ENABLE_THREADLOCALS ? RINGBUFFER_NO_GC_DEFAULT_SIZE : RINGBUFFER_DEFAULT_SIZE; final String userPreferredRBSize = PropertiesUtil.getProperties().getStringProperty(propertyName, String.valueOf(ringBufferSize)); try { http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/15d95ecb/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java index e4b5133..6d12afa 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEvent.java @@ -28,7 +28,9 @@ import org.apache.logging.log4j.core.config.Property; import org.apache.logging.log4j.core.impl.Log4jLogEvent; import org.apache.logging.log4j.core.impl.ThrowableProxy; import org.apache.logging.log4j.core.lookup.StrSubstitutor; +import org.apache.logging.log4j.core.util.Constants; import org.apache.logging.log4j.message.Message; +import org.apache.logging.log4j.message.ReusableMessage; import org.apache.logging.log4j.message.SimpleMessage; import org.apache.logging.log4j.util.Strings; @@ -52,7 +54,57 @@ public class RingBufferLogEvent implements LogEvent { @Override public RingBufferLogEvent newInstance() { - return new RingBufferLogEvent(); + RingBufferLogEvent result = new RingBufferLogEvent(); + if (Constants.ENABLE_THREADLOCALS) { + result.messageText = new StringBuilder(128); + } + return result; + } + } + + private static class StringBuilderWrapperMessage implements ReusableMessage { + static final StringBuilderWrapperMessage INSTANCE = new StringBuilderWrapperMessage(); + private StringBuilder stringBuilder; + + @Override + public boolean isReused() { + return true; + } + + @Override + public String getFormattedMessage() { + return null; + } + + @Override + public String getFormat() { + return null; + } + + @Override + public Object[] getParameters() { + return new Object[0]; + } + + @Override + public Throwable getThrowable() { + return null; + } + + @Override + public void formatTo(final StringBuilder buffer) { + buffer.append(stringBuilder); + + // ensure that excessively long char[] arrays are not kept in memory forever + if (stringBuilder.length() > 512) { + stringBuilder.setLength(512); + stringBuilder.trimToSize(); + } + } + + public Message setFormattedMessage(final StringBuilder messageText) { + this.stringBuilder = messageText; + return this; } } @@ -61,6 +113,7 @@ public class RingBufferLogEvent implements LogEvent { private Marker marker; private String fqcn; private Level level; + private StringBuilder messageText; private Message message; private transient Throwable thrown; private ThrowableProxy thrownProxy; @@ -82,7 +135,16 @@ public class RingBufferLogEvent implements LogEvent { this.marker = aMarker; this.fqcn = theFqcn; this.level = aLevel; - this.message = msg; + if (msg instanceof ReusableMessage && ((ReusableMessage) msg).isReused()) { + if (messageText == null) { + // Should never happen: + // only happens if user logs a custom reused message when Constants.ENABLE_THREADLOCALS is false + messageText = new StringBuilder(128); + } + ((ReusableMessage) msg).formatTo(messageText); + } else { + this.message = msg; + } this.thrown = aThrowable; this.thrownProxy = null; this.contextMap = aMap; @@ -95,7 +157,7 @@ public class RingBufferLogEvent implements LogEvent { /** * Event processor that reads the event from the ringbuffer can call this method. - * + * * @param endOfBatch flag to indicate if this is the last event in a batch from the RingBuffer */ public void execute(final boolean endOfBatch) { @@ -105,7 +167,7 @@ public class RingBufferLogEvent implements LogEvent { /** * Returns {@code true} if this event is the end of a batch, {@code false} otherwise. - * + * * @return {@code true} if this event is the end of a batch, {@code false} otherwise */ @Override @@ -154,7 +216,11 @@ public class RingBufferLogEvent implements LogEvent { @Override public Message getMessage() { if (message == null) { - message = new SimpleMessage(Strings.EMPTY); + if (messageText == null) { + message = new SimpleMessage(Strings.EMPTY); + } else { + message = StringBuilderWrapperMessage.INSTANCE.setFormattedMessage(messageText); + } } return message; } @@ -205,7 +271,7 @@ public class RingBufferLogEvent implements LogEvent { public long getTimeMillis() { return currentTimeMillis; } - + @Override public long getNanoTime() { return nanoTime; @@ -214,7 +280,7 @@ public class RingBufferLogEvent implements LogEvent { /** * Merges the contents of the specified map into the contextMap, after replacing any variables in the property * values with the StrSubstitutor-supplied actual values. - * + * * @param properties configured properties * @param strSubstitutor used to lookup values of variables in properties */ http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/15d95ecb/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/MessagePatternConverter.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/MessagePatternConverter.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/MessagePatternConverter.java index 787a71c..fd389f4 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/MessagePatternConverter.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/MessagePatternConverter.java @@ -21,6 +21,8 @@ import org.apache.logging.log4j.core.config.Configuration; import org.apache.logging.log4j.core.config.plugins.Plugin; import org.apache.logging.log4j.message.Message; import org.apache.logging.log4j.message.MultiformatMessage; +import org.apache.logging.log4j.message.ReusableMessage; +import org.apache.logging.log4j.util.StringBuilderFormattable; /** * Returns the event's rendered message in a StringBuilder. @@ -59,6 +61,22 @@ public final class MessagePatternConverter extends LogEventPatternConverter { @Override public void format(final LogEvent event, final StringBuilder toAppendTo) { final Message msg = event.getMessage(); + if (msg instanceof StringBuilderFormattable) { + int offset = toAppendTo.length(); + ((StringBuilderFormattable) msg).formatTo(toAppendTo); + + // TODO can we optimize this? + if (config != null) { + for (int i = offset; i < toAppendTo.length() - 1; i++) { + if (toAppendTo.charAt(i) == '$' && toAppendTo.charAt(i + 1) == '{') { + final String value = toAppendTo.substring(offset, toAppendTo.length()); + toAppendTo.setLength(offset); + toAppendTo.append(config.getStrSubstitutor().replace(event, value)); + } + } + } + return; + } if (msg != null) { String result; if (msg instanceof MultiformatMessage) { http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/15d95ecb/src/changes/changes.xml ---------------------------------------------------------------------- diff --git a/src/changes/changes.xml b/src/changes/changes.xml index f9ea553..e9b75b5 100644 --- a/src/changes/changes.xml +++ b/src/changes/changes.xml @@ -24,6 +24,9 @@ </properties> <body> <release version="2.6" date="2016-MM-DD" description="GA Release 2.6"> + <action issue="LOG4J2-1271" dev="rpopma" type="add"> + Add MessageFactory that avoid allocation by reusing a cached ParameterizedMessage instance. + </action> <action issue="LOG4J2-1271" dev="rpopma" type="update"> ParameterizedMessage optimizations to avoid or at least postpone allocating temporary objects. </action>
