From 59f88190fcd3bc0e6fbd90668625feae3ad1e671 Mon Sep 17 00:00:00 2001 From: "Piotr P. Karwasz" Date: Wed, 12 Jul 2023 10:18:09 +0200 Subject: [PATCH] Issue #1550: remove multiple `isFiltered` invocations Async logger configs call `isFiltered(LogEvent)` multiple times. While this is not a problem per-se, it can cause a performance penalty if the filter is slow and creates problems to stateful filters. --- .../core/async/AsyncLoggerConfigTest.java | 38 +++++++++++++++++++ .../log4j/core/config/LoggerConfigTest.java | 34 ++++++++++++++++- .../log4j/core/async/AsyncLoggerConfig.java | 35 ++++++++--------- .../log4j/core/config/LoggerConfig.java | 17 ++++++--- .../1550_multiple_filter_invocations.xml | 25 ++++++++++++ 5 files changed, 126 insertions(+), 23 deletions(-) create mode 100644 src/changelog/.2.x.x/1550_multiple_filter_invocations.xml diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest.java index 606f2a58be3..715cd500fb6 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/async/AsyncLoggerConfigTest.java @@ -20,23 +20,36 @@ import java.io.File; import java.io.FileReader; +import org.apache.logging.log4j.Level; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; +import org.apache.logging.log4j.core.Appender; +import org.apache.logging.log4j.core.Filter; import org.apache.logging.log4j.core.config.AppenderRef; +import org.apache.logging.log4j.core.config.Configuration; import org.apache.logging.log4j.core.config.ConfigurationFactory; import org.apache.logging.log4j.core.config.DefaultConfiguration; import org.apache.logging.log4j.core.config.LoggerConfig; +import org.apache.logging.log4j.core.config.NullConfiguration; import org.apache.logging.log4j.core.test.CoreLoggerContexts; import org.apache.logging.log4j.core.test.categories.AsyncLoggers; +import org.apache.logging.log4j.message.SimpleMessage; import org.junit.BeforeClass; import org.junit.Test; import org.junit.experimental.categories.Category; import static org.junit.Assert.*; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.times; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.when; @Category(AsyncLoggers.class) public class AsyncLoggerConfigTest { + private static final String FQCN = AsyncLoggerConfigTest.class.getName(); + @BeforeClass public static void beforeClass() { System.setProperty(ConfigurationFactory.CONFIGURATION_FILE_PROPERTY, "AsyncLoggerConfigTest.xml"); @@ -81,4 +94,29 @@ public void testIncludeLocationDefaultsToFalse() { assertFalse("Include location should default to false for async loggers", loggerConfig.isIncludeLocation()); } + + @Test + public void testSingleFilterInvocation() { + final Configuration configuration = new NullConfiguration(); + final Filter filter = mock(Filter.class); + final LoggerConfig config = AsyncLoggerConfig.newAsyncBuilder() + .withLoggerName(FQCN) + .withConfig(configuration) + .withLevel(Level.INFO) + .withtFilter(filter) + .build(); + final Appender appender = mock(Appender.class); + when(appender.isStarted()).thenReturn(true); + when(appender.getName()).thenReturn("test"); + config.addAppender(appender, null, null); + final AsyncLoggerConfigDisruptor disruptor = (AsyncLoggerConfigDisruptor) configuration.getAsyncLoggerConfigDelegate(); + disruptor.start(); + try { + config.log(FQCN, FQCN, null, Level.INFO, new SimpleMessage(), null); + verify(appender, times(1)).append(any()); + verify(filter, times(1)).filter(any()); + } finally { + disruptor.stop(); + } + } } diff --git a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/config/LoggerConfigTest.java b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/config/LoggerConfigTest.java index d1223ba6287..3a35b3b9976 100644 --- a/log4j-core-test/src/test/java/org/apache/logging/log4j/core/config/LoggerConfigTest.java +++ b/log4j-core-test/src/test/java/org/apache/logging/log4j/core/config/LoggerConfigTest.java @@ -21,17 +21,29 @@ import java.util.concurrent.atomic.AtomicReference; import org.apache.logging.log4j.Level; +import org.apache.logging.log4j.core.Appender; +import org.apache.logging.log4j.core.Filter; import org.apache.logging.log4j.core.impl.Log4jLogEvent.Builder; import org.apache.logging.log4j.message.SimpleMessage; import org.junit.jupiter.api.Test; -import static org.junit.jupiter.api.Assertions.*; +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertNotSame; +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertSame; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.times; +import static org.mockito.Mockito.verify; +import static org.mockito.Mockito.when; /** * Tests for LoggerConfig. */ public class LoggerConfigTest { + private static final String FQCN = LoggerConfigTest.class.getName(); + private static LoggerConfig createForProperties(final Property[] properties) { return LoggerConfig.createLogger(true, Level.INFO, "name", "false", new AppenderRef[0], properties, new NullConfiguration(), null); @@ -109,4 +121,24 @@ public void testLevel() { assertEquals(config2.getLevel(), Level.ERROR, "Unexpected Level"); assertNull(config2.getExplicitLevel(),"Unexpected explicit level"); } + + @Test + public void testSingleFilterInvocation() { + final Configuration configuration = new NullConfiguration(); + final Filter filter = mock(Filter.class); + final LoggerConfig config = LoggerConfig.newBuilder() + .withLoggerName(FQCN) + .withConfig(configuration) + .withLevel(Level.INFO) + .withtFilter(filter) + .build(); + final Appender appender = mock(Appender.class); + when(appender.isStarted()).thenReturn(true); + when(appender.getName()).thenReturn("test"); + config.addAppender(appender, null, null); + + config.log(FQCN, FQCN, null, Level.INFO, new SimpleMessage(), null); + verify(appender, times(1)).append(any()); + verify(filter, times(1)).filter(any()); + } } diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java index 134d9cda452..027ab98870a 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLoggerConfig.java @@ -126,15 +126,17 @@ protected void log(final LogEvent event, final LoggerConfigPredicate predicate) // This is the first AsnycLoggerConfig encountered by this LogEvent ASYNC_LOGGER_ENTERED.set(Boolean.TRUE); try { - // Detect the first time we encounter an AsyncLoggerConfig. We must log - // to all non-async loggers first. - super.log(event, LoggerConfigPredicate.SYNCHRONOUS_ONLY); - // Then pass the event to the background thread where - // all async logging is executed. It is important this - // happens at most once and after all synchronous loggers - // have been invoked, because we lose parameter references - // from reusable messages. - logToAsyncDelegate(event); + if (!isFiltered(event)) { + // Detect the first time we encounter an AsyncLoggerConfig. We must log + // to all non-async loggers first. + processLogEvent(event, LoggerConfigPredicate.SYNCHRONOUS_ONLY); + // Then pass the event to the background thread where + // all async logging is executed. It is important this + // happens at most once and after all synchronous loggers + // have been invoked, because we lose parameter references + // from reusable messages. + logToAsyncDelegate(event); + } } finally { ASYNC_LOGGER_ENTERED.set(Boolean.FALSE); } @@ -149,13 +151,11 @@ protected void callAppenders(final LogEvent event) { } private void logToAsyncDelegate(final LogEvent event) { - if (!isFiltered(event)) { - // Passes on the event to a separate thread that will call - // asyncCallAppenders(LogEvent). - populateLazilyInitializedFields(event); - if (!delegate.tryEnqueue(event, this)) { - handleQueueFull(event); - } + // Passes on the event to a separate thread that will call + // asyncCallAppenders(LogEvent). + populateLazilyInitializedFields(event); + if (!delegate.tryEnqueue(event, this)) { + handleQueueFull(event); } } @@ -187,7 +187,8 @@ void logInBackgroundThread(final LogEvent event) { * default {@link LoggerConfig} definitions), which will be invoked on the calling thread. */ void logToAsyncLoggerConfigsOnCurrentThread(final LogEvent event) { - log(event, LoggerConfigPredicate.ASYNCHRONOUS_ONLY); + // skip the filter, which was already called on the logging thread + processLogEvent(event, LoggerConfigPredicate.ASYNCHRONOUS_ONLY); } private String displayName() { diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig.java index d15cbd3a32a..d28ab10dbcb 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/LoggerConfig.java @@ -611,9 +611,9 @@ public void log(final LogEvent event) { /** * Logs an event. * - * @param event The log event. - * @param predicate predicate for which LoggerConfig instances to append to. - * A null value is equivalent to a true predicate. + * @param event The log event. + * @param predicate predicate for which LoggerConfig instances to append to. A + * {@literal null} value is equivalent to a true predicate. */ protected void log(final LogEvent event, final LoggerConfigPredicate predicate) { if (!isFiltered(event)) { @@ -631,9 +631,16 @@ public ReliabilityStrategy getReliabilityStrategy() { return reliabilityStrategy; } - private void processLogEvent(final LogEvent event, final LoggerConfigPredicate predicate) { + /** + * Logs an event, bypassing filters. + * + * @param event The log event. + * @param predicate predicate for which LoggerConfig instances to append to. A + * {@literal null} value is equivalent to a true predicate. + */ + protected void processLogEvent(final LogEvent event, final LoggerConfigPredicate predicate) { event.setIncludeLocation(isIncludeLocation()); - if (predicate.allow(this)) { + if (predicate == null || predicate.allow(this)) { callAppenders(event); } logParent(event, predicate); diff --git a/src/changelog/.2.x.x/1550_multiple_filter_invocations.xml b/src/changelog/.2.x.x/1550_multiple_filter_invocations.xml new file mode 100644 index 00000000000..a865adc7f8f --- /dev/null +++ b/src/changelog/.2.x.x/1550_multiple_filter_invocations.xml @@ -0,0 +1,25 @@ + + + + + + Removes additional `isFiltered` checks in `AsyncLoggerConfig`. +