From 6d3105f1462af7a55ced0d50a99415542c602ff2 Mon Sep 17 00:00:00 2001 From: "Piotr P. Karwasz" Date: Tue, 28 Jan 2025 08:38:23 +0100 Subject: [PATCH 1/2] 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 557bd3432cd3ab126d928f749b71ab52ae84e2e6 Mon Sep 17 00:00:00 2001 From: Tristan Tarrant Date: Thu, 30 Jan 2025 10:24:39 +0100 Subject: [PATCH 2/2] Use a WeakValuesHashMap to store loggers --- .../util/internal/InternalLoggerRegistry.java | 24 +--- .../core/util/internal/WeakValuesHashMap.java | 121 ++++++++++++++++++ 2 files changed, 126 insertions(+), 19 deletions(-) create mode 100644 log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/WeakValuesHashMap.java 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..8a4418b60b9 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 @@ -18,9 +18,7 @@ import static java.util.Objects.requireNonNull; -import java.lang.ref.WeakReference; import java.util.Collection; -import java.util.HashMap; import java.util.Map; import java.util.Optional; import java.util.WeakHashMap; @@ -29,7 +27,6 @@ import java.util.concurrent.locks.ReentrantReadWriteLock; import java.util.function.BiFunction; import java.util.stream.Collectors; -import java.util.stream.Stream; import org.apache.logging.log4j.core.Logger; import org.apache.logging.log4j.message.MessageFactory; import org.apache.logging.log4j.status.StatusLogger; @@ -40,15 +37,14 @@ * Convenience class used by {@link org.apache.logging.log4j.core.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. + * of the version of the Log4j API at runtime. *

* @since 2.25.0 */ @NullMarked public final class InternalLoggerRegistry { - private final Map>> loggerRefByNameByMessageFactory = - new WeakHashMap<>(); + private final Map> loggerRefByNameByMessageFactory = new WeakHashMap<>(); private final ReadWriteLock lock = new ReentrantReadWriteLock(); @@ -73,7 +69,6 @@ public InternalLoggerRegistry() {} return Optional.of(loggerRefByNameByMessageFactory) .map(loggerRefByNameByMessageFactory -> loggerRefByNameByMessageFactory.get(messageFactory)) .map(loggerRefByName -> loggerRefByName.get(name)) - .map(WeakReference::get) .orElse(null); } finally { readLock.unlock(); @@ -88,10 +83,6 @@ public Collection getLoggers() { // https://github.com/apache/logging-log4j2/issues/3234 return loggerRefByNameByMessageFactory.values().stream() .flatMap(loggerRefByName -> loggerRefByName.values().stream()) - .flatMap(loggerRef -> { - @Nullable Logger logger = loggerRef.get(); - return logger != null ? Stream.of(logger) : Stream.empty(); - }) .collect(Collectors.toList()); } finally { readLock.unlock(); @@ -176,14 +167,9 @@ 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; + return loggerRefByNameByMessageFactory + .computeIfAbsent(messageFactory, ignored -> new WeakValuesHashMap<>()) + .computeIfAbsent(name, ignored -> newLogger); } finally { writeLock.unlock(); } diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/WeakValuesHashMap.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/WeakValuesHashMap.java new file mode 100644 index 00000000000..b1acb71d6a4 --- /dev/null +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/WeakValuesHashMap.java @@ -0,0 +1,121 @@ +/* + * 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.util.internal; + +import java.lang.ref.ReferenceQueue; +import java.lang.ref.WeakReference; +import java.util.AbstractMap; +import java.util.Collection; +import java.util.HashMap; +import java.util.Map; +import java.util.Set; + +/** + * A {@link HashMap} implementation which is similar to {@link java.util.WeakHashMap} but for weak values instead of + * keys. Warning: this is not a general-purpose implementation; only what's needed by @{@link InternalLoggerRegistry} + * is implemented. + * @param - the type of keys maintained by this map + * @param – the type of mapped values + */ +class WeakValuesHashMap extends AbstractMap { + private final HashMap> map; + private final ReferenceQueue queue; + + public WeakValuesHashMap() { + map = new HashMap<>(10); + queue = new ReferenceQueue<>(); + } + + @Override + public V put(K key, V value) { + processQueue(); + WeakValue ref = new WeakValue<>(key, value, queue); + return unref(map.put(key, ref)); + } + + @Override + public V get(Object key) { + processQueue(); + return unref(map.get(key)); + } + + @Override + public V remove(Object key) { + return unref(map.get(key)); + } + + @Override + public void clear() { + map.clear(); + } + + @Override + public boolean containsKey(Object key) { + processQueue(); + return map.containsKey(key); + } + + @Override + public boolean containsValue(Object value) { + throw new UnsupportedOperationException(); + } + + @Override + public Set keySet() { + throw new UnsupportedOperationException(); + } + + @Override + public int size() { + processQueue(); + return map.size(); + } + + @Override + public Set> entrySet() { + throw new UnsupportedOperationException(); + } + + @Override + public Collection values() { + throw new UnsupportedOperationException(); + } + + private V unref(WeakValue valueRef) { + return valueRef == null ? null : valueRef.get(); + } + + @SuppressWarnings("unchecked") + private void processQueue() { + for (WeakValue v = (WeakValue) queue.poll(); v != null; v = (WeakValue) queue.poll()) { + map.remove(v.getKey()); + } + } + + private class WeakValue extends WeakReference { + private final K key; + + private WeakValue(K key, T value, ReferenceQueue queue) { + super(value, queue); + this.key = key; + } + + private K getKey() { + return key; + } + } +}