Merge "Add support for tracing the execution time of operations"
diff --git a/java/com/google/gerrit/server/index/account/AccountIndexerImpl.java b/java/com/google/gerrit/server/index/account/AccountIndexerImpl.java
index b8ececb..27f6caa 100644
--- a/java/com/google/gerrit/server/index/account/AccountIndexerImpl.java
+++ b/java/com/google/gerrit/server/index/account/AccountIndexerImpl.java
@@ -23,6 +23,8 @@
 import com.google.gerrit.reviewdb.client.Account;
 import com.google.gerrit.server.account.AccountCache;
 import com.google.gerrit.server.account.AccountState;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
 import com.google.inject.assistedinject.Assisted;
 import com.google.inject.assistedinject.AssistedInject;
 import java.io.IOException;
@@ -85,9 +87,17 @@
     for (Index<Account.Id, AccountState> i : getWriteIndexes()) {
       // Evict the cache to get an up-to-date value for sure.
       if (accountState.isPresent()) {
-        i.replace(accountState.get());
+        try (TraceTimer traceTimer =
+            TraceContext.newTimer(
+                "Replacing account %d in index version %d", id.get(), i.getSchema().getVersion())) {
+          i.replace(accountState.get());
+        }
       } else {
-        i.delete(id);
+        try (TraceTimer traceTimer =
+            TraceContext.newTimer(
+                "Deleteing account %d in index version %d", id.get(), i.getSchema().getVersion())) {
+          i.delete(id);
+        }
       }
     }
     fireAccountIndexedEvent(id.get());
diff --git a/java/com/google/gerrit/server/index/change/ChangeIndexer.java b/java/com/google/gerrit/server/index/change/ChangeIndexer.java
index 8573862..113d340 100644
--- a/java/com/google/gerrit/server/index/change/ChangeIndexer.java
+++ b/java/com/google/gerrit/server/index/change/ChangeIndexer.java
@@ -33,6 +33,8 @@
 import com.google.gerrit.server.config.GerritServerConfig;
 import com.google.gerrit.server.index.IndexExecutor;
 import com.google.gerrit.server.index.IndexUtils;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
 import com.google.gerrit.server.notedb.ChangeNotes;
 import com.google.gerrit.server.notedb.NotesMigration;
 import com.google.gerrit.server.project.NoSuchChangeException;
@@ -214,7 +216,12 @@
   private void indexImpl(ChangeData cd) throws IOException {
     logger.atInfo().log("Replace change %d in index.", cd.getId().get());
     for (Index<?, ChangeData> i : getWriteIndexes()) {
-      i.replace(cd);
+      try (TraceTimer traceTimer =
+          TraceContext.newTimer(
+              "Replacing change %d in index version %d",
+              cd.getId().get(), i.getSchema().getVersion())) {
+        i.replace(cd);
+      }
     }
     fireChangeIndexedEvent(cd.project().get(), cd.getId().get());
   }
@@ -417,7 +424,11 @@
       // Implementations should not need to access the DB in order to delete a
       // change ID.
       for (ChangeIndex i : getWriteIndexes()) {
-        i.delete(id);
+        try (TraceTimer traceTimer =
+            TraceContext.newTimer(
+                "Deleteing change %d in index version %d", id.get(), i.getSchema().getVersion())) {
+          i.delete(id);
+        }
       }
       fireChangeDeletedFromIndexEvent(id.get());
       return null;
diff --git a/java/com/google/gerrit/server/index/group/GroupIndexerImpl.java b/java/com/google/gerrit/server/index/group/GroupIndexerImpl.java
index 3f4c7be..28e441b 100644
--- a/java/com/google/gerrit/server/index/group/GroupIndexerImpl.java
+++ b/java/com/google/gerrit/server/index/group/GroupIndexerImpl.java
@@ -23,6 +23,8 @@
 import com.google.gerrit.reviewdb.client.AccountGroup;
 import com.google.gerrit.server.account.GroupCache;
 import com.google.gerrit.server.group.InternalGroup;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
 import com.google.inject.assistedinject.Assisted;
 import com.google.inject.assistedinject.AssistedInject;
 import java.io.IOException;
@@ -85,9 +87,17 @@
 
     for (Index<AccountGroup.UUID, InternalGroup> i : getWriteIndexes()) {
       if (internalGroup.isPresent()) {
-        i.replace(internalGroup.get());
+        try (TraceTimer traceTimer =
+            TraceContext.newTimer(
+                "Replacing group %s in index version %d", uuid.get(), i.getSchema().getVersion())) {
+          i.replace(internalGroup.get());
+        }
       } else {
-        i.delete(uuid);
+        try (TraceTimer traceTimer =
+            TraceContext.newTimer(
+                "Deleting group %s in index version %d", uuid.get(), i.getSchema().getVersion())) {
+          i.delete(uuid);
+        }
       }
     }
     fireGroupIndexedEvent(uuid.get());
