From 98189ee3f9d56dcb5f5d8d910d20806feb4f0435 Mon Sep 17 00:00:00 2001 From: "Piotr P. Karwasz" Date: Tue, 28 Jan 2025 08:38:23 +0100 Subject: [PATCH 1/4] Minimize lock usage in `InternalLoggerRegistry` It has been reported that holding a lock on `InternalLoggerRegistry` during the creation of a logger can cause performance loss and deadlocks. The logger constructor can trigger property lookups and other pluggable operations, we don't entirely control. The fix to #3252 only covered one of these cases. This change moves the instantiation of new `Logger`s outside the write lock. While in some cases, this will cause multiple instantiations of loggers with the same parameters, all such loggers are functionally equivalent. On the other hand, the change allows the creation of different loggers in parallel. Closes #3399 --- .../util/internal/InternalLoggerRegistry.java | 67 +++++++++---------- src/changelog/.2.x.x/3399_logger_registry.xml | 10 +++ 2 files changed, 43 insertions(+), 34 deletions(-) create mode 100644 src/changelog/.2.x.x/3399_logger_registry.xml diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java index 59df6749612..3c1b294634c 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java @@ -147,44 +147,43 @@ public Logger computeIfAbsent( return logger; } + // Creating a logger is expensive and might cause lookups and locks, possibly deadlocks: + // https://github.com/apache/logging-log4j2/issues/3252 + // https://github.com/apache/logging-log4j2/issues/3399 + // + // Creating loggers without a lock, allows multiple threads to create loggers in parallel, which also + // improves performance. + // Since all loggers with the same parameters are equivalent, we can safely return the logger from the + // thread that finishes first. + Logger newLogger = loggerSupplier.apply(name, messageFactory); + + // Report name and message factory mismatch if there are any + final String loggerName = newLogger.getName(); + final MessageFactory loggerMessageFactory = newLogger.getMessageFactory(); + if (!loggerName.equals(name) || !loggerMessageFactory.equals(messageFactory)) { + StatusLogger.getLogger() + .error( + "Newly registered logger with name `{}` and message factory `{}`, is requested to be associated with a different name `{}` or message factory `{}`.\n" + + "Effectively the message factory of the logger will be used and the other one will be ignored.\n" + + "This generally hints a problem at the logger context implementation.\n" + + "Please report this using the Log4j project issue tracker.", + loggerName, + loggerMessageFactory, + name, + messageFactory); + } + // Write lock slow path: Insert the logger writeLock.lock(); try { - // See if the logger is created by another thread in the meantime - final Map> loggerRefByName = - loggerRefByNameByMessageFactory.computeIfAbsent(messageFactory, ignored -> new HashMap<>()); - WeakReference loggerRef = loggerRefByName.get(name); - if (loggerRef != null && (logger = loggerRef.get()) != null) { - return logger; - } - - // Create the logger - logger = loggerSupplier.apply(name, messageFactory); - - // Report name and message factory mismatch if there are any - final String loggerName = logger.getName(); - final MessageFactory loggerMessageFactory = logger.getMessageFactory(); - if (!loggerMessageFactory.equals(messageFactory)) { - StatusLogger.getLogger() - .error( - "Newly registered logger with name `{}` and message factory `{}`, is requested to be associated with a different name `{}` or message factory `{}`.\n" - + "Effectively the message factory of the logger will be used and the other one will be ignored.\n" - + "This generally hints a problem at the logger context implementation.\n" - + "Please report this using the Log4j project issue tracker.", - loggerName, - loggerMessageFactory, - name, - messageFactory); - // Register logger under alternative keys - loggerRefByNameByMessageFactory - .computeIfAbsent(loggerMessageFactory, ignored -> new HashMap<>()) - .putIfAbsent(loggerName, new WeakReference<>(logger)); - } - - // Insert the logger - loggerRefByName.put(name, new WeakReference<>(logger)); - return logger; + Logger currentLogger = loggerRefByNameByMessageFactory + .computeIfAbsent(messageFactory, ignored -> new HashMap<>()) + .computeIfAbsent(name, ignored -> new WeakReference<>(newLogger)) + .get(); + // A replacement for Reference.reachabilityFence() from Java 9. + // Prevents `newLogger` to become unreachable in the lines above. + return currentLogger != null ? currentLogger : newLogger; } finally { writeLock.unlock(); } diff --git a/src/changelog/.2.x.x/3399_logger_registry.xml b/src/changelog/.2.x.x/3399_logger_registry.xml new file mode 100644 index 00000000000..0eb56f1a64b --- /dev/null +++ b/src/changelog/.2.x.x/3399_logger_registry.xml @@ -0,0 +1,10 @@ + + + + + Minimize lock usage in `InternalLoggerRegistry`. + + From 14c6df0d8053e4f312bf72cd117ce8488f0a43df Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Volkan=20Yaz=C4=B1c=C4=B1?= Date: Fri, 31 Jan 2025 11:10:44 +0100 Subject: [PATCH 2/4] Handle when `WeakReference` returns null --- .../util/internal/InternalLoggerRegistry.java | 35 ++++++++++++------- 1 file changed, 22 insertions(+), 13 deletions(-) diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java index 3c1b294634c..cbe33c10071 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java @@ -147,12 +147,19 @@ public Logger computeIfAbsent( return logger; } - // Creating a logger is expensive and might cause lookups and locks, possibly deadlocks: - // https://github.com/apache/logging-log4j2/issues/3252 - // https://github.com/apache/logging-log4j2/issues/3399 + // Intentionally moving the logger creation outside the write lock, because: + // + // - Logger instantiation is expensive (causes contention on the write-lock) + // + // - User code might have circular code paths, though through different threads. + // Consider `T1[ILR:computeIfAbsent] -> ... -> T1[Logger::new] -> ... -> T2[ILR::computeIfAbsent]`. + // Hence, having logger instantiation while holding a write lock might cause deadlocks: + // https://github.com/apache/logging-log4j2/issues/3252 + // https://github.com/apache/logging-log4j2/issues/3399 + // + // - Creating loggers without a lock, allows multiple threads to create loggers in parallel, which also improves + // performance. // - // Creating loggers without a lock, allows multiple threads to create loggers in parallel, which also - // improves performance. // Since all loggers with the same parameters are equivalent, we can safely return the logger from the // thread that finishes first. Logger newLogger = loggerSupplier.apply(name, messageFactory); @@ -176,14 +183,16 @@ public Logger computeIfAbsent( // Write lock slow path: Insert the logger writeLock.lock(); try { - - Logger currentLogger = loggerRefByNameByMessageFactory - .computeIfAbsent(messageFactory, ignored -> new HashMap<>()) - .computeIfAbsent(name, ignored -> new WeakReference<>(newLogger)) - .get(); - // A replacement for Reference.reachabilityFence() from Java 9. - // Prevents `newLogger` to become unreachable in the lines above. - return currentLogger != null ? currentLogger : newLogger; + Map> loggerRefByName = loggerRefByNameByMessageFactory.get(messageFactory); + // noinspection Java8MapApi (avoid the allocation of lambda passed to `Map::computeIfAbsent`) + if (loggerRefByName == null) { + loggerRefByNameByMessageFactory.put(messageFactory, loggerRefByName = new HashMap<>()); + } + final WeakReference loggerRef = loggerRefByName.get(name); + if (loggerRef == null || (logger = loggerRef.get()) == null) { + loggerRefByName.put(name, new WeakReference<>(logger = newLogger)); + } + return logger; } finally { writeLock.unlock(); } From 71b3b1c053da87d0877c3c85f263bbc9f3e1d599 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Volkan=20Yaz=C4=B1c=C4=B1?= Date: Fri, 31 Jan 2025 17:27:50 +0100 Subject: [PATCH 3/4] Avoid lambda allocation in `getLogger()` --- .../util/internal/InternalLoggerRegistry.java | 15 +++++++++------ 1 file changed, 9 insertions(+), 6 deletions(-) diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java index cbe33c10071..90cd6153a63 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java @@ -22,7 +22,6 @@ import java.util.Collection; import java.util.HashMap; import java.util.Map; -import java.util.Optional; import java.util.WeakHashMap; import java.util.concurrent.locks.Lock; import java.util.concurrent.locks.ReadWriteLock; @@ -70,11 +69,15 @@ public InternalLoggerRegistry() {} requireNonNull(messageFactory, "messageFactory"); readLock.lock(); try { - return Optional.of(loggerRefByNameByMessageFactory) - .map(loggerRefByNameByMessageFactory -> loggerRefByNameByMessageFactory.get(messageFactory)) - .map(loggerRefByName -> loggerRefByName.get(name)) - .map(WeakReference::get) - .orElse(null); + final Map> loggerRefByName = + loggerRefByNameByMessageFactory.get(messageFactory); + if (loggerRefByName != null) { + final WeakReference loggerRef = loggerRefByName.get(name); + if (loggerRef != null) { + return loggerRef.get(); + } + } + return null; } finally { readLock.unlock(); } From bb40734032d6b3c75aae8956f33fe6983519087c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Volkan=20Yaz=C4=B1c=C4=B1?= Date: Fri, 31 Jan 2025 17:32:23 +0100 Subject: [PATCH 4/4] Improve JavaDoc --- .../log4j/core/util/internal/InternalLoggerRegistry.java | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java index 90cd6153a63..eff1d46b77a 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/InternalLoggerRegistry.java @@ -30,17 +30,20 @@ import java.util.stream.Collectors; import java.util.stream.Stream; import org.apache.logging.log4j.core.Logger; +import org.apache.logging.log4j.core.LoggerContext; import org.apache.logging.log4j.message.MessageFactory; import org.apache.logging.log4j.status.StatusLogger; import org.jspecify.annotations.NullMarked; import org.jspecify.annotations.Nullable; /** - * Convenience class used by {@link org.apache.logging.log4j.core.LoggerContext} + * A registry of {@link Logger}s namespaced by name and message factory. + * This class is internally used by {@link LoggerContext}. *

- * We don't use {@link org.apache.logging.log4j.spi.LoggerRegistry} from the Log4j API to keep Log4j Core independent - * from the version of the Log4j API at runtime. + * We don't use {@linkplain org.apache.logging.log4j.spi.LoggerRegistry the registry from Log4j API} to keep Log4j Core independent from the version of Log4j API at runtime. + * This also allows Log4j Core to evolve independently from Log4j API. *

+ * * @since 2.25.0 */ @NullMarked