Skip to content

Commit

Permalink
Remove unneeded weak reference from prefix logger
Browse files Browse the repository at this point in the history
We have a custom logger implementation known as a prefix logger that is
used to write every message by the logger with a given prefix. This is
useful for node-level, index-level, and shard-level messages where we
want to log the node name, index name, and shard ID, respectively, if
possible. The mechanism that we employ is that of a marker. Log4j has a
built-in facility for managing these markers, but its effectively a
memory leak because these markers are held in a map and can never be
released. This is problematic for us since indices and shards do not
necessarily have infinite life spans and so on a node where there are
many indices being creted and destroyed, this infinite lifespan can be a
problem indeed. To solve this, we use our own cache of markers. This is
necessary to prevent too many instances of the marker for the same
prefix from being created (just think of all the shard-level components
that exist in the system), and to workaround the effective leak in
Log4j. These markers are stored as weak references in a weak hash
map. It is these weak references that are unneeded. When a key is
removed from a weak hash map, the corresponding entry is placed on a
reference queue that is eventually cleared. This commit simplifies
prefix logger by removing this unnecessary weak reference wrapper.

Relates #22460
  • Loading branch information
jasontedor committed Jun 10, 2017
1 parent 58bc897 commit 0914292
Show file tree
Hide file tree
Showing 2 changed files with 58 additions and 8 deletions.
Expand Up @@ -26,34 +26,69 @@
import org.apache.logging.log4j.spi.ExtendedLogger;
import org.apache.logging.log4j.spi.ExtendedLoggerWrapper;

import java.lang.ref.WeakReference;
import java.util.WeakHashMap;

/**
* A logger that prefixes all messages with a fixed prefix specified during construction. The prefix mechanism uses the marker construct, so
* for the prefixes to appear, the logging layout pattern must include the marker in its pattern.
*/
class PrefixLogger extends ExtendedLoggerWrapper {

// we can not use the built-in Marker tracking (MarkerManager) because the MarkerManager holds
// a permanent reference to the marker; however, we have transient markers from index-level and
// shard-level components so this would effectively be a memory leak
private static final WeakHashMap<String, WeakReference<Marker>> markers = new WeakHashMap<>();
/*
* We can not use the built-in Marker tracking (MarkerManager) because the MarkerManager holds a permanent reference to the marker;
* however, we have transient markers from index-level and shard-level components so this would effectively be a memory leak. Since we
* can not tie into the lifecycle of these components, we have to use a mechanism that enables garbage collection of such markers when
* they are no longer in use.
*/
private static final WeakHashMap<String, Marker> markers = new WeakHashMap<>();

/**
* Return the size of the cached markers. This size can vary as markers are cached but collected during GC activity when a given prefix
* is no longer in use.
*
* @return the size of the cached markers
*/
static int markersSize() {
return markers.size();
}

/**
* The marker for this prefix logger.
*/
private final Marker marker;

/**
* Obtain the prefix for this prefix logger. This can be used to create a logger with the same prefix as this one.
*
* @return the prefix
*/
public String prefix() {
return marker.getName();
}

/**
* Construct a prefix logger with the specified name and prefix.
*
* @param logger the extended logger to wrap
* @param name the name of this prefix logger
* @param prefix the prefix for this prefix logger
*/
PrefixLogger(final ExtendedLogger logger, final String name, final String prefix) {
super(logger, name, null);

final String actualPrefix = (prefix == null ? "" : prefix).intern();
final Marker actualMarker;
// markers is not thread-safe, so we synchronize access
synchronized (markers) {
final WeakReference<Marker> marker = markers.get(actualPrefix);
final Marker maybeMarker = marker == null ? null : marker.get();
final Marker maybeMarker = markers.get(actualPrefix);
if (maybeMarker == null) {
actualMarker = new MarkerManager.Log4jMarker(actualPrefix);
markers.put(actualPrefix, new WeakReference<>(actualMarker));
/*
* We must create a new instance here as otherwise the marker will hold a reference to the key in the weak hash map; as
* those references are held strongly, this would give a strong reference back to the key preventing them from ever being
* collected. This also guarantees that no other strong reference can be held to the prefix anywhere.
*/
markers.put(new String(actualPrefix), actualMarker);
} else {
actualMarker = maybeMarker;
}
Expand Down
Expand Up @@ -47,6 +47,7 @@
import java.util.regex.Pattern;

import static org.hamcrest.Matchers.equalTo;
import static org.hamcrest.Matchers.lessThan;
import static org.hamcrest.Matchers.startsWith;

public class EvilLoggerTests extends ESTestCase {
Expand Down Expand Up @@ -170,6 +171,20 @@ public void testPrefixLogger() throws IOException, IllegalAccessException, UserE
}
}

public void testPrefixLoggerMarkersCanBeCollected() throws IOException, UserException {
setupLogging("prefix");

final int prefixes = 1 << 19; // to ensure enough markers that the GC should collect some when we force a GC below
for (int i = 0; i < prefixes; i++) {
// this has the side effect of caching a marker with this prefix
Loggers.getLogger("prefix" + i, "prefix" + i);
}

// this will free the weakly referenced keys in the marker cache
System.gc();
assertThat(PrefixLogger.markersSize(), lessThan(prefixes));
}

public void testProperties() throws IOException, UserException {
final Settings.Builder builder = Settings.builder().put("cluster.name", randomAlphaOfLength(16));
if (randomBoolean()) {
Expand Down

0 comments on commit 0914292

Please sign in to comment.