diff --git a/java/com/google/gerrit/server/index/project/ProjectIndexerImpl.java b/java/com/google/gerrit/server/index/project/ProjectIndexerImpl.java
index f5bf8b5..1ec5d55 100644
--- a/java/com/google/gerrit/server/index/project/ProjectIndexerImpl.java
+++ b/java/com/google/gerrit/server/index/project/ProjectIndexerImpl.java
@@ -24,6 +24,8 @@
 import com.google.gerrit.index.project.ProjectIndexCollection;
 import com.google.gerrit.index.project.ProjectIndexer;
 import com.google.gerrit.reviewdb.client.Project;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
 import com.google.gerrit.server.project.ProjectCache;
 import com.google.gerrit.server.project.ProjectState;
 import com.google.inject.assistedinject.Assisted;
@@ -75,13 +77,23 @@
       logger.atInfo().log("Replace project %s in index", nameKey.get());
       ProjectData projectData = projectState.toProjectData();
       for (ProjectIndex i : getWriteIndexes()) {
-        i.replace(projectData);
+        try (TraceTimer traceTimer =
+            TraceContext.newTimer(
+                "Replacing project %s in index version %d",
+                nameKey.get(), i.getSchema().getVersion())) {
+          i.replace(projectData);
+        }
       }
       fireProjectIndexedEvent(nameKey.get());
     } else {
       logger.atInfo().log("Delete project %s from index", nameKey.get());
       for (ProjectIndex i : getWriteIndexes()) {
-        i.delete(nameKey);
+        try (TraceTimer traceTimer =
+            TraceContext.newTimer(
+                "Deleting project %s in index version %d",
+                nameKey.get(), i.getSchema().getVersion())) {
+          i.delete(nameKey);
+        }
       }
     }
   }
diff --git a/java/com/google/gerrit/server/logging/TraceContext.java b/java/com/google/gerrit/server/logging/TraceContext.java
index 2674b23..977baa5 100644
--- a/java/com/google/gerrit/server/logging/TraceContext.java
+++ b/java/com/google/gerrit/server/logging/TraceContext.java
@@ -16,11 +16,15 @@
 
 import static com.google.common.base.Preconditions.checkNotNull;
 
+import com.google.common.base.Stopwatch;
 import com.google.common.base.Strings;
 import com.google.common.collect.HashBasedTable;
 import com.google.common.collect.Table;
+import com.google.common.flogger.FluentLogger;
 import com.google.gerrit.common.Nullable;
 import java.util.Optional;
+import java.util.concurrent.TimeUnit;
+import java.util.function.Consumer;
 
 /**
  * TraceContext that allows to set logging tags and enforce logging.
@@ -149,6 +153,75 @@
     void accept(String tagName, String traceId);
   }
 
+  /**
+   * Opens a new timer that logs the time for an operation if request tracing is enabled.
+   *
+   * <p>If request tracing is not enabled this is a no-op.
+   *
+   * @param message the message
+   * @return the trace timer
+   */
+  public static TraceTimer newTimer(String message) {
+    return new TraceTimer(message);
+  }
+
+  /**
+   * Opens a new timer that logs the time for an operation if request tracing is enabled.
+   *
+   * <p>If request tracing is not enabled this is a no-op.
+   *
+   * @param format the message format string
+   * @param arg argument for the message
+   * @return the trace timer
+   */
+  public static TraceTimer newTimer(String format, Object arg) {
+    return new TraceTimer(format, arg);
+  }
+
+  /**
+   * Opens a new timer that logs the time for an operation if request tracing is enabled.
+   *
+   * <p>If request tracing is not enabled this is a no-op.
+   *
+   * @param format the message format string
+   * @param arg1 first argument for the message
+   * @param arg2 second argument for the message
+   * @return the trace timer
+   */
+  public static TraceTimer newTimer(String format, Object arg1, Object arg2) {
+    return new TraceTimer(format, arg1, arg2);
+  }
+
+  public static class TraceTimer implements AutoCloseable {
+    private static final FluentLogger logger = FluentLogger.forEnclosingClass();
+
+    private final Consumer<Long> logFn;
+    private final Stopwatch stopwatch;
+
+    private TraceTimer(String message) {
+      this(elapsedMs -> logger.atFine().log(message + " (%d ms)", elapsedMs));
+    }
+
+    private TraceTimer(String format, @Nullable Object arg) {
+      this(elapsedMs -> logger.atFine().log(format + " (%d ms)", arg, elapsedMs));
+    }
+
+    private TraceTimer(String format, @Nullable Object arg1, @Nullable Object arg2) {
+      this(elapsedMs -> logger.atFine().log(format + " (%d ms)", arg1, arg2, elapsedMs));
+    }
+
+    private TraceTimer(Consumer<Long> logFn) {
+      this.logFn = logFn;
+      this.stopwatch = Stopwatch.createStarted();
+    }
+
+    @Override
+    public void close() {
+      stopwatch.stop();
+      logFn.accept(stopwatch.elapsed(TimeUnit.MILLISECONDS));
+    }
+  }
+
   // Table<TAG_NAME, TAG_VALUE, REMOVE_ON_CLOSE>
   private final Table<String, String, Boolean> tags = HashBasedTable.create();