Add more TraceTimers to postUpdate operations that are called on git push
We are investigating a slow git push, where the slowness is caused by
evaluating submit requirments in the synchronous path. From the trace we
see that the submit requirement evaluation is triggered from a
postUpdate step (but we don't know to which op this postUpdate step
belongs, this is getting fixed by change Ie2d70ba4a). When running the
integration tests we can see that the postUpdate from ChangeInserter and
the reviewer ops (AddReviewersOp, DeleteReviewerOp,
DeleteReviewerByEmailOp) is being invoked on git push. It's not obvious
what in the postUpdate steps of these ops may trigger the submit
requirement evaluation. It may be the synchronous sending of emails or
the synchronous firing of events. Add TraceTimers for these so that we
can pinpoint the code that triggers the submit requirement evaluation.
Release-Notes: skip
Bug: Google b/399825642
Change-Id: Id293d3513aea0e202603c93b5faeafedd802dccd
Signed-off-by: Edwin Kempin <ekempin@google.com>
diff --git a/java/com/google/gerrit/server/change/ChangeInserter.java b/java/com/google/gerrit/server/change/ChangeInserter.java
index 366bf1e..3f7b2bb 100644
--- a/java/com/google/gerrit/server/change/ChangeInserter.java
+++ b/java/com/google/gerrit/server/change/ChangeInserter.java
@@ -68,6 +68,9 @@
import com.google.gerrit.server.git.validators.CommitValidationInfoListener;
import com.google.gerrit.server.git.validators.CommitValidators;
import com.google.gerrit.server.git.validators.TopicValidator;
+import com.google.gerrit.server.logging.Metadata;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
import com.google.gerrit.server.mail.EmailFactories;
import com.google.gerrit.server.mail.send.ChangeEmail;
import com.google.gerrit.server.mail.send.MessageIdGenerator;
@@ -644,7 +647,15 @@
Future<?> possiblyIgnoredError =
sendEmailExecutor.submit(requestScopePropagator.wrap(sender));
} else {
- sender.run();
+ try (TraceTimer timer =
+ TraceContext.newTimer(
+ "ChangeInserterSynchronousEmailNotification",
+ Metadata.builder()
+ .projectName(change.getProject().get())
+ .changeId(change.getId().get())
+ .build())) {
+ sender.run();
+ }
}
}
diff --git a/java/com/google/gerrit/server/change/DeleteReviewerByEmailOp.java b/java/com/google/gerrit/server/change/DeleteReviewerByEmailOp.java
index b1395b5..0c280a7 100644
--- a/java/com/google/gerrit/server/change/DeleteReviewerByEmailOp.java
+++ b/java/com/google/gerrit/server/change/DeleteReviewerByEmailOp.java
@@ -22,6 +22,9 @@
import com.google.gerrit.entities.PatchSet;
import com.google.gerrit.extensions.restapi.AuthException;
import com.google.gerrit.server.ChangeMessagesUtil;
+import com.google.gerrit.server.logging.Metadata;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
import com.google.gerrit.server.mail.EmailFactories;
import com.google.gerrit.server.mail.send.ChangeEmail;
import com.google.gerrit.server.mail.send.DeleteReviewerChangeEmailDecorator;
@@ -100,7 +103,16 @@
outgoingEmail.setNotify(notify);
outgoingEmail.setMessageId(
messageIdGenerator.fromChangeUpdate(ctx.getRepoView(), change.currentPatchSetId()));
- outgoingEmail.send();
+
+ try (TraceTimer timer =
+ TraceContext.newTimer(
+ "DeleteReviewerByEmailSynchronousEmailNotification",
+ Metadata.builder()
+ .projectName(change.getProject().get())
+ .changeId(change.getId().get())
+ .build())) {
+ outgoingEmail.send();
+ }
} catch (Exception err) {
logger.atSevere().withCause(err).log("Cannot email update for change %s", change.getId());
}
diff --git a/java/com/google/gerrit/server/change/DeleteReviewerOp.java b/java/com/google/gerrit/server/change/DeleteReviewerOp.java
index 4087f84..a2eb621 100644
--- a/java/com/google/gerrit/server/change/DeleteReviewerOp.java
+++ b/java/com/google/gerrit/server/change/DeleteReviewerOp.java
@@ -39,6 +39,9 @@
import com.google.gerrit.server.account.AccountState;
import com.google.gerrit.server.approval.ApprovalsUtil;
import com.google.gerrit.server.extensions.events.ReviewerDeleted;
+import com.google.gerrit.server.logging.Metadata;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
import com.google.gerrit.server.mail.EmailFactories;
import com.google.gerrit.server.mail.send.ChangeEmail;
import com.google.gerrit.server.mail.send.DeleteReviewerChangeEmailDecorator;
@@ -270,6 +273,15 @@
outgoingEmail.setNotify(notify);
outgoingEmail.setMessageId(
messageIdGenerator.fromChangeUpdate(repoView, change.currentPatchSetId()));
- outgoingEmail.send();
+
+ try (TraceTimer timer =
+ TraceContext.newTimer(
+ "DeleteReviewerSynchronousEmailNotification",
+ Metadata.builder()
+ .projectName(currChange.getProject().get())
+ .changeId(currChange.getId().get())
+ .build())) {
+ outgoingEmail.send();
+ }
}
}
diff --git a/java/com/google/gerrit/server/change/ReviewerModifier.java b/java/com/google/gerrit/server/change/ReviewerModifier.java
index 8a1ed00..f34a673 100644
--- a/java/com/google/gerrit/server/change/ReviewerModifier.java
+++ b/java/com/google/gerrit/server/change/ReviewerModifier.java
@@ -62,6 +62,7 @@
import com.google.gerrit.server.group.SystemGroupBackend;
import com.google.gerrit.server.logging.Metadata;
import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
import com.google.gerrit.server.mail.send.OutgoingEmailValidator;
import com.google.gerrit.server.notedb.ChangeNotes;
import com.google.gerrit.server.permissions.ChangePermission;
@@ -686,9 +687,12 @@
}
public void postUpdate(PostUpdateContext ctx) throws Exception {
- for (ReviewerModification addition : modifications()) {
- if (addition.op != null) {
- addition.op.postUpdate(ctx);
+ try (TraceTimer timer =
+ TraceContext.newTimer("ReviewerMoodifier#postUpdate", Metadata.empty())) {
+ for (ReviewerModification addition : modifications()) {
+ if (addition.op != null) {
+ addition.op.postUpdate(ctx);
+ }
}
}
}
diff --git a/java/com/google/gerrit/server/change/ReviewerOp.java b/java/com/google/gerrit/server/change/ReviewerOp.java
index 12227c2..5bbabdf 100644
--- a/java/com/google/gerrit/server/change/ReviewerOp.java
+++ b/java/com/google/gerrit/server/change/ReviewerOp.java
@@ -24,6 +24,9 @@
import com.google.gerrit.entities.PatchSet;
import com.google.gerrit.entities.PatchSetApproval;
import com.google.gerrit.extensions.restapi.RestApiException;
+import com.google.gerrit.server.logging.Metadata;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
import com.google.gerrit.server.permissions.PermissionBackendException;
import com.google.gerrit.server.update.BatchUpdateOp;
import com.google.gerrit.server.update.ChangeContext;
@@ -49,7 +52,9 @@
}
public void sendEvent() {
- eventSender.run();
+ try (TraceTimer timer = TraceContext.newTimer("ReviewerOp#sendEvent", Metadata.empty())) {
+ eventSender.run();
+ }
}
void setPatchSet(PatchSet patchSet) {
diff --git a/java/com/google/gerrit/server/extensions/events/CommentAdded.java b/java/com/google/gerrit/server/extensions/events/CommentAdded.java
index c6661bd..a3424e6 100644
--- a/java/com/google/gerrit/server/extensions/events/CommentAdded.java
+++ b/java/com/google/gerrit/server/extensions/events/CommentAdded.java
@@ -26,6 +26,9 @@
import com.google.gerrit.extensions.events.CommentAddedListener;
import com.google.gerrit.server.GpgException;
import com.google.gerrit.server.account.AccountState;
+import com.google.gerrit.server.logging.Metadata;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
import com.google.gerrit.server.patch.PatchListNotAvailableException;
import com.google.gerrit.server.patch.PatchListObjectTooLargeException;
import com.google.gerrit.server.permissions.PermissionBackendException;
@@ -62,25 +65,29 @@
if (listeners.isEmpty()) {
return;
}
- try {
- Event event =
- new Event(
- util.changeInfo(changeData),
- util.revisionInfo(changeData.project(), ps),
- util.accountInfo(author),
- comment,
- util.approvals(author, approvals, when),
- util.approvals(author, oldApprovals, when),
- when);
- listeners.runEach(l -> l.onCommentAdded(event));
- } catch (PatchListObjectTooLargeException e) {
- logger.atWarning().log("Couldn't fire event: %s", e.getMessage());
- } catch (PatchListNotAvailableException
- | GpgException
- | IOException
- | StorageException
- | PermissionBackendException e) {
- logger.atSevere().withCause(e).log("Couldn't fire event");
+ try (TraceTimer timer =
+ TraceContext.newTimer(
+ "Fire CommentAdded", Metadata.builder().changeId(changeData.getId().get()).build())) {
+ try {
+ Event event =
+ new Event(
+ util.changeInfo(changeData),
+ util.revisionInfo(changeData.project(), ps),
+ util.accountInfo(author),
+ comment,
+ util.approvals(author, approvals, when),
+ util.approvals(author, oldApprovals, when),
+ when);
+ listeners.runEach(l -> l.onCommentAdded(event));
+ } catch (PatchListObjectTooLargeException e) {
+ logger.atWarning().log("Couldn't fire event: %s", e.getMessage());
+ } catch (PatchListNotAvailableException
+ | GpgException
+ | IOException
+ | StorageException
+ | PermissionBackendException e) {
+ logger.atSevere().withCause(e).log("Couldn't fire event");
+ }
}
}
