Add a performance logger that records the execution times as a metric
This makes the execution times for operations (steps executed in order
to serve a request) available as a metric, so that they can be observed
more easily (e.g. to check if they become better/worse over time). This
allows us to detect performance regressions more easily.
Signed-off-by: Edwin Kempin <ekempin@google.com>
Change-Id: I7d067b0658401ffaeedd63970ab577e2a027f1c7
diff --git a/Documentation/metrics.txt b/Documentation/metrics.txt
index e84a698..5224ae9 100644
--- a/Documentation/metrics.txt
+++ b/Documentation/metrics.txt
@@ -31,6 +31,11 @@
* `cancellation/receive_timeout_count`: Number of requests that are cancelled
because link:config.html#receive.timeout[receive.timout] is exceeded
+[[performance]]
+=== Performance
+
+* `performance/operations`: Latency of performing operations
+
=== Pushes
* `receivecommits/changes`: histogram of number of changes processed
diff --git a/java/com/google/gerrit/server/PerformanceMetrics.java b/java/com/google/gerrit/server/PerformanceMetrics.java
new file mode 100644
index 0000000..91feebd
--- /dev/null
+++ b/java/com/google/gerrit/server/PerformanceMetrics.java
@@ -0,0 +1,88 @@
+// Copyright (C) 2021 The Android Open Source Project
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package com.google.gerrit.server;
+
+import com.google.gerrit.common.Nullable;
+import com.google.gerrit.metrics.Description;
+import com.google.gerrit.metrics.Field;
+import com.google.gerrit.metrics.MetricMaker;
+import com.google.gerrit.metrics.Timer3;
+import com.google.gerrit.server.logging.Metadata;
+import com.google.gerrit.server.logging.PerformanceLogger;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.inject.Inject;
+import com.google.inject.Singleton;
+import java.util.concurrent.TimeUnit;
+
+/** Performance logger that records the execution times as a metric. */
+@Singleton
+public class PerformanceMetrics implements PerformanceLogger {
+ private static final String OPERATION_LATENCY_METRIC_NAME = "performance/operations";
+
+ public final Timer3<String, String, String> operationsLatency;
+
+ @Inject
+ PerformanceMetrics(MetricMaker metricMaker) {
+ this.operationsLatency =
+ metricMaker.newTimer(
+ OPERATION_LATENCY_METRIC_NAME,
+ new Description("Latency of performing operations")
+ .setCumulative()
+ .setUnit(Description.Units.MILLISECONDS),
+ Field.ofString(
+ "operation_name",
+ (metadataBuilder, fieldValue) -> metadataBuilder.operationName(fieldValue))
+ .build(),
+ Field.ofString("change_identifier", (metadataBuilder, fieldValue) -> {}).build(),
+ Field.ofString("trace_id", (metadataBuilder, fieldValue) -> {}).build());
+ }
+
+ @Override
+ public void log(String operation, long durationMs) {
+ log(operation, durationMs, /* metadata= */ null);
+ }
+
+ @Override
+ public void log(String operation, long durationMs, @Nullable Metadata metadata) {
+ if (OPERATION_LATENCY_METRIC_NAME.equals(operation)) {
+ // Recording the metric below triggers writing a performance log entry. If we are called for
+ // this performance log entry we must abort to avoid an endless loop.
+ // In practice this should not happen since PerformanceLoggers are only called on close() of
+ // the PerformanceLogContext, and hence the performance log that gets written by the metric
+ // below gets ignored.
+ return;
+ }
+
+ operationsLatency.record(
+ operation,
+ formatChangeIdentifier(metadata),
+ TraceContext.getTraceId().orElse(""),
+ durationMs,
+ TimeUnit.MILLISECONDS);
+ }
+
+ private String formatChangeIdentifier(@Nullable Metadata metadata) {
+ if (metadata == null
+ || (!metadata.projectName().isPresent() && !metadata.changeId().isPresent())) {
+ return "";
+ }
+
+ StringBuilder sb = new StringBuilder();
+ sb.append(metadata.projectName().orElse("n/a"));
+ sb.append('~');
+ sb.append(metadata.changeId().map(String::valueOf).orElse("n/a"));
+ return sb.toString();
+ }
+}
diff --git a/java/com/google/gerrit/server/config/GerritGlobalModule.java b/java/com/google/gerrit/server/config/GerritGlobalModule.java
index ef1c0ae..35b16b4 100644
--- a/java/com/google/gerrit/server/config/GerritGlobalModule.java
+++ b/java/com/google/gerrit/server/config/GerritGlobalModule.java
@@ -85,6 +85,7 @@
import com.google.gerrit.server.ExceptionHookImpl;
import com.google.gerrit.server.ExternalUser;
import com.google.gerrit.server.IdentifiedUser;
+import com.google.gerrit.server.PerformanceMetrics;
import com.google.gerrit.server.RequestListener;
import com.google.gerrit.server.TraceRequestListener;
import com.google.gerrit.server.account.AccountCacheImpl;
@@ -431,6 +432,7 @@
DynamicSet.setOf(binder(), SubmitRule.class);
DynamicSet.setOf(binder(), QuotaEnforcer.class);
DynamicSet.setOf(binder(), PerformanceLogger.class);
+ DynamicSet.bind(binder(), PerformanceLogger.class).to(PerformanceMetrics.class);
DynamicSet.setOf(binder(), RequestListener.class);
DynamicSet.bind(binder(), RequestListener.class).to(TraceRequestListener.class);
DynamicSet.setOf(binder(), ChangeETagComputation.class);
diff --git a/javatests/com/google/gerrit/server/logging/PerformanceLogContextTest.java b/javatests/com/google/gerrit/server/logging/PerformanceLogContextTest.java
index ed4325d..fefa066 100644
--- a/javatests/com/google/gerrit/server/logging/PerformanceLogContextTest.java
+++ b/javatests/com/google/gerrit/server/logging/PerformanceLogContextTest.java
@@ -34,6 +34,7 @@
import com.google.inject.Injector;
import java.util.ArrayList;
import java.util.List;
+import java.util.concurrent.CopyOnWriteArrayList;
import org.eclipse.jgit.lib.Config;
import org.junit.After;
import org.junit.Before;
@@ -110,9 +111,10 @@
@Test
public void
- traceTimersInsidePerformanceLogContextDoNotCreatePerformanceLogIfNoPerformanceLoggers() {
+ traceTimersInsidePerformanceLogContextDoNotCreatePerformanceLogIfNoPerformanceLoggers()
+ throws Exception {
// Remove test performance logger so that there are no registered performance loggers.
- performanceLoggerRegistrationHandle.remove();
+ removeAllPerformanceLoggers();
assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
@@ -277,9 +279,10 @@
@Test
public void
- timerMetricssInsidePerformanceLogContextDoNotCreatePerformanceLogIfNoPerformanceLoggers() {
- // Remove test performance logger so that there are no registered performance loggers.
- performanceLoggerRegistrationHandle.remove();
+ timerMetricssInsidePerformanceLogContextDoNotCreatePerformanceLogIfNoPerformanceLoggers()
+ throws Exception {
+ // Remove all performance loggers so that there are no registered performance loggers.
+ removeAllPerformanceLoggers();
assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
@@ -369,6 +372,12 @@
}
}
+ private void removeAllPerformanceLoggers() throws Exception {
+ java.lang.reflect.Field itemsField = DynamicSet.class.getDeclaredField("items");
+ itemsField.setAccessible(true);
+ ((CopyOnWriteArrayList<?>) itemsField.get(performanceLoggers)).clear();
+ }
+
@AutoValue
abstract static class PerformanceLogEntry {
static PerformanceLogEntry create(String operation, Metadata metadata) {
