This is an automated email from the ASF dual-hosted git repository. ckozak pushed a commit to branch LOG4J2-2606 in repository https://gitbox.apache.org/repos/asf/logging-log4j2.git
commit 6c9824f70cc03aab4d4c0eb2dec814b15b2daa01 Author: Carter Kozak <[email protected]> AuthorDate: Wed May 22 14:22:34 2019 -0400 Apply synchronization to the mixed async logging implementation Updated benchmarking results: ``` Benchmark (asyncLoggerType) (queueFullPolicy) Mode Cnt Score Error Units ConcurrentAsyncLoggerToFileBenchmark.concurrentLoggingThreads ASYNC_CONTEXT ENQUEUE thrpt 3 1196852.082 ± 656921.903 ops/s ConcurrentAsyncLoggerToFileBenchmark.concurrentLoggingThreads ASYNC_CONTEXT ENQUEUE_UNSYNCHRONIZED thrpt 3 299829.995 ± 672293.830 ops/s ConcurrentAsyncLoggerToFileBenchmark.concurrentLoggingThreads ASYNC_CONTEXT SYNCHRONOUS thrpt 3 1119699.755 ± 985194.962 ops/s ConcurrentAsyncLoggerToFileBenchmark.concurrentLoggingThreads ASYNC_CONFIG ENQUEUE thrpt 3 1255978.339 ± 208596.091 ops/s ConcurrentAsyncLoggerToFileBenchmark.concurrentLoggingThreads ASYNC_CONFIG ENQUEUE_UNSYNCHRONIZED thrpt 3 252966.661 ± 31303.171 ops/s ConcurrentAsyncLoggerToFileBenchmark.concurrentLoggingThreads ASYNC_CONFIG SYNCHRONOUS thrpt 3 1050306.069 ± 1564741.862 ops/s ConcurrentAsyncLoggerToFileBenchmark.singleLoggingThread ASYNC_CONTEXT ENQUEUE thrpt 3 1256681.352 ± 1858635.191 ops/s ConcurrentAsyncLoggerToFileBenchmark.singleLoggingThread ASYNC_CONTEXT ENQUEUE_UNSYNCHRONIZED thrpt 3 1357446.702 ± 825753.509 ops/s ConcurrentAsyncLoggerToFileBenchmark.singleLoggingThread ASYNC_CONTEXT SYNCHRONOUS thrpt 3 1240065.456 ± 832767.348 ops/s ConcurrentAsyncLoggerToFileBenchmark.singleLoggingThread ASYNC_CONFIG ENQUEUE thrpt 3 1376691.658 ± 614955.853 ops/s ConcurrentAsyncLoggerToFileBenchmark.singleLoggingThread ASYNC_CONFIG ENQUEUE_UNSYNCHRONIZED thrpt 3 1403978.404 ± 776352.491 ops/s ConcurrentAsyncLoggerToFileBenchmark.singleLoggingThread ASYNC_CONFIG SYNCHRONOUS thrpt 3 1347219.410 ± 2608889.236 ops/s ``` --- .../core/async/AsyncLoggerConfigDelegate.java | 5 +++++ .../core/async/AsyncLoggerConfigDisruptor.java | 23 +++++++++++++++++++++- .../logging/log4j/core/async/DisruptorUtil.java | 2 ++ .../jmh/ConcurrentAsyncLoggerToFileBenchmark.java | 1 + 4 files changed, 30 insertions(+), 1 deletion(-) diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigDelegate.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigDelegate.java index 0e230bb..6c25229 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigDelegate.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigDelegate.java @@ -46,6 +46,11 @@ public interface AsyncLoggerConfigDelegate { */ EventRoute getEventRoute(final Level level); + /** + * Enqueues the {@link LogEvent} on the mixed configuration ringbuffer. + * This method must only be used after {@link #tryEnqueue(LogEvent, AsyncLoggerConfig)} returns <code>false</code> + * indicating that the ringbuffer is full, otherwise it my incur unnecessary synchronization. + */ void enqueueEvent(LogEvent event, AsyncLoggerConfig asyncLoggerConfig); boolean tryEnqueue(LogEvent event, AsyncLoggerConfig asyncLoggerConfig); diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigDisruptor.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigDisruptor.java index b29dda3..a453170 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigDisruptor.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigDisruptor.java @@ -16,6 +16,7 @@ */ package org.apache.logging.log4j.core.async; +import java.util.concurrent.Semaphore; import java.util.concurrent.ThreadFactory; import java.util.concurrent.TimeUnit; @@ -186,6 +187,11 @@ public class AsyncLoggerConfigDisruptor extends AbstractLifeCycle implements Asy private EventTranslatorTwoArg<Log4jEventWrapper, LogEvent, AsyncLoggerConfig> translator; private volatile boolean alreadyLoggedWarning = false; + // queueFullEnqueueSemaphore is null when the semaphore is disabled (non-positive value) + private final Semaphore queueFullEnqueueSemaphore = DisruptorUtil.ASYNC_CONFIG_ENQUEUE_SEMAPHORE_PERMITS > 0 + ? new Semaphore(DisruptorUtil.ASYNC_CONFIG_ENQUEUE_SEMAPHORE_PERMITS) + : null; + public AsyncLoggerConfigDisruptor() { } @@ -369,7 +375,22 @@ public class AsyncLoggerConfigDisruptor extends AbstractLifeCycle implements Asy } private void enqueue(final LogEvent logEvent, final AsyncLoggerConfig asyncLoggerConfig) { - disruptor.getRingBuffer().publishEvent(translator, logEvent, asyncLoggerConfig); + if (synchronizeEnqueueWhenQueueFull()) { + queueFullEnqueueSemaphore.acquireUninterruptibly(); + try { + disruptor.getRingBuffer().publishEvent(translator, logEvent, asyncLoggerConfig); + } finally { + queueFullEnqueueSemaphore.release(); + } + } else { + disruptor.getRingBuffer().publishEvent(translator, logEvent, asyncLoggerConfig); + } + } + + private boolean synchronizeEnqueueWhenQueueFull() { + return queueFullEnqueueSemaphore != null + // Background thread must never block + && backgroundThreadId != Thread.currentThread().getId(); } @Override 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 6e868f8..5a415a0 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 @@ -51,6 +51,8 @@ final class DisruptorUtil { // Non-positive values disable the semaphore. static final int ASYNC_LOGGER_ENQUEUE_SEMAPHORE_PERMITS = PropertiesUtil.getProperties() .getIntegerProperty("AsyncLogger.AsyncQueueFullEnqueueSemaphorePermits", 1); + static final int ASYNC_CONFIG_ENQUEUE_SEMAPHORE_PERMITS = PropertiesUtil.getProperties() + .getIntegerProperty("AsyncLoggerConfig.AsyncQueueFullEnqueueSemaphorePermits", 1); private DisruptorUtil() { } diff --git a/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ConcurrentAsyncLoggerToFileBenchmark.java b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ConcurrentAsyncLoggerToFileBenchmark.java index 2e9d3fe..d7c67cc 100644 --- a/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ConcurrentAsyncLoggerToFileBenchmark.java +++ b/log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/ConcurrentAsyncLoggerToFileBenchmark.java @@ -104,6 +104,7 @@ public class ConcurrentAsyncLoggerToFileBenchmark { ENQUEUE_UNSYNCHRONIZED(new HashMap<>() {{ put("log4j2.AsyncQueueFullPolicy", "Default"); put("AsyncLogger.AsyncQueueFullEnqueueSemaphorePermits", "0"); + put("AsyncLoggerConfig.AsyncQueueFullEnqueueSemaphorePermits", "0"); } }), SYNCHRONOUS(Collections.singletonMap("log4j2.AsyncQueueFullPolicy",
