From 07dbcc9f5bd7d536b7fba3280107dde67109280b Mon Sep 17 00:00:00 2001 From: Rebeca Gallardo Date: Wed, 25 Oct 2023 11:54:34 -0700 Subject: [PATCH 1/4] Log "excessive" creation of factories and proxies --- .../netflix/archaius/ConfigProxyFactory.java | 38 +++++++++++++++++++ 1 file changed, 38 insertions(+) diff --git a/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java b/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java index a35eb16b..f5f147f9 100644 --- a/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java +++ b/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java @@ -16,6 +16,9 @@ import org.slf4j.LoggerFactory; import javax.inject.Inject; +import java.io.ByteArrayOutputStream; +import java.io.IOException; +import java.io.PrintWriter; import java.lang.invoke.MethodHandle; import java.lang.invoke.MethodHandles; import java.lang.invoke.MethodType; @@ -24,6 +27,7 @@ import java.lang.reflect.Method; import java.lang.reflect.Proxy; import java.lang.reflect.Type; +import java.nio.charset.StandardCharsets; import java.util.Collections; import java.util.HashMap; import java.util.LinkedList; @@ -31,6 +35,7 @@ import java.util.Map; import java.util.Set; import java.util.SortedSet; +import java.util.WeakHashMap; import java.util.function.Function; import java.util.stream.Collectors; @@ -98,6 +103,12 @@ public class ConfigProxyFactory { private static final Logger LOG = LoggerFactory.getLogger(ConfigProxyFactory.class); + // Users sometimes leak both factories and proxies, leading to memory problems that get blamed on us ;-) + // We'll use these maps to keep track of how many instances of each are created and make log noise to help them + // track down the actual culprits. WeakHashMaps to avoid holding onto objects ourselves. + private static final Map FACTORIES_COUNT = Collections.synchronizedMap(new WeakHashMap<>()); + private static final Map, Integer> PROXIES_COUNT = Collections.synchronizedMap(new WeakHashMap<>()); + /** * The decoder is used for the purpose of decoding any @DefaultValue annotation */ @@ -121,6 +132,8 @@ public ConfigProxyFactory(Config config, Decoder decoder, PropertyFactory factor this.decoder = decoder; this.config = config; this.propertyRepository = factory; + + warnWhenTooMany(FACTORIES_COUNT, config, 5, String.format("ProxyFactory(Config:%s)", config.hashCode())); } /** @@ -189,6 +202,8 @@ interface PropertyValueGetter { @SuppressWarnings({"unchecked", "rawtypes"}) T newProxy(final Class type, final String initialPrefix, boolean immutable) { + warnWhenTooMany(PROXIES_COUNT, type, 50, String.format("Proxy(%s)", type)); + Configuration annot = type.getAnnotation(Configuration.class); final String prefix = derivePrefix(annot, initialPrefix); @@ -460,6 +475,29 @@ private static void maybeWrapThenRethrow(Throwable t) { throw new RuntimeException(t); } + private static void warnWhenTooMany(Map counters, T countKey, int limit, String objectDescription) { + int currentCount = counters.merge(countKey, 1, Integer::sum); + + // Emit warning if we're over the limit BUT only when the current count is a multiple of the limit :-) + // This is to avoid being *too* noisy + if (LOG.isWarnEnabled() && + currentCount >= limit && + (currentCount % limit == 0 )) { + + String stackTraceForDebuggint; + try (ByteArrayOutputStream os = new ByteArrayOutputStream(4000); + PrintWriter pw = new PrintWriter(os)) { + new RuntimeException().printStackTrace(pw); + pw.flush(); + stackTraceForDebuggint = os.toString(StandardCharsets.UTF_8.name()); + } catch (IOException e) { + stackTraceForDebuggint = ""; + } + + LOG.warn("Too many {} are being created. Please review the calling code to prevent memory leaks. Stack trace for debugging follows {}", + objectDescription, stackTraceForDebuggint); + } + } /** InvocationHandler for config proxies. */ private static class ConfigProxyInvocationHandler

implements InvocationHandler { From 9be6228d62b782f6c40cf728cfedb20ed1477f88 Mon Sep 17 00:00:00 2001 From: Rebeca Gallardo Date: Mon, 30 Oct 2023 10:42:57 -0700 Subject: [PATCH 2/4] Simplify code a bit and avoid performance penalty for non-offenders. --- .../netflix/archaius/ConfigProxyFactory.java | 25 +++++-------------- 1 file changed, 6 insertions(+), 19 deletions(-) diff --git a/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java b/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java index f5f147f9..936343f4 100644 --- a/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java +++ b/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java @@ -16,9 +16,6 @@ import org.slf4j.LoggerFactory; import javax.inject.Inject; -import java.io.ByteArrayOutputStream; -import java.io.IOException; -import java.io.PrintWriter; import java.lang.invoke.MethodHandle; import java.lang.invoke.MethodHandles; import java.lang.invoke.MethodType; @@ -27,7 +24,6 @@ import java.lang.reflect.Method; import java.lang.reflect.Proxy; import java.lang.reflect.Type; -import java.nio.charset.StandardCharsets; import java.util.Collections; import java.util.HashMap; import java.util.LinkedList; @@ -37,6 +33,7 @@ import java.util.SortedSet; import java.util.WeakHashMap; import java.util.function.Function; +import java.util.function.Supplier; import java.util.stream.Collectors; /** @@ -133,7 +130,7 @@ public ConfigProxyFactory(Config config, Decoder decoder, PropertyFactory factor this.config = config; this.propertyRepository = factory; - warnWhenTooMany(FACTORIES_COUNT, config, 5, String.format("ProxyFactory(Config:%s)", config.hashCode())); + warnWhenTooMany(FACTORIES_COUNT, config, 5, () -> String.format("ProxyFactory(Config:%s)", config.hashCode())); } /** @@ -202,7 +199,7 @@ interface PropertyValueGetter { @SuppressWarnings({"unchecked", "rawtypes"}) T newProxy(final Class type, final String initialPrefix, boolean immutable) { - warnWhenTooMany(PROXIES_COUNT, type, 50, String.format("Proxy(%s)", type)); + warnWhenTooMany(PROXIES_COUNT, type, 50, () -> String.format("Proxy(%s)", type)); Configuration annot = type.getAnnotation(Configuration.class); @@ -475,7 +472,7 @@ private static void maybeWrapThenRethrow(Throwable t) { throw new RuntimeException(t); } - private static void warnWhenTooMany(Map counters, T countKey, int limit, String objectDescription) { + private static void warnWhenTooMany(Map counters, T countKey, int limit, Supplier objectDescription) { int currentCount = counters.merge(countKey, 1, Integer::sum); // Emit warning if we're over the limit BUT only when the current count is a multiple of the limit :-) @@ -484,18 +481,8 @@ private static void warnWhenTooMany(Map counters, T countKey, in currentCount >= limit && (currentCount % limit == 0 )) { - String stackTraceForDebuggint; - try (ByteArrayOutputStream os = new ByteArrayOutputStream(4000); - PrintWriter pw = new PrintWriter(os)) { - new RuntimeException().printStackTrace(pw); - pw.flush(); - stackTraceForDebuggint = os.toString(StandardCharsets.UTF_8.name()); - } catch (IOException e) { - stackTraceForDebuggint = ""; - } - - LOG.warn("Too many {} are being created. Please review the calling code to prevent memory leaks. Stack trace for debugging follows {}", - objectDescription, stackTraceForDebuggint); + LOG.warn("Too many {} are being created. Please review the calling code to prevent memory leaks. Stack trace for debugging follows: ", + objectDescription.get(), new Throwable()); } } From ffd39f073cd2e582ba560e80135800f84aa0fd28 Mon Sep 17 00:00:00 2001 From: Rebeca Gallardo Date: Mon, 30 Oct 2023 11:26:23 -0700 Subject: [PATCH 3/4] Index count of created proxies by prefix too, and lower warning threshold By keeping track of created proxies on a per-factory basis and including the prefix in the count key we can lower the reporting limit. A user could potentially create up to 16 proxies for each uniq (config, interface, prefix) combination before triggering warnings. Made reporting trigger configurable but not dynamic. Users with known bad usage patterns can quiet down the warnings until a fix can be made. Added a manual test for logging. Set as @Ignored, since CI can't verify it's working anyway. --- .../netflix/archaius/ConfigProxyFactory.java | 60 ++++++++++++++++--- .../netflix/archaius/ProxyFactoryTest.java | 23 +++++++ 2 files changed, 74 insertions(+), 9 deletions(-) diff --git a/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java b/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java index 936343f4..398b0c61 100644 --- a/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java +++ b/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java @@ -29,6 +29,7 @@ import java.util.LinkedList; import java.util.List; import java.util.Map; +import java.util.Objects; import java.util.Set; import java.util.SortedSet; import java.util.WeakHashMap; @@ -100,11 +101,21 @@ public class ConfigProxyFactory { private static final Logger LOG = LoggerFactory.getLogger(ConfigProxyFactory.class); - // Users sometimes leak both factories and proxies, leading to memory problems that get blamed on us ;-) - // We'll use these maps to keep track of how many instances of each are created and make log noise to help them - // track down the actual culprits. WeakHashMaps to avoid holding onto objects ourselves. + // Users sometimes leak both factories and proxies, leading to hard-to-track-down memory problems. + // We use these maps to keep track of how many instances of each are created and make log noise to help them + // track down the culprits. WeakHashMaps to avoid holding onto objects ourselves. + /** + * Global count of proxy factories, indexed by Config object. An application could legitimately have more + * than one proxy factory per config, if they want to use different Decoders or PropertyFactories. + */ private static final Map FACTORIES_COUNT = Collections.synchronizedMap(new WeakHashMap<>()); - private static final Map, Integer> PROXIES_COUNT = Collections.synchronizedMap(new WeakHashMap<>()); + private static final String EXCESSIVE_PROXIES_LIMIT = "archaius.excessiveProxiesLogging.limit"; + + /** + * Per-factory count of proxies, indexed by implemented interface and prefix. Because this count is kept per-proxy, + * it's also implicitly indexed by Config object :-) + */ + private final Map PROXIES_COUNT = Collections.synchronizedMap(new WeakHashMap<>()); /** * The decoder is used for the purpose of decoding any @DefaultValue annotation @@ -112,6 +123,7 @@ public class ConfigProxyFactory { private final Decoder decoder; private final PropertyRepository propertyRepository; private final Config config; + private final int excessiveProxyLimit; /** @@ -129,8 +141,9 @@ public ConfigProxyFactory(Config config, Decoder decoder, PropertyFactory factor this.decoder = decoder; this.config = config; this.propertyRepository = factory; + excessiveProxyLimit = config.getInteger(EXCESSIVE_PROXIES_LIMIT, 5); - warnWhenTooMany(FACTORIES_COUNT, config, 5, () -> String.format("ProxyFactory(Config:%s)", config.hashCode())); + warnWhenTooMany(FACTORIES_COUNT, config, excessiveProxyLimit, () -> String.format("ProxyFactory(Config:%s)", config.hashCode())); } /** @@ -199,12 +212,12 @@ interface PropertyValueGetter { @SuppressWarnings({"unchecked", "rawtypes"}) T newProxy(final Class type, final String initialPrefix, boolean immutable) { - warnWhenTooMany(PROXIES_COUNT, type, 50, () -> String.format("Proxy(%s)", type)); - Configuration annot = type.getAnnotation(Configuration.class); - final String prefix = derivePrefix(annot, initialPrefix); + warnWhenTooMany(PROXIES_COUNT, new InterfaceAndPrefix(type, prefix), excessiveProxyLimit, () -> String.format("Proxy(%s, %s)", type, prefix)); + + // There's a circular dependency between these maps and the proxy object. They must be created first because the // proxy's invocation handler needs to keep a reference to them, but the proxy must be created before they get // filled because we may need to call methods on the interface in order to fill the maps :-| @@ -481,7 +494,7 @@ private static void warnWhenTooMany(Map counters, T countKey, in currentCount >= limit && (currentCount % limit == 0 )) { - LOG.warn("Too many {} are being created. Please review the calling code to prevent memory leaks. Stack trace for debugging follows: ", + LOG.warn("Too many {} objects are being created. Please review the calling code to prevent memory leaks. Stack trace for debugging follows:", objectDescription.get(), new Throwable()); } } @@ -562,6 +575,35 @@ private MethodInvokerHolder(PropertyValueGetter invoker, String propertyName) } } + /** Key to index counts of created proxies */ + private static final class InterfaceAndPrefix { + final Class configInterface; + final String prefix; + + private InterfaceAndPrefix(Class configInterface, String prefix) { + this.configInterface = configInterface; + this.prefix = prefix; + } + + @Override + public boolean equals(Object o) { + if (this == o) { + return true; + } + if (o == null || getClass() != o.getClass()) { + return false; + } + InterfaceAndPrefix that = (InterfaceAndPrefix) o; + return Objects.equals(configInterface, that.configInterface) && + Objects.equals(prefix, that.prefix); + } + + @Override + public int hashCode() { + return Objects.hash(configInterface, prefix); + } + } + /** Implement apache-commons StrLookup by interpreting the key as an index into an array */ private static class ArrayLookup extends StrLookup { private final V[] elements; diff --git a/archaius2-core/src/test/java/com/netflix/archaius/ProxyFactoryTest.java b/archaius2-core/src/test/java/com/netflix/archaius/ProxyFactoryTest.java index 6ee94d68..05c833d4 100644 --- a/archaius2-core/src/test/java/com/netflix/archaius/ProxyFactoryTest.java +++ b/archaius2-core/src/test/java/com/netflix/archaius/ProxyFactoryTest.java @@ -17,6 +17,7 @@ import javax.annotation.Nullable; import org.junit.Assert; +import org.junit.Ignore; import org.junit.Test; import com.netflix.archaius.api.Config; @@ -551,4 +552,26 @@ public void testObjectMethods_ClassWithArgumentsAndDefaultMethod() { //noinspection EqualsWithItself Assert.assertEquals(withArgs, withArgs); } + + @Ignore("Manual test. Output is just log entries, can't be verified by CI") + @Test + public void testLogExcessiveUse() { + SettableConfig config = new DefaultSettableConfig(); + PropertyFactory propertyFactory = DefaultPropertyFactory.from(config); + + for (int i = 0; i < 5; i++) { + new ConfigProxyFactory(config, config.getDecoder(), propertyFactory); // Last one should emit a log! + } + + SettableConfig otherConfig = new DefaultSettableConfig(); + for (int i = 0; i < 4; i++) { + new ConfigProxyFactory(otherConfig, config.getDecoder(), propertyFactory); // Should not log! It's only 4 and on a different config. + } + + ConfigProxyFactory factory = new ConfigProxyFactory(config, config.getDecoder(), propertyFactory); // Should not log, because we only log every 5. + for (int i = 0; i < 5; i++) { + factory.newProxy(WithArguments.class, "aPrefix"); // Last one should emit a log + } + factory.newProxy(WithArguments.class, "somePrefix"); // This one should not log, because it's a new prefix. + } } From dbe9b5c6dc1b73dca50ce9fc27d4b331a019b7c7 Mon Sep 17 00:00:00 2001 From: Rebeca Gallardo Date: Mon, 30 Oct 2023 13:32:26 -0700 Subject: [PATCH 4/4] More verbose logging with instructions for users. --- .../java/com/netflix/archaius/ConfigProxyFactory.java | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java b/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java index 398b0c61..8e669232 100644 --- a/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java +++ b/archaius2-core/src/main/java/com/netflix/archaius/ConfigProxyFactory.java @@ -494,8 +494,13 @@ private static void warnWhenTooMany(Map counters, T countKey, in currentCount >= limit && (currentCount % limit == 0 )) { - LOG.warn("Too many {} objects are being created. Please review the calling code to prevent memory leaks. Stack trace for debugging follows:", - objectDescription.get(), new Throwable()); + LOG.warn( + "Too many {} objects are being created ({} so far).\n" + + "Please review the calling code to prevent memory leaks.\n" + + "Normal usage for ConfigProxyFactory is to create singletons via your DI mechanism.\n" + + "For special use cases that *require* creating multiple instances you can tune reporting\n" + + "by setting the `{}` config key to a higher threshold.\nStack trace for debugging follows:", + objectDescription.get(), currentCount, EXCESSIVE_PROXIES_LIMIT, new Throwable()); } }