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) {