Add support for tracing the execution time of operations
For some operations we have metrics that record how long the operation
took. For these operations we already record the execution time in the
trace.
However sometimes it is useful to record the execution time of an
operation in a trace without having a metric for this operation. This
change adds support for recording execution times of operations in a
trace without having a metric for it.
E.g.
try (TraceTimer traceTimer =
TraceContext.newTimer("do foo for user %s", user)) {
// do foo
}
adds the following entry to the trace:
do foo for user jdoe took 20ms
If tracing is not enabled this is a no-op.
To demonstrate the new functionality this change records the times the
indexing takes if tracing is enabled.
Change-Id: Iddf4fd78ddfb96965802f95535a264a9c8f8a2ea
Signed-off-by: Edwin Kempin <ekempin@google.com>
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 5397077..3e7bab4 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.
@@ -148,6 +152,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();
