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 14ca876d587f9d3ef4d2202c9788cbe31a29ac92 Author: Carter Kozak <[email protected]> AuthorDate: Wed May 22 14:06:00 2019 -0400 Update enqueue from synchronized to a Semaphore for more configurability --- .../logging/log4j/core/async/AsyncLoggerDisruptor.java | 18 ++++++++++++++---- .../apache/logging/log4j/core/async/DisruptorUtil.java | 5 +++-- .../perf/jmh/ConcurrentAsyncLoggerToFileBenchmark.java | 2 +- 3 files changed, 18 insertions(+), 7 deletions(-) diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerDisruptor.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerDisruptor.java index b827f8c..1e294e4 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerDisruptor.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerDisruptor.java @@ -17,6 +17,7 @@ package org.apache.logging.log4j.core.async; +import java.util.concurrent.Semaphore; import java.util.concurrent.ThreadFactory; import java.util.concurrent.TimeUnit; @@ -46,7 +47,10 @@ class AsyncLoggerDisruptor extends AbstractLifeCycle { private static final int SLEEP_MILLIS_BETWEEN_DRAIN_ATTEMPTS = 50; private static final int MAX_DRAIN_ATTEMPTS_BEFORE_SHUTDOWN = 200; - private final Object queueFullEnqueueLock = new Object(); + // queueFullEnqueueSemaphore is null when the semaphore is disabled (non-positive value) + private final Semaphore queueFullEnqueueSemaphore = DisruptorUtil.ASYNC_LOGGER_ENQUEUE_SEMAPHORE_PERMITS > 0 + ? new Semaphore(DisruptorUtil.ASYNC_LOGGER_ENQUEUE_SEMAPHORE_PERMITS) + : null; private volatile Disruptor<RingBufferLogEvent> disruptor; private String contextName; @@ -226,8 +230,11 @@ class AsyncLoggerDisruptor extends AbstractLifeCycle { // Avoiding this and using an older reference could result in adding a log event to the disruptor after it // was shut down, which could cause the publishEvent method to hang and never return. if (synchronizeEnqueueWhenQueueFull()) { - synchronized (queueFullEnqueueLock) { + queueFullEnqueueSemaphore.acquireUninterruptibly(); + try { disruptor.publishEvent(translator); + } finally { + queueFullEnqueueSemaphore.release(); } } else { disruptor.publishEvent(translator); @@ -252,7 +259,8 @@ class AsyncLoggerDisruptor extends AbstractLifeCycle { // Avoiding this and using an older reference could result in adding a log event to the disruptor after it // was shut down, which could cause the publishEvent method to hang and never return. if (synchronizeEnqueueWhenQueueFull()) { - synchronized (queueFullEnqueueLock) { + queueFullEnqueueSemaphore.acquireUninterruptibly(); + try { disruptor.getRingBuffer().publishEvent(translator, asyncLogger, // asyncLogger: 0 location, // location: 1 @@ -261,6 +269,8 @@ class AsyncLoggerDisruptor extends AbstractLifeCycle { marker, // 4 msg, // 5 thrown); // 6 + } finally { + queueFullEnqueueSemaphore.release(); } } else { disruptor.getRingBuffer().publishEvent(translator, @@ -281,7 +291,7 @@ class AsyncLoggerDisruptor extends AbstractLifeCycle { } private boolean synchronizeEnqueueWhenQueueFull() { - return DisruptorUtil.SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_IS_FULL + return queueFullEnqueueSemaphore != null // Background thread must never block && backgroundThreadId != Thread.currentThread().getId(); } 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 59d2a7e..6e868f8 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 @@ -48,8 +48,9 @@ final class DisruptorUtil { // LOG4J2-2606: Disruptor spins enqueuing events across multiple threads when the queue is full. // CPU utilization is significantly reduced by restricting access to the enqueue operation. - static final boolean SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_IS_FULL = PropertiesUtil.getProperties() - .getBooleanProperty("AsyncLogger.SynchronizeEnqueueWhenQueueFull", true); + // Non-positive values disable the semaphore. + static final int ASYNC_LOGGER_ENQUEUE_SEMAPHORE_PERMITS = PropertiesUtil.getProperties() + .getIntegerProperty("AsyncLogger.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 20415f0..2e9d3fe 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 @@ -103,7 +103,7 @@ public class ConcurrentAsyncLoggerToFileBenchmark { ENQUEUE(Collections.singletonMap("log4j2.AsyncQueueFullPolicy", "Default")), ENQUEUE_UNSYNCHRONIZED(new HashMap<>() {{ put("log4j2.AsyncQueueFullPolicy", "Default"); - put("log4j2.AsyncLogger.SynchronizeEnqueueWhenQueueFull", "false"); + put("AsyncLogger.AsyncQueueFullEnqueueSemaphorePermits", "0"); } }), SYNCHRONOUS(Collections.singletonMap("log4j2.AsyncQueueFullPolicy",
