From 05ef38da22795fb26952e922b5ca06a6625411e9 Mon Sep 17 00:00:00 2001 From: "Piotr P. Karwasz" Date: Mon, 22 Jan 2024 15:46:10 +0100 Subject: [PATCH] Simplify async logger in `main` Due to the introduction of `Recycler` in `main` and related changes, many async loggers can be simplified: * no thread name caching is required, * in many methods we can use `ReusableLogEvent` instead of concrete classes, * many casts from `ReadOnlyStringMap` to `StringMap` are not necessary. --- .../AsyncLoggerTestCachedThreadName.java | 63 ------------------- .../AsyncLoggerTestUncachedThreadName.java | 62 ------------------ .../core/async/QueueFullAbstractTest.java | 8 ++- .../core/async/RingBufferLogEventTest.java | 21 +++---- .../logging/log4j/core/async/AsyncLogger.java | 51 ++------------- .../async/AsyncLoggerConfigDisruptor.java | 12 ++-- .../core/async/AsyncLoggerDisruptor.java | 3 +- .../log4j/core/async/InternalAsyncUtil.java | 5 +- .../core/async/RingBufferLogEventHandler.java | 3 - .../async/RingBufferLogEventTranslator.java | 6 +- 10 files changed, 33 insertions(+), 201 deletions(-) delete mode 100644 log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTestCachedThreadName.java delete mode 100644 log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTestUncachedThreadName.java diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTestCachedThreadName.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTestCachedThreadName.java deleted file mode 100644 index 639d519a67f..00000000000 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTestCachedThreadName.java +++ /dev/null @@ -1,63 +0,0 @@ -/* - * 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.core.async; - -import static org.junit.jupiter.api.Assertions.assertNotNull; -import static org.junit.jupiter.api.Assertions.assertTrue; - -import java.io.BufferedReader; -import java.io.File; -import java.io.FileReader; -import org.apache.logging.log4j.LogManager; -import org.apache.logging.log4j.Logger; -import org.apache.logging.log4j.core.impl.Log4jPropertyKey; -import org.apache.logging.log4j.core.test.CoreLoggerContexts; -import org.apache.logging.log4j.core.test.junit.ContextSelectorType; -import org.junit.jupiter.api.Tag; -import org.junit.jupiter.api.Test; -import org.junitpioneer.jupiter.SetSystemProperty; - -@Tag("async") -@ContextSelectorType(AsyncLoggerContextSelector.class) -@SetSystemProperty(key = Log4jPropertyKey.Constant.CONFIG_LOCATION, value = "AsyncLoggerTest.xml") -public class AsyncLoggerTestCachedThreadName { - - @Test - public void testAsyncLogUsesCachedThreadName() throws Exception { - final File file = new File("target", "AsyncLoggerTest.log"); - // System.out.println(f.getAbsolutePath()); - file.delete(); - final Logger log = LogManager.getLogger("com.foo.Bar"); - final String msg = "Async logger msg"; - log.info(msg); - Thread.currentThread().setName("MODIFIED-THREADNAME"); - log.info(msg); - CoreLoggerContexts.stopLoggerContext(file); // stop async thread - - final BufferedReader reader = new BufferedReader(new FileReader(file)); - final String line1 = reader.readLine(); - final String line2 = reader.readLine(); - // System.out.println(line1); - // System.out.println(line2); - reader.close(); - file.delete(); - assertNotNull(line1, "line1"); - assertNotNull(line2, "line2"); - assertTrue(line1.endsWith(" INFO c.f.Bar [main] Async logger msg "), "line1"); - assertTrue(line2.endsWith(" INFO c.f.Bar [main] Async logger msg "), "line2"); - } -} diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTestUncachedThreadName.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTestUncachedThreadName.java deleted file mode 100644 index e9295b45ad1..00000000000 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerTestUncachedThreadName.java +++ /dev/null @@ -1,62 +0,0 @@ -/* - * 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.core.async; - -import static org.junit.jupiter.api.Assertions.assertNotNull; -import static org.junit.jupiter.api.Assertions.assertTrue; - -import java.io.BufferedReader; -import java.io.File; -import java.io.FileReader; -import org.apache.logging.log4j.LogManager; -import org.apache.logging.log4j.Logger; -import org.apache.logging.log4j.core.impl.Log4jPropertyKey; -import org.apache.logging.log4j.core.test.CoreLoggerContexts; -import org.apache.logging.log4j.core.test.junit.ContextSelectorType; -import org.junit.jupiter.api.Test; -import org.junitpioneer.jupiter.SetSystemProperty; - -@SetSystemProperty(key = Log4jPropertyKey.Constant.ASYNC_LOGGER_THREAD_NAME_STRATEGY, value = "UNCACHED") -@SetSystemProperty(key = Log4jPropertyKey.Constant.CONFIG_LOCATION, value = "AsyncLoggerTest.xml") -@ContextSelectorType(AsyncLoggerContextSelector.class) -public class AsyncLoggerTestUncachedThreadName { - - @Test - public void testAsyncLogUsesCurrentThreadName() throws Exception { - final File file = new File("target", "AsyncLoggerTest.log"); - // System.out.println(f.getAbsolutePath()); - file.delete(); - final Logger log = LogManager.getLogger("com.foo.Bar"); - final String msg = "Async logger msg"; - log.info(msg); - Thread.currentThread().setName("MODIFIED-THREADNAME"); - log.info(msg); - CoreLoggerContexts.stopLoggerContext(file); // stop async thread - - final BufferedReader reader = new BufferedReader(new FileReader(file)); - final String line1 = reader.readLine(); - final String line2 = reader.readLine(); - // System.out.println(line1); - // System.out.println(line2); - reader.close(); - file.delete(); - assertNotNull(line1, "line1"); - assertNotNull(line2, "line2"); - assertTrue(line1.endsWith(" INFO c.f.Bar [main] Async logger msg "), "line1"); - assertTrue(line2.endsWith(" INFO c.f.Bar [MODIFIED-THREADNAME] Async logger msg "), "line2"); - } -} diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/QueueFullAbstractTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/QueueFullAbstractTest.java index 62a7a722184..6b1f3a1464e 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/QueueFullAbstractTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/QueueFullAbstractTest.java @@ -302,9 +302,11 @@ protected static void assertAsyncLoggerConfig(final LoggerContext ctx, final int final Configuration config = ctx.getConfiguration(); assertThat(config).isNotNull(); assertThat(config.getRootLogger()).isInstanceOf(AsyncLoggerConfig.class); - final AsyncLoggerConfigDisruptor disruptor = (AsyncLoggerConfigDisruptor) config.getAsyncLoggerConfigDelegate(); - final Field sizeField = field(AsyncLoggerConfigDisruptor.class, "ringBufferSize"); - assertThat(sizeField.get(disruptor)).isEqualTo(expectedBufferSize); + final AsyncLoggerConfigDisruptor disruptorWrapper = + (AsyncLoggerConfigDisruptor) config.getAsyncLoggerConfigDelegate(); + final Disruptor disruptor = (Disruptor) + field(AsyncLoggerConfigDisruptor.class, "disruptor").get(disruptorWrapper); + assertThat(disruptor.getBufferSize()).isEqualTo(expectedBufferSize); } protected static void assertFormatMessagesInBackground() { diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java index e2c8008a577..e9f0aed2a4e 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/RingBufferLogEventTest.java @@ -38,7 +38,6 @@ import org.apache.logging.log4j.message.ReusableMessageFactory; import org.apache.logging.log4j.message.SimpleMessage; import org.apache.logging.log4j.spi.MutableThreadContextStack; -import org.apache.logging.log4j.util.StringMap; import org.junit.jupiter.api.Tag; import org.junit.jupiter.api.Test; @@ -80,7 +79,7 @@ public void testIsPopulated() { level, data, t, - (StringMap) evt.getContextData(), + evt.getContextData(), contextStack, -1, threadName, @@ -116,7 +115,7 @@ public void testGetLevelReturnsOffIfNullLevelSet() { level, data, t, - (StringMap) evt.getContextData(), + evt.getContextData(), contextStack, -1, threadName, @@ -147,7 +146,7 @@ public void testGetMessageReturnsNonNullMessage() { level, data, t, - (StringMap) evt.getContextData(), + evt.getContextData(), contextStack, -1, threadName, @@ -178,7 +177,7 @@ public void testGetMillisReturnsConstructorMillisForNormalMessage() { level, data, t, - (StringMap) evt.getContextData(), + evt.getContextData(), contextStack, -1, threadName, @@ -210,7 +209,7 @@ public void testCreateMementoReturnsCopy() { level, data, t, - (StringMap) evt.getContextData(), + evt.getContextData(), contextStack, -1, threadName, @@ -218,7 +217,7 @@ public void testCreateMementoReturnsCopy() { location, new FixedPreciseClock(12345, 678), new DummyNanoClock(1)); - ((StringMap) evt.getContextData()).putValue("key", "value"); + evt.getContextData().putValue("key", "value"); final LogEvent actual = evt.toMemento(); assertEquals(evt.getLoggerName(), actual.getLoggerName()); @@ -261,7 +260,7 @@ public void testCreateMementoRetainsParametersAndFormat() { level, message, t, - (StringMap) evt.getContextData(), + evt.getContextData(), contextStack, -1, threadName, @@ -269,7 +268,7 @@ public void testCreateMementoRetainsParametersAndFormat() { location, new FixedPreciseClock(12345, 678), new DummyNanoClock(1)); - ((StringMap) evt.getContextData()).putValue("key", "value"); + evt.getContextData().putValue("key", "value"); final Message actual = evt.toMemento().getMessage(); assertEquals("Hello {}!", actual.getFormat()); @@ -304,7 +303,7 @@ public void testMementoReuse() { level, message, t, - (StringMap) evt.getContextData(), + evt.getContextData(), contextStack, -1, threadName, @@ -312,7 +311,7 @@ public void testMementoReuse() { location, new FixedPreciseClock(12345, 678), new DummyNanoClock(1)); - ((StringMap) evt.getContextData()).putValue("key", "value"); + evt.getContextData().putValue("key", "value"); final Message memento1 = evt.memento(); final Message memento2 = evt.memento(); 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 4aef03e08bf..5515fcbb348 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 @@ -16,15 +16,14 @@ */ package org.apache.logging.log4j.core.async; -import com.lmax.disruptor.EventTranslatorVararg; import java.util.List; import org.apache.logging.log4j.Level; import org.apache.logging.log4j.Marker; import org.apache.logging.log4j.ThreadContext; -import org.apache.logging.log4j.ThreadContext.ContextStack; import org.apache.logging.log4j.core.ContextDataInjector; import org.apache.logging.log4j.core.Logger; import org.apache.logging.log4j.core.LoggerContext; +import org.apache.logging.log4j.core.ReusableLogEvent; import org.apache.logging.log4j.core.config.Configuration; import org.apache.logging.log4j.core.config.LoggerConfig; import org.apache.logging.log4j.core.config.Property; @@ -58,7 +57,7 @@ * and they will flush to disk at the end of each batch. This means that even with immediateFlush=false, there will * never be any items left in the buffer; all log events will all be written to disk in a very efficient manner. */ -public class AsyncLogger extends Logger implements EventTranslatorVararg { +public class AsyncLogger extends Logger { // Implementation note: many methods in this class are tuned for performance. MODIFY WITH CARE! // Specifically, try to keep the hot methods to 35 bytecodes or less: // this is within the MaxInlineSize threshold and makes these methods candidates for @@ -276,46 +275,6 @@ private StackTraceElement calcLocationIfRequested(final String fqcn) { return includeLocation ? StackLocatorUtil.calcLocation(fqcn) : null; } - /* - * (non-Javadoc) - * - * @see com.lmax.disruptor.EventTranslatorVararg#translateTo(java.lang.Object, long, java.lang.Object[]) - */ - @Override - public void translateTo(final RingBufferLogEvent event, final long sequence, final Object... args) { - // Implementation note: candidate for optimization: exceeds 35 bytecodes. - final AsyncLogger asyncLogger = (AsyncLogger) args[0]; - final StackTraceElement location = (StackTraceElement) args[1]; - final String fqcn = (String) args[2]; - final Level level = (Level) args[3]; - final Marker marker = (Marker) args[4]; - final Message message = (Message) args[5]; - final Throwable thrown = (Throwable) args[6]; - - // needs shallow copy to be fast (LOG4J2-154) - final ContextStack contextStack = ThreadContext.getImmutableStack(); - - final Thread currentThread = Thread.currentThread(); - event.setValues( - asyncLogger, - asyncLogger.getName(), - marker, - fqcn, - level, - message, - thrown, - // config properties are taken care of in the EventHandler thread - // in the AsyncLogger#actualAsyncLog method - contextDataInjector.injectContextData(null, (StringMap) event.getContextData()), - contextStack, - currentThread.getId(), - currentThread.getName(), - currentThread.getPriority(), - location, - clock, - nanoClock); - } - /** * LOG4J2-471: prevent deadlock when RingBuffer is full and object being logged calls Logger.log() from its * toString() method @@ -340,7 +299,7 @@ void logMessageInCurrentThread( * * @param event the event to log */ - public void actualAsyncLog(final RingBufferLogEvent event) { + public void actualAsyncLog(final ReusableLogEvent event) { final LoggerConfig privateConfigLoggerConfig = privateConfig.loggerConfig; final List properties = privateConfigLoggerConfig.getPropertyList(); @@ -352,7 +311,7 @@ public void actualAsyncLog(final RingBufferLogEvent event) { } @SuppressWarnings("ForLoopReplaceableByForEach") // Avoid iterator allocation - private void onPropertiesPresent(final RingBufferLogEvent event, final List properties) { + private void onPropertiesPresent(final ReusableLogEvent event, final List properties) { final StringMap contextData = getContextData(event); for (int i = 0, size = properties.size(); i < size; i++) { final Property prop = properties.get(i); @@ -367,7 +326,7 @@ private void onPropertiesPresent(final RingBufferLogEvent event, final List disruptor; private long backgroundThreadId; // LOG4J2-471 - private EventFactory factory; private EventTranslatorTwoArg translator; private volatile boolean alreadyLoggedWarning; private final AsyncWaitStrategyFactory asyncWaitStrategyFactory; @@ -207,7 +204,8 @@ public void start() { return; } LOGGER.trace("AsyncLoggerConfigDisruptor creating new disruptor for this configuration."); - ringBufferSize = DisruptorUtil.calculateRingBufferSize(Log4jPropertyKey.ASYNC_CONFIG_RING_BUFFER_SIZE); + final int ringBufferSize = + DisruptorUtil.calculateRingBufferSize(Log4jPropertyKey.ASYNC_CONFIG_RING_BUFFER_SIZE); waitStrategy = DisruptorUtil.createWaitStrategy( Log4jPropertyKey.ASYNC_CONFIG_WAIT_STRATEGY, asyncWaitStrategyFactory); @@ -223,7 +221,7 @@ public Thread newThread(final Runnable r) { asyncQueueFullPolicy = AsyncQueueFullPolicyFactory.create(); translator = mutable ? MUTABLE_TRANSLATOR : TRANSLATOR; - factory = mutable ? MUTABLE_FACTORY : FACTORY; + final EventFactory factory = mutable ? MUTABLE_FACTORY : FACTORY; disruptor = new Disruptor<>(factory, ringBufferSize, threadFactory, ProducerType.MULTI, waitStrategy); final ExceptionHandler errorHandler = 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 fb477901870..2edf4bb9bb2 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 @@ -103,7 +103,8 @@ public void start() { } setStarting(); LOGGER.trace("[{}] AsyncLoggerDisruptor creating new disruptor for this context.", contextName); - int ringBufferSize = DisruptorUtil.calculateRingBufferSize(Log4jPropertyKey.ASYNC_LOGGER_RING_BUFFER_SIZE); + final int ringBufferSize = + DisruptorUtil.calculateRingBufferSize(Log4jPropertyKey.ASYNC_LOGGER_RING_BUFFER_SIZE); final AsyncWaitStrategyFactory factory = waitStrategyFactorySupplier.get(); // get factory from configuration waitStrategy = DisruptorUtil.createWaitStrategy(Log4jPropertyKey.ASYNC_LOGGER_WAIT_STRATEGY, factory); diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/InternalAsyncUtil.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/InternalAsyncUtil.java index aa82a0dfe3e..8cff3d79d02 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/InternalAsyncUtil.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/InternalAsyncUtil.java @@ -26,7 +26,10 @@ * Consider this class private. *

*/ -public class InternalAsyncUtil { +public final class InternalAsyncUtil { + + private InternalAsyncUtil() {} + /** * Returns the specified message, with its content frozen unless system property * {@code log4j.format.msg.async} is true or the message class is annotated with diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventHandler.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventHandler.java index 9b350bf4b62..f141846591f 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventHandler.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventHandler.java @@ -77,7 +77,4 @@ public long getThreadId() { public void onStart() { threadId = Thread.currentThread().getId(); } - - @Override - public void onShutdown() {} } diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java index 837cae9ca8c..15b2b652bcb 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/RingBufferLogEventTranslator.java @@ -24,7 +24,6 @@ import org.apache.logging.log4j.core.time.Clock; import org.apache.logging.log4j.core.time.NanoClock; import org.apache.logging.log4j.message.Message; -import org.apache.logging.log4j.util.ReadOnlyStringMap; import org.apache.logging.log4j.util.StringMap; /** @@ -55,7 +54,7 @@ public class RingBufferLogEventTranslator implements EventTranslator