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/01/13 16:00:42 UTC
[1/2] logging-log4j2 git commit: LOG4J2-1221 Added async logger
Timeout wait strategy and made this the default. Prevents deadlock that may
occur on Solaris.
Repository: logging-log4j2
Updated Branches:
refs/heads/master 9be7f31d9 -> d0b97aa94
LOG4J2-1221 Added async logger Timeout wait strategy and made this the default. Prevents deadlock that may occur on Solaris.
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/f9a4b707
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/f9a4b707
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/f9a4b707
Branch: refs/heads/master
Commit: f9a4b7078b04e6bfadc26ccc31ed05ae0c0acb12
Parents: 9be7f31
Author: rpopma <rp...@apache.org>
Authored: Wed Jan 13 23:58:49 2016 +0900
Committer: rpopma <rp...@apache.org>
Committed: Wed Jan 13 23:58:49 2016 +0900
----------------------------------------------------------------------
.../logging/log4j/core/async/DisruptorUtil.java | 27 +++++++++++++-------
src/changes/changes.xml | 4 +++
src/site/xdoc/manual/async.xml | 16 +++++++++---
3 files changed, 34 insertions(+), 13 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/f9a4b707/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 917710f..a610b95 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
@@ -20,18 +20,14 @@ package org.apache.logging.log4j.core.async;
import java.util.concurrent.Callable;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Future;
+import java.util.concurrent.TimeUnit;
+import com.lmax.disruptor.*;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.util.Integers;
import org.apache.logging.log4j.status.StatusLogger;
import org.apache.logging.log4j.util.PropertiesUtil;
-import com.lmax.disruptor.BlockingWaitStrategy;
-import com.lmax.disruptor.ExceptionHandler;
-import com.lmax.disruptor.SleepingWaitStrategy;
-import com.lmax.disruptor.WaitStrategy;
-import com.lmax.disruptor.YieldingWaitStrategy;
-
/**
* Utility methods for getting Disruptor related configuration.
*/
@@ -43,7 +39,19 @@ final class DisruptorUtil {
private DisruptorUtil() {
}
+ static long getTimeout(final String propertyName, final long defaultTimeout) {
+ return PropertiesUtil.getProperties().getLongProperty(propertyName, defaultTimeout);
+ }
+
static WaitStrategy createWaitStrategy(final String propertyName) {
+ final String key = propertyName.startsWith("AsyncLogger.")
+ ? "AsyncLogger.Timeout"
+ : "AsyncLoggerConfig.Timeout";
+ final long timeout = DisruptorUtil.getTimeout(key, 10L);
+ return createWaitStrategy(propertyName, timeout);
+ }
+
+ static WaitStrategy createWaitStrategy(final String propertyName, final long timeoutMs) {
final String strategy = PropertiesUtil.getProperties().getStringProperty(propertyName);
if (strategy != null) {
LOGGER.trace("property {}={}", propertyName, strategy);
@@ -53,9 +61,11 @@ final class DisruptorUtil {
return new YieldingWaitStrategy();
} else if ("Block".equalsIgnoreCase(strategy)) {
return new BlockingWaitStrategy();
+ } else if ("Timeout".equalsIgnoreCase(strategy)) {
+ return new TimeoutBlockingWaitStrategy(timeoutMs, TimeUnit.MILLISECONDS);
}
}
- return new BlockingWaitStrategy();
+ return new TimeoutBlockingWaitStrategy(timeoutMs, TimeUnit.MILLISECONDS);
}
static int calculateRingBufferSize(final String propertyName) {
@@ -95,7 +105,7 @@ final class DisruptorUtil {
/**
* Returns the thread ID of the background appender thread. This allows us to detect Logger.log() calls initiated
* from the appender thread, which may cause deadlock when the RingBuffer is full. (LOG4J2-471)
- *
+ *
* @param executor runs the appender thread
* @return the thread ID of the background appender thread
*/
@@ -114,5 +124,4 @@ final class DisruptorUtil {
throw new IllegalStateException(msg, ex);
}
}
-
}
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/f9a4b707/src/changes/changes.xml
----------------------------------------------------------------------
diff --git a/src/changes/changes.xml b/src/changes/changes.xml
index bf4d0d9..3bf73f7 100644
--- a/src/changes/changes.xml
+++ b/src/changes/changes.xml
@@ -24,6 +24,10 @@
</properties>
<body>
<release version="2.5.1" date="201Y-MM-DD" description="GA Release 2.5.1">
+ <action issue="LOG4J2-1221" dev="rpopma" type="add" due-to="Michael Barker">
+ Added async logger Timeout wait strategy and made this the default wait strategy for async loggers.
+ This prevents a rare deadlock that may occur on Solaris.
+ </action>
<action issue="LOG4J2-1080" dev="rpopma" type="add">
Added option to discard events below a certain log level if the async logger ring buffer
or async appender queue remaining capacity falls below a certain ratio.
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/f9a4b707/src/site/xdoc/manual/async.xml
----------------------------------------------------------------------
diff --git a/src/site/xdoc/manual/async.xml b/src/site/xdoc/manual/async.xml
index 0f6a754..911c27a 100644
--- a/src/site/xdoc/manual/async.xml
+++ b/src/site/xdoc/manual/async.xml
@@ -207,15 +207,19 @@
<tr>
<td>AsyncLogger.WaitStrategy</td>
<td>
- <tt>Block</tt>
+ <tt>Timeout</tt>
</td>
<td>
- Valid values: Block, Sleep, Yield.
+ Valid values: Block, Timeout, Sleep, Yield.
<br />
<tt>Block</tt> is a strategy that uses a lock and condition variable for the I/O thread waiting for log events.
Block can be used when throughput and low-latency are not as important as CPU resource.
Recommended for resource constrained/virtualised environments.
<br />
+ <tt>Timeout</tt> is a variation of the <tt>Block</tt> strategy that will periodically
+ wake up from the lock condition await() call. This ensures that if a notification is missed somehow
+ the consumer thread is not stuck but will recover with a small latency delay (default 10ms).
+ <br />
<tt>Sleep</tt> is a strategy that initially spins, then uses a Thread.yield(), and
eventually parks for the minimum number of nanos the OS and JVM will allow
while the I/O thread is waiting for log events. Sleep is a good compromise between performance
@@ -364,15 +368,19 @@
<tr>
<td>AsyncLoggerConfig.WaitStrategy</td>
<td>
- <tt>Block</tt>
+ <tt>Timeout</tt>
</td>
<td>
- Valid values: Block, Sleep, Yield.
+ Valid values: Block, Timeout, Sleep, Yield.
<br />
<tt>Block</tt> is a strategy that uses a lock and condition variable for the I/O thread waiting for log events.
Block can be used when throughput and low-latency are not as important as CPU resource.
Recommended for resource constrained/virtualised environments.
<br />
+ <tt>Timeout</tt> is a variation of the <tt>Block</tt> strategy that will periodically
+ wake up from the lock condition await() call. This ensures that if a notification is missed somehow
+ the consumer thread is not stuck but will recover with a small latency delay (default 10ms).
+ <br />
<tt>Sleep</tt> is a strategy that initially spins, then uses a Thread.yield(), and
eventually parks for the minimum number of nanos the OS and JVM will allow
while the I/O thread is waiting for log events. Sleep is a good compromise between performance
[2/2] logging-log4j2 git commit: refactored large method into smaller
methods with a single responsibility
Posted by rp...@apache.org.
refactored large method into smaller methods with a single responsibility
Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo
Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/d0b97aa9
Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/d0b97aa9
Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/d0b97aa9
Branch: refs/heads/master
Commit: d0b97aa9443b9b38501150bb1c1a123c9e43fe9f
Parents: f9a4b70
Author: rpopma <rp...@apache.org>
Authored: Thu Jan 14 00:00:36 2016 +0900
Committer: rpopma <rp...@apache.org>
Committed: Thu Jan 14 00:00:36 2016 +0900
----------------------------------------------------------------------
.../log4j/core/appender/AsyncAppender.java | 79 +++++++++++---------
1 file changed, 45 insertions(+), 34 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/d0b97aa9/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
----------------------------------------------------------------------
diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
index 79b3ace..f9f25b3 100644
--- a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
+++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AsyncAppender.java
@@ -183,40 +183,51 @@ public final class AsyncAppender extends AbstractAppender {
* @param logEvent the event to log
*/
public void logMessageInBackgroundThread(final Log4jLogEvent logEvent) {
- boolean appendSuccessful = false;
- if (blocking) {
- final Serializable serialized = Log4jLogEvent.serialize(logEvent, includeLocation);
- try {
- // wait for free slots in the queue
- queue.put(serialized);
- appendSuccessful = true;
- } catch (final InterruptedException e) {
- // LOG4J2-1049: Some applications use Thread.interrupt() to send
- // messages between application threads. This does not necessarily
- // mean that the queue is full. To prevent dropping a log message,
- // quickly try to offer the event to the queue again.
- // (Yes, this means there is a possibility the same event is logged twice.)
- //
- // Finally, catching the InterruptedException means the
- // interrupted flag has been cleared on the current thread.
- // This may interfere with the application's expectation of
- // being interrupted, so when we are done, we set the interrupted
- // flag again.
- appendSuccessful = queue.offer(serialized);
- if (!appendSuccessful) {
- LOGGER.warn("Interrupted while waiting for a free slot in the AsyncAppender LogEvent-queue {}",
- getName());
- }
- // set the interrupted flag again.
- Thread.currentThread().interrupt();
- }
- } else {
- appendSuccessful = queue.offer(Log4jLogEvent.serialize(logEvent, includeLocation));
- if (!appendSuccessful) {
- error("Appender " + getName() + " is unable to write primary appenders. queue is full");
- }
+ final boolean success = blocking ? enqueueOrBlockIfQueueFull(logEvent) : enqueueOrDropIfQueueFull(logEvent);
+ logToErrorAppenderIfNecessary(success, logEvent);
+ }
+
+ private boolean enqueueOrBlockIfQueueFull(final Log4jLogEvent logEvent) {
+ boolean appendSuccessful;
+ final Serializable serialized = Log4jLogEvent.serialize(logEvent, includeLocation);
+ try {
+ // wait for free slots in the queue
+ queue.put(serialized);
+ appendSuccessful = true;
+ } catch (final InterruptedException e) {
+ appendSuccessful = handleInterruptedException(serialized);
}
- logToErrorAppenderIfNecessary(appendSuccessful, logEvent);
+ return appendSuccessful;
+ }
+
+ private boolean enqueueOrDropIfQueueFull(final Log4jLogEvent logEvent) {
+ final boolean appendSuccessful = queue.offer(Log4jLogEvent.serialize(logEvent, includeLocation));
+ if (!appendSuccessful) {
+ error("Appender " + getName() + " is unable to write primary appenders. queue is full");
+ }
+ return appendSuccessful;
+ }
+
+ // LOG4J2-1049: Some applications use Thread.interrupt() to send
+ // messages between application threads. This does not necessarily
+ // mean that the queue is full. To prevent dropping a log message,
+ // quickly try to offer the event to the queue again.
+ // (Yes, this means there is a possibility the same event is logged twice.)
+ //
+ // Finally, catching the InterruptedException means the
+ // interrupted flag has been cleared on the current thread.
+ // This may interfere with the application's expectation of
+ // being interrupted, so when we are done, we set the interrupted
+ // flag again.
+ private boolean handleInterruptedException(final Serializable serialized) {
+ final boolean appendSuccessful = queue.offer(serialized);
+ if (!appendSuccessful) {
+ LOGGER.warn("Interrupted while waiting for a free slot in the AsyncAppender LogEvent-queue {}",
+ getName());
+ }
+ // set the interrupted flag again.
+ Thread.currentThread().interrupt();
+ return appendSuccessful;
}
private void logToErrorAppenderIfNecessary(final boolean appendSuccessful, final Log4jLogEvent logEvent) {
@@ -251,7 +262,7 @@ public final class AsyncAppender extends AbstractAppender {
@PluginAttribute(value = "bufferSize", defaultInt = DEFAULT_QUEUE_SIZE) final int size,
@PluginAttribute("name") final String name,
@PluginAttribute(value = "includeLocation", defaultBoolean = false) final boolean includeLocation,
- @PluginElement("Filter") final Filter filter,
+ @PluginElement("Filter") final Filter filter,
@PluginConfiguration final Configuration config,
@PluginAttribute(value = "ignoreExceptions", defaultBoolean = true) final boolean ignoreExceptions) {
// @formatter:on