Fix performance bug in logging: Avoid expensive stack trace/reflection

This shows significant resource usage for Flume jobs in pprof. It might
also improve performance in the frontend.

Also rename LazyArg-s for clarity, and to avoid the impression that use
of non-lazy args for logging is OK.

Change-Id: Ibd60407c5c87e79bdadd4546cb0c7bbd5b72156d

java/com/google/gerrit/index/query/QueryProcessor.java

@@ -218,7 +218,7 @@ public abstract class QueryProcessor<T> {
 
     logger.atFine().log(
         "Executing %d %s index queries for %s",
-        cnt, schemaDef.getName(), callerFinder.findCaller());
+        cnt, schemaDef.getName(), callerFinder.findCallerLazy());
     List<QueryResult<T>> out;
     try {
       // Parse and rewrite all queries.

java/com/google/gerrit/server/account/externalids/ExternalIdNotes.java

@@ -675,7 +675,8 @@ public class ExternalIdNotes extends VersionedMetaData {
   @Override
   protected void onLoad() throws IOException, ConfigInvalidException {
     if (revision != null) {
-      logger.atFine().log("Reading external ID note map (caller: %s)", callerFinder.findCaller());
+      logger.atFine().log(
+          "Reading external ID note map (caller: %s)", callerFinder.findCallerLazy());
       noteMap = NoteMap.read(reader, revision);
     } else {
       noteMap = NoteMap.newEmptyMap();

java/com/google/gerrit/server/logging/CallerFinder.java

@@ -142,7 +142,7 @@ public abstract class CallerFinder {
 
   /**
    * The minimum number of calls known to have occurred between the first call to the target class
-   * and the call of {@link #findCaller()}. If in doubt, specify zero here to avoid accidentally
+   * and the call of {@link #findCallerLazy()}. If in doubt, specify zero here to avoid accidentally
    * skipping past the caller.
    *
    * @return the number of stack elements to skip when computing the caller
@@ -195,7 +195,7 @@ public abstract class CallerFinder {
     public abstract CallerFinder build();
   }
 
-  public LazyArg<String> findCaller() {
+  public LazyArg<String> findCallerLazy() {
     return lazy(
         () ->
             targets().stream()

java/com/google/gerrit/server/logging/Metadata.java

@@ -18,11 +18,14 @@ import com.google.auto.value.AutoValue;
 import com.google.common.base.MoreObjects;
 import com.google.common.base.MoreObjects.ToStringHelper;
 import com.google.common.collect.ImmutableList;
+import com.google.common.flogger.LazyArg;
+import com.google.common.flogger.LazyArgs;
 import com.google.gerrit.common.Nullable;
 import java.lang.reflect.InvocationTargetException;
 import java.lang.reflect.Method;
 import java.lang.reflect.Modifier;
 import java.util.Arrays;
+import java.util.Comparator;
 import java.util.Optional;
 
 /** Metadata that is provided to {@link PerformanceLogger}s as context for performance records. */
@@ -141,7 +144,8 @@ public abstract class Metadata {
   public abstract Optional<String> username();
 
   /**
-   * Returns a string representation of this instance that is suitable for logging.
+   * Returns a string representation of this instance that is suitable for logging. This is wrapped
+   * in a {@link LazyArg<String>} because it is expensive to evaluate.
    *
    * <p>{@link #toString()} formats the {@link Optional} fields as {@code key=Optional[value]} or
    * {@code key=Optional.empty}. Since this class has many optional fields from which usually only a
@@ -178,7 +182,9 @@ public abstract class Metadata {
    *
    * @return string representation of this instance that is suitable for logging
    */
-  public String toStringForLogging() {
+  LazyArg<String> toStringForLoggingLazy() {
+    return LazyArgs.lazy(
+        () -> {
           // Append class name.
           String className = getClass().getSimpleName();
           if (className.startsWith("AutoValue_")) {
@@ -188,15 +194,15 @@ public abstract class Metadata {
 
           // Append key-value pairs for field which are set.
           Method[] methods = Metadata.class.getDeclaredMethods();
-    Arrays.<Method>sort(methods, (m1, m2) -> m1.getName().compareTo(m2.getName()));
+          Arrays.sort(methods, Comparator.comparing(Method::getName));
           for (Method method : methods) {
             if (Modifier.isStatic(method.getModifiers())) {
               // skip static method
               continue;
             }
 
-      if (method.getName().equals(Thread.currentThread().getStackTrace()[1].getMethodName())) {
-        // skip this method (toStringForLogging() method)
+            if (method.getName().matches("(lambda\\$)?toStringForLoggingLazy(\\$0)?")) {
+              // skip toStringForLoggingLazy() and the lambda itself
               continue;
             }
 
@@ -210,7 +216,9 @@ public abstract class Metadata {
             Object returnValue;
             try {
               returnValue = method.invoke(this);
-      } catch (IllegalArgumentException | IllegalAccessException | InvocationTargetException e) {
+            } catch (IllegalArgumentException
+                | IllegalAccessException
+                | InvocationTargetException e) {
               // should never happen
               throw new IllegalStateException(e);
             }
@@ -231,6 +239,7 @@ public abstract class Metadata {
           }
 
           return stringHelper.toString();
+        });
   }
 
   public static Metadata.Builder builder() {

java/com/google/gerrit/server/logging/TraceContext.java

@@ -196,13 +196,13 @@ public class TraceContext implements AutoCloseable {
       this(
           () ->
               logger.atFine().log(
-                  "Starting timer for %s (%s)", operation, metadata.toStringForLogging()),
+                  "Starting timer for %s (%s)", operation, metadata.toStringForLoggingLazy()),
           elapsedMs -> {
             LoggingContext.getInstance()
                 .addPerformanceLogRecord(
                     () -> PerformanceLogRecord.create(operation, elapsedMs, metadata));
             logger.atFine().log(
-                "%s (%s) done (%d ms)", operation, metadata.toStringForLogging(), elapsedMs);
+                "%s (%s) done (%d ms)", operation, metadata.toStringForLoggingLazy(), elapsedMs);
           });
     }
 

java/com/google/gerrit/server/permissions/RefControl.java

@@ -395,7 +395,7 @@ class RefControl {
           withForce,
           projectControl.getProject().getName(),
           refName,
-          callerFinder.findCaller());
+          callerFinder.findCallerLazy());
       return false;
     }
 
@@ -408,7 +408,7 @@ class RefControl {
             withForce,
             projectControl.getProject().getName(),
             refName,
-            callerFinder.findCaller());
+            callerFinder.findCallerLazy());
         return true;
       }
     }
@@ -420,7 +420,7 @@ class RefControl {
         withForce,
         projectControl.getProject().getName(),
         refName,
-        callerFinder.findCaller());
+        callerFinder.findCallerLazy());
     return false;
   }
 

javatests/com/google/gerrit/server/logging/MetadataTest.java

@@ -23,7 +23,7 @@ public class MetadataTest {
   @Test
   public void stringForLoggingOmitsEmptyOptionalValuesAndReformatsOptionalValuesThatArePresent() {
     Metadata metadata = Metadata.builder().accountId(1000001).branchName("refs/heads/foo").build();
-    assertThat(metadata.toStringForLogging())
+    assertThat(metadata.toStringForLoggingLazy().evaluate())
         .isEqualTo("Metadata{accountId=1000001, branchName=refs/heads/foo, pluginMetadata=[]}");
   }
 
@@ -31,6 +31,7 @@ public class MetadataTest {
   public void
       stringForLoggingOmitsEmptyOptionalValuesAndReformatsOptionalValuesThatArePresentNoFieldsSet() {
     Metadata metadata = Metadata.builder().build();
-    assertThat(metadata.toStringForLogging()).isEqualTo("Metadata{pluginMetadata=[]}");
+    assertThat(metadata.toStringForLoggingLazy().evaluate())
+        .isEqualTo("Metadata{pluginMetadata=[]}");
   }
 }