Reduce allocation overhead of ExceptionLogger / LogCollector (#10684)

Reducing overhead of getting ExcetionLogger

Unlike most loggers, ExceptionLogger can be looked up repeatedly by the exception handling code woven into instrumentation.

If an instrumentation constantly creates an exception, that could cause the Logger construction to become which results in creating SLCompatHelper constantly which in turn creates String-s and byte[]-s while determined the looger level.

To avoid that problem, the LoggerHelper is cached for ExceptionLogger.  We should also consider changing how the Logger is acuired, but that will be addressed in a separate PR.

Reducing allocation overhead of LogCollector

LogCollector creates RawLogMessage objects that act as keys for de-duplication.  If instrumentation has a hot exception, RawLogMessage construction can become a bottleneck.

While this change doesn't eliminate RawLogMessage, it does reduce the cost of hashCode & equals which are used by the Map to de-duplicate.

hashCode is improved by using the new HashingUtils.hash which avoids the array creation needed to call the var-arg method Objects.hash.

equals is improved by special casing, this.throwable == that.throwable.  While this case seems unlikely, it occurs when the JVM's hot throw optimization kicks in for NPEs.

equals is further improved by caching the result of getStackTrace.  Because getStackTrace returns an array, it makes a defensive copy on each call.

By caching getStackTrace, we avoid making a copy each time equals is called.

Clean-up

Making cachedStackTrace private
For clarity, returning local stackTrace rather than cachedStackTrace

Clarifying comments

Changed hot exception to fast throw, since that in comments, since that is the name used by the JVM

Merge branch 'master' into dougqh/exception-logger-quick-fixes

Fix broken import

Introduced a broken import while reincorporating stand-alone reproduction into code base

Sizing list appropriately

Merge branch 'dougqh/exception-logger-quick-fixes' of github.com:DataDog/dd-trace-java into dougqh/exception-logger-quick-fixes

Fixing oversight in handling of null Throwable

Adding noException case

Fixed bad copy job from stand-alone reproduction

spotless

Fixing imports

Merge branch 'master' into dougqh/exception-logger-quick-fixes

Merge branch 'master' into dougqh/exception-logger-quick-fixes

Merge branch 'master' into dougqh/exception-logger-quick-fixes

Merge branch 'master' into dougqh/exception-logger-quick-fixes

Merge branch 'master' into dougqh/exception-logger-quick-fixes

Co-authored-by: bric3 <brice.dutheil@gmail.com>
Co-authored-by: devflow.devflow-routing-intake <devflow.devflow-routing-intake@kubernetes.us1.ddbuild.io>

Author: 3 people

dd-java-agent/agent-bootstrap/src/jmh/java/datadog/trace/bootstrap/ExceptionLoggerBenchmark.java

@@ -0,0 +1,28 @@
+package datadog.trace.bootstrap;
+
+import org.openjdk.jmh.annotations.Benchmark;
+import org.openjdk.jmh.annotations.Fork;
+import org.openjdk.jmh.annotations.Measurement;
+import org.openjdk.jmh.annotations.Threads;
+import org.openjdk.jmh.annotations.Warmup;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+/**
+ * Benchmark showing impact of ExceptionLogger
+ *
+ * <p>NOTE: This benchmark exists to check the efficiency of retrieving the ExceptionLogger.
+ * Previously, this caused significant allocation.
+ */
+@Fork(2)
+@Warmup(iterations = 2)
+@Measurement(iterations = 5)
+@Threads(8)
+public class ExceptionLoggerBenchmark {
+  @Benchmark
+  public Logger getExceptionLogger() {
+    // This matches what happens in the bytecode weaving that defends against
+    // exception leaking out of instrumentation.
+    return LoggerFactory.getLogger(ExceptionLogger.class);
+  }
+}

dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/ExceptionLogger.java

@@ -8,6 +8,8 @@
  *
  * <p>See datadog.trace.agent.tooling.ExceptionHandlers
  */
-public class ExceptionLogger {
+public final class ExceptionLogger {
   public static final Logger LOGGER = LoggerFactory.getLogger(ExceptionLogger.class);
+
+  private ExceptionLogger() {}
 }

dd-java-agent/agent-logging/src/main/java/datadog/trace/logging/simplelogger/SLCompatFactory.java

@@ -12,9 +12,12 @@
  * <p>Tries to initialize lazily to mimic the behavior of {@code SimpleLogger} as much as possible.
  */
 public final class SLCompatFactory extends LoggerHelperFactory {
-
   static final long START_TIME = System.currentTimeMillis();
 
+  // DQH - ExceptionLogger isn't visible to this class, so hard-coding instead
+  static final String EXCEPTION_LOGGER_NAME = "datadog.trace.bootstrap.ExceptionLogger";
+  LoggerHelper cachedExceptionLoggerHelper;
+
   private static Properties getProperties() {
     try {
       return System.getProperties();
@@ -55,6 +58,27 @@ private SLCompatSettings getSettings() {
 
   @Override
   public LoggerHelper loggerHelperForName(String name) {
+    if (EXCEPTION_LOGGER_NAME.equals(name)) {
+      // DQH - This is ugly.  The exception propagation protection that handles
+      // unexpected exceptions in instrumentation always calls LoggerFactory.getLogger.
+
+      // getLogger is actually a factory method that always creates a new instance,
+      // which can cause this method to become extremely hot -- leading to significant
+      // amount of allocation and garbage collection.
+
+      // To guard against that scenario, cache the ExceptionLogger LoggerHelper instance
+      LoggerHelper helper = cachedExceptionLoggerHelper;
+      if (helper != null) return helper;
+
+      helper = createLoggerHelperForName(name);
+      cachedExceptionLoggerHelper = helper;
+      return helper;
+    } else {
+      return createLoggerHelperForName(name);
+    }
+  }
+
+  private LoggerHelper createLoggerHelperForName(String name) {
     SLCompatSettings settings = getSettings();
     return new SLCompatHelper(name, settings);
   }

internal-api/src/jmh/java/datadog/trace/api/telemetry/LogCollectorBenchmark.java

@@ -0,0 +1,48 @@
+package datadog.trace.api.telemetry;
+
+import org.openjdk.jmh.annotations.Benchmark;
+import org.openjdk.jmh.annotations.Fork;
+import org.openjdk.jmh.annotations.Measurement;
+import org.openjdk.jmh.annotations.Threads;
+import org.openjdk.jmh.annotations.Warmup;
+
+@Fork(2)
+@Warmup(iterations = 2)
+@Measurement(iterations = 5)
+@Threads(8)
+public class LogCollectorBenchmark {
+  @Benchmark
+  public void noException_before() {
+    LogCollector.get().addLogMessage("error", "ugh!", null);
+  }
+
+  static final Object NULL = null;
+
+  @Benchmark
+  public void nullPointerException() {
+    // Represents the fast throw case where the JVM switches to using
+    // a single Exception instance to handle a hot throw location
+    // of NullPointerException, ArrayIndexOutOfBoundsException, etc.
+    // In this case, the stacktrace of the exception will not be available.
+    try {
+      NULL.hashCode();
+    } catch (Throwable t) {
+      LogCollector.get().addLogMessage("error", "npe", t);
+    }
+  }
+
+  @Benchmark
+  public void unsupportedOperationException() {
+    // Represents the common case where stack trace is preserved
+    // despite hot throw
+    try {
+      unsupportedOperation();
+    } catch (Throwable t) {
+      LogCollector.get().addLogMessage("error", "unsupported", t);
+    }
+  }
+
+  static void unsupportedOperation() {
+    throw new UnsupportedOperationException();
+  }
+}

internal-api/src/main/java/datadog/trace/api/telemetry/LogCollector.java

@@ -1,5 +1,6 @@
 package datadog.trace.api.telemetry;
 
+import datadog.trace.util.HashingUtils;
 import edu.umd.cs.findbugs.annotations.SuppressFBWarnings;
 import java.util.ArrayList;
 import java.util.Collection;
@@ -68,7 +69,7 @@ public Collection<RawLogMessage> drain() {
       return Collections.emptyList();
     }
 
-    List<RawLogMessage> list = new ArrayList<>();
+    List<RawLogMessage> list = new ArrayList<>(rawLogMessages.size());
     Iterator<Map.Entry<RawLogMessage, AtomicInteger>> iterator =
         rawLogMessages.entrySet().iterator();
 
@@ -87,14 +88,16 @@ public Collection<RawLogMessage> drain() {
     return list;
   }
 
-  public static class RawLogMessage {
+  public static final class RawLogMessage {
     public final String message;
     public final String logLevel;
     public final Throwable throwable;
     public final String tags;
     public final long timestamp;
     public int count;
 
+    private StackTraceElement[] cachedStackTrace = null;
+
     public RawLogMessage(
         String logLevel, String message, Throwable throwable, String tags, long timestamp) {
       this.logLevel = logLevel;
@@ -104,24 +107,49 @@ public RawLogMessage(
       this.timestamp = timestamp;
     }
 
+    public StackTraceElement[] stackTrace() {
+      if (throwable == null) return null;
+
+      // DQH - getStackTrace makes a defensive copy, so getStackTrace can become a significant
+      // source of allocation
+      // In the worst case of a hot exception, we'll constantly call hashCode & equals to
+      // check against the key stored in the map, so avoiding repeated allocation on each
+      // comparison does provide a measurable gain
+      StackTraceElement[] stackTrace = cachedStackTrace;
+      if (stackTrace != null) return stackTrace;
+
+      cachedStackTrace = stackTrace = throwable.getStackTrace();
+      return stackTrace;
+    }
+
     @Override
     public boolean equals(Object o) {
       if (this == o) return true;
       if (o == null || getClass() != o.getClass()) return false;
       RawLogMessage that = (RawLogMessage) o;
-      return Objects.equals(logLevel, that.logLevel)
-          && Objects.equals(message, that.message)
-          && Objects.equals(
-              throwable == null ? null : throwable.getClass(),
-              that.throwable == null ? null : that.throwable.getClass())
-          && Objects.deepEquals(
-              throwable == null ? null : throwable.getStackTrace(),
-              that.throwable == null ? null : that.throwable.getStackTrace());
+
+      if (!Objects.equals(logLevel, that.logLevel)) return false;
+      if (!Objects.equals(message, that.message)) return false;
+
+      if (throwable == that.throwable) {
+        // DQH - While this path may seem unlikely, it does happen if the JVM fast
+        // throws optimization kicks-in (for NPE, etc), so this case is worth optimizing.
+
+        // This also covers the case where both throwables are null
+        return true;
+      } else if (throwable != null && that.throwable != null) {
+        // Both have a throwable perform a deeper comparison
+        return throwable.getClass().equals(that.throwable.getClass())
+            && Objects.deepEquals(stackTrace(), that.stackTrace());
+      } else {
+        // One has an exception & the other doesn't, not equal
+        return false;
+      }
     }
 
     @Override
     public int hashCode() {
-      return Objects.hash(logLevel, message, throwable == null ? null : throwable.getClass());
+      return HashingUtils.hash(logLevel, message, throwable == null ? null : throwable.getClass());
     }
   }
 }