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();