Add debug logs when auto-rebuilding changes in NoteDb

We have aggregate statistics for these, but we have had issues causing
storms of auto-rebuilding (e.g. Ic55a2ce4) and it would be nice to
identify these in the logs as well.

Change-Id: I67aa538e19ec1534e3cae7f96cf9e95c4df237d0

gerrit-server/src/main/java/com/google/gerrit/server/notedb/ChangeNotes.java

@@ -75,6 +75,7 @@ import java.util.HashSet;
 import java.util.List;
 import java.util.Map;
 import java.util.Set;
+import java.util.concurrent.TimeUnit;
 
 /** View of a single {@link Change} based on the log of its notes branch. */
 public class ChangeNotes extends AbstractChangeNotes<ChangeNotes> {
@@ -559,8 +560,8 @@ public class ChangeNotes extends AbstractChangeNotes<ChangeNotes> {
 
   private LoadHandle rebuildAndOpen(Repository repo, ObjectId oldId)
       throws IOException {
-    try (Timer1.Context timer =
+    Timer1.Context timer = args.metrics.autoRebuildLatency.start(CHANGES);
-        args.metrics.autoRebuildLatency.start(CHANGES)) {
+    try {
       Change.Id cid = getChangeId();
       ReviewDb db = args.db.get();
       ChangeRebuilder rebuilder = args.rebuilder.get();
@@ -583,6 +584,7 @@ public class ChangeNotes extends AbstractChangeNotes<ChangeNotes> {
           //
           // Parse notes from the staged result so we can return something useful
           // to the caller instead of throwing.
+          log.debug("Rebuilding change {} failed", getChangeId());
           args.metrics.autoRebuildFailureCount.increment(CHANGES);
           rebuildResult = checkNotNull(r);
           checkNotNull(r.newState());
@@ -599,6 +601,10 @@ public class ChangeNotes extends AbstractChangeNotes<ChangeNotes> {
       return super.openHandle(repo, oldId);
     } catch (OrmException e) {
       throw new IOException(e);
+    } finally {
+      log.debug("Rebuilt change {} in project {} in {} ms",
+          getChangeId(), getProjectName(),
+          TimeUnit.MILLISECONDS.convert(timer.stop(), TimeUnit.NANOSECONDS));
     }
   }
 }

gerrit-server/src/main/java/com/google/gerrit/server/notedb/DraftCommentNotes.java

@@ -43,14 +43,20 @@ import org.eclipse.jgit.lib.Repository;
 import org.eclipse.jgit.notes.NoteMap;
 import org.eclipse.jgit.revwalk.RevCommit;
 import org.eclipse.jgit.transport.ReceiveCommand;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import java.io.IOException;
+import java.util.concurrent.TimeUnit;
 
 /**
  * View of the draft comments for a single {@link Change} based on the log of
  * its drafts branch.
  */
 public class DraftCommentNotes extends AbstractChangeNotes<DraftCommentNotes> {
+  private static final Logger log =
+      LoggerFactory.getLogger(DraftCommentNotes.class);
+
   public interface Factory {
     DraftCommentNotes create(Change change, Account.Id accountId);
     DraftCommentNotes createWithAutoRebuildingDisabled(
@@ -184,8 +190,8 @@ public class DraftCommentNotes extends AbstractChangeNotes<DraftCommentNotes> {
   }
 
   private LoadHandle rebuildAndOpen(Repository repo) throws IOException {
-    try (Timer1.Context timer =
+    Timer1.Context timer = args.metrics.autoRebuildLatency.start(CHANGES);
-        args.metrics.autoRebuildLatency.start(CHANGES)) {
+    try {
       Change.Id cid = getChangeId();
       ReviewDb db = args.db.get();
       ChangeRebuilder rebuilder = args.rebuilder.get();
@@ -200,6 +206,7 @@ public class DraftCommentNotes extends AbstractChangeNotes<DraftCommentNotes> {
           repo.scanForRepoChanges();
         } catch (OrmException | IOException e) {
           // See ChangeNotes#rebuildAndOpen.
+          log.debug("Rebuilding change {} via drafts failed", getChangeId());
           args.metrics.autoRebuildFailureCount.increment(CHANGES);
           checkNotNull(r.staged());
           return LoadHandle.create(
@@ -213,6 +220,13 @@ public class DraftCommentNotes extends AbstractChangeNotes<DraftCommentNotes> {
       return super.openHandle(repo);
     } catch (OrmException e) {
       throw new IOException(e);
+    } finally {
+      log.debug("Rebuilt change {} in {} in {} ms via drafts",
+          getChangeId(),
+          change != null
+              ? "project " + change.getProject()
+              : "unknown project",
+          TimeUnit.MILLISECONDS.convert(timer.stop(), TimeUnit.NANOSECONDS));
     }
   }