Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Log "excessive" creation of factories and proxies #690

Merged
Show file tree
Hide file tree
Changes from 3 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -29,9 +29,12 @@
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;
import java.util.function.Function;
import java.util.function.Supplier;
import java.util.stream.Collectors;

/**
Expand Down Expand Up @@ -98,12 +101,29 @@
public class ConfigProxyFactory {
private static final Logger LOG = LoggerFactory.getLogger(ConfigProxyFactory.class);

// 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<Config, Integer> FACTORIES_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<InterfaceAndPrefix, Integer> PROXIES_COUNT = Collections.synchronizedMap(new WeakHashMap<>());

/**
* The decoder is used for the purpose of decoding any @DefaultValue annotation
*/
private final Decoder decoder;
private final PropertyRepository propertyRepository;
private final Config config;
private final int excessiveProxyLimit;


/**
Expand All @@ -121,6 +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, excessiveProxyLimit, () -> String.format("ProxyFactory(Config:%s)", config.hashCode()));
}

/**
Expand Down Expand Up @@ -190,9 +213,11 @@ interface PropertyValueGetter<T> {
@SuppressWarnings({"unchecked", "rawtypes"})
<T> T newProxy(final Class<T> type, final String initialPrefix, boolean immutable) {
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 :-|
Expand Down Expand Up @@ -460,6 +485,19 @@ private static void maybeWrapThenRethrow(Throwable t) {
throw new RuntimeException(t);
}

private static <T> void warnWhenTooMany(Map<T, Integer> counters, T countKey, int limit, Supplier<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 )) {

LOG.warn("Too many {} objects are being created. Please review the calling code to prevent memory leaks. Stack trace for debugging follows:",

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit: Perhaps log the EXCESSIVE_PROXIES_LIMIT knob so users know how to adjust this if they have a legit reason to create so many of these proxies. But also log that you should only be creating a singleton.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done :-)
New log message looks like

2023-10-30 13:30:48,612 WARN  ConfigProxyFactory:497  Too many ProxyFactory(Config:330084561) objects are being created (5 so far).
Please review the calling code to prevent memory leaks.
Normal usage for ConfigProxyFactory is to create singletons via your DI mechanism.
For special use cases that *require* creating multiple instances you can tune reporting
by setting the `archaius.excessiveProxiesLogging.limit` config key to a higher threshold.
Stack trace for debugging follows: [Test worker]
java.lang.Throwable
	at com.netflix.archaius.ConfigProxyFactory.warnWhenTooMany(ConfigProxyFactory.java:503)
	at com.netflix.archaius.ConfigProxyFactory.<init>(ConfigProxyFactory.java:146)
	at com.netflix.archaius.ProxyFactoryTest.testLogExcessiveUse(ProxyFactoryTest.java:563)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        ...

objectDescription.get(), new Throwable());
}
}

/** InvocationHandler for config proxies. */
private static class ConfigProxyInvocationHandler<P> implements InvocationHandler {
Expand Down Expand Up @@ -537,6 +575,35 @@ private MethodInvokerHolder(PropertyValueGetter<T> 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<V> extends StrLookup<V> {
private final V[] elements;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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.
}
}