BatchUpdate: Add debug logs for slow change updates

Change-Id: Ibc00cf124ee3cb378144a569dcd10242628e19d2

gerrit-server/src/main/java/com/google/gerrit/server/git/BatchUpdate.java

@@ -17,6 +17,9 @@ package com.google.gerrit.server.git;
 import static com.google.common.base.Preconditions.checkArgument;
 import static com.google.common.base.Preconditions.checkNotNull;
 import static com.google.common.base.Preconditions.checkState;
+import static java.util.concurrent.TimeUnit.MILLISECONDS;
+import static java.util.concurrent.TimeUnit.NANOSECONDS;
+import static java.util.concurrent.TimeUnit.SECONDS;
 
 import com.google.common.base.Throwables;
 import com.google.common.collect.ImmutableList;
@@ -41,6 +44,8 @@ import com.google.gerrit.server.CurrentUser;
 import com.google.gerrit.server.GerritPersonIdent;
 import com.google.gerrit.server.IdentifiedUser;
 import com.google.gerrit.server.config.AllUsersName;
+import com.google.gerrit.server.config.ConfigUtil;
+import com.google.gerrit.server.config.GerritServerConfig;
 import com.google.gerrit.server.extensions.events.GitReferenceUpdated;
 import com.google.gerrit.server.index.change.ChangeIndexer;
 import com.google.gerrit.server.notedb.ChangeNotes;
@@ -59,6 +64,7 @@ import com.google.inject.assistedinject.Assisted;
 import com.google.inject.assistedinject.AssistedInject;
 
 import org.eclipse.jgit.lib.BatchRefUpdate;
+import org.eclipse.jgit.lib.Config;
 import org.eclipse.jgit.lib.NullProgressMonitor;
 import org.eclipse.jgit.lib.ObjectInserter;
 import org.eclipse.jgit.lib.ObjectReader;
@@ -463,6 +469,7 @@ public class BatchUpdate implements AutoCloseable {
   private final ReviewDb db;
   private final SchemaFactory<ReviewDb> schemaFactory;
 
+  private final long logThresholdNanos;
   private final Project.NameKey project;
   private final CurrentUser user;
   private final Timestamp when;
@@ -485,6 +492,7 @@ public class BatchUpdate implements AutoCloseable {
 
   @AssistedInject
   BatchUpdate(
+      @GerritServerConfig Config cfg,
       AllUsersName allUsers,
       ChangeControl.GenericFactory changeControlFactory,
       ChangeIndexer indexer,
@@ -513,6 +521,10 @@ public class BatchUpdate implements AutoCloseable {
     this.schemaFactory = schemaFactory;
     this.updateManagerFactory = updateManagerFactory;
 
+    this.logThresholdNanos = MILLISECONDS.toNanos(
+        ConfigUtil.getTimeUnit(
+            cfg, "change", null, "updateDebugLogThreshold",
+            SECONDS.toMillis(2), MILLISECONDS));
     this.db = db;
     this.project = project;
     this.user = user;
@@ -670,10 +682,14 @@ public class BatchUpdate implements AutoCloseable {
         tasks.add(task);
         futures.add(executor.submit(task));
       }
+      long startNanos = System.nanoTime();
       Futures.allAsList(futures).get();
+      maybeLogSlowUpdate(startNanos, "change");
 
       if (notesMigration.commitChangeWrites()) {
+        startNanos = System.nanoTime();
         executeNoteDbUpdates(tasks);
+        maybeLogSlowUpdate(startNanos, "NoteDb");
       }
     } catch (ExecutionException | InterruptedException e) {
       Throwables.propagateIfInstanceOf(e.getCause(), UpdateException.class);
@@ -693,6 +709,25 @@ public class BatchUpdate implements AutoCloseable {
     }
   }
 
+  private static class SlowUpdateException extends Exception {
+    private static final long serialVersionUID = 1L;
+
+    private SlowUpdateException(String fmt, Object... args) {
+      super(String.format(fmt, args));
+    }
+  }
+
+  private void maybeLogSlowUpdate(long startNanos, String desc) {
+    long elapsedNanos = System.nanoTime() - startNanos;
+    if (!log.isDebugEnabled() || elapsedNanos <= logThresholdNanos) {
+      return;
+    }
+    log.debug("Slow " + desc + " update",
+        new SlowUpdateException(
+            "Slow %s update (%d ms) to %s for %s",
+            desc, NANOSECONDS.toMillis(elapsedNanos), project, ops.keySet()));
+  }
+
   private void executeNoteDbUpdates(List<ChangeTask> tasks) {
     // Aggregate together all NoteDb ref updates from the ops we executed,
     // possibly in parallel. Each task had its own NoteDbUpdateManager instance