PerformanceMetrics: Suppress redundant logging
Whenever a timer metric is recorded we write a fine log for tracing and
a performance log. In case of the operationsLatency metric this logging
is redundant. It's redundant because fine logging has already been done
when the performance log event to which we are listening is emitted.
Suppressing the performance log also means that we no longer need to
worry about potential cyclic calls, and hence the corresponding check
can be removed.
Signed-off-by: Edwin Kempin <ekempin@google.com>
Change-Id: I2bb9c9f68ec5aee7fd412b9a0e55e7274d1f79db
diff --git a/java/com/google/gerrit/metrics/Timer0.java b/java/com/google/gerrit/metrics/Timer0.java
index 2617431..72ebc67 100644
--- a/java/com/google/gerrit/metrics/Timer0.java
+++ b/java/com/google/gerrit/metrics/Timer0.java
@@ -49,6 +49,8 @@
}
}
+ private boolean suppressLogging;
+
protected final String name;
public Timer0(String name) {
@@ -73,13 +75,23 @@
*/
public final void record(long value, TimeUnit unit) {
long durationMs = unit.toMillis(value);
- LoggingContext.getInstance()
- .addPerformanceLogRecord(() -> PerformanceLogRecord.create(name, durationMs));
- logger.atFinest().log("%s took %dms", name, durationMs);
+
+ if (!suppressLogging) {
+ LoggingContext.getInstance()
+ .addPerformanceLogRecord(() -> PerformanceLogRecord.create(name, durationMs));
+ logger.atFinest().log("%s took %dms", name, durationMs);
+ }
+
doRecord(value, unit);
RequestStateContext.abortIfCancelled();
}
+ /** Suppress logging (debug log and performance log) when values are recorded. */
+ public final Timer0 suppressLogging() {
+ this.suppressLogging = true;
+ return this;
+ }
+
/**
* Record a value in the distribution.
*
diff --git a/java/com/google/gerrit/metrics/Timer1.java b/java/com/google/gerrit/metrics/Timer1.java
index 319f3e0..eefd462 100644
--- a/java/com/google/gerrit/metrics/Timer1.java
+++ b/java/com/google/gerrit/metrics/Timer1.java
@@ -54,6 +54,8 @@
}
}
+ private boolean suppressLogging;
+
protected final String name;
protected final Field<F1> field;
@@ -87,14 +89,22 @@
field.metadataMapper().accept(metadataBuilder, fieldValue);
Metadata metadata = metadataBuilder.build();
- LoggingContext.getInstance()
- .addPerformanceLogRecord(() -> PerformanceLogRecord.create(name, durationMs, metadata));
+ if (!suppressLogging) {
+ LoggingContext.getInstance()
+ .addPerformanceLogRecord(() -> PerformanceLogRecord.create(name, durationMs, metadata));
+ logger.atFinest().log("%s (%s = %s) took %dms", name, field.name(), fieldValue, durationMs);
+ }
- logger.atFinest().log("%s (%s = %s) took %dms", name, field.name(), fieldValue, durationMs);
doRecord(fieldValue, value, unit);
RequestStateContext.abortIfCancelled();
}
+ /** Suppress logging (debug log and performance log) when values are recorded. */
+ public final Timer1<F1> suppressLogging() {
+ this.suppressLogging = true;
+ return this;
+ }
+
/**
* Record a value in the distribution.
*
diff --git a/java/com/google/gerrit/metrics/Timer2.java b/java/com/google/gerrit/metrics/Timer2.java
index 8ae76a2..09878ad 100644
--- a/java/com/google/gerrit/metrics/Timer2.java
+++ b/java/com/google/gerrit/metrics/Timer2.java
@@ -57,6 +57,8 @@
}
}
+ private boolean suppressLogging;
+
protected final String name;
protected final Field<F1> field1;
protected final Field<F2> field2;
@@ -95,16 +97,24 @@
field2.metadataMapper().accept(metadataBuilder, fieldValue2);
Metadata metadata = metadataBuilder.build();
- LoggingContext.getInstance()
- .addPerformanceLogRecord(() -> PerformanceLogRecord.create(name, durationMs, metadata));
+ if (!suppressLogging) {
+ LoggingContext.getInstance()
+ .addPerformanceLogRecord(() -> PerformanceLogRecord.create(name, durationMs, metadata));
+ logger.atFinest().log(
+ "%s (%s = %s, %s = %s) took %dms",
+ name, field1.name(), fieldValue1, field2.name(), fieldValue2, durationMs);
+ }
- logger.atFinest().log(
- "%s (%s = %s, %s = %s) took %dms",
- name, field1.name(), fieldValue1, field2.name(), fieldValue2, durationMs);
doRecord(fieldValue1, fieldValue2, value, unit);
RequestStateContext.abortIfCancelled();
}
+ /** Suppress logging (debug log and performance log) when values are recorded. */
+ public final Timer2<F1, F2> suppressLogging() {
+ this.suppressLogging = true;
+ return this;
+ }
+
/**
* Record a value in the distribution.
*
diff --git a/java/com/google/gerrit/metrics/Timer3.java b/java/com/google/gerrit/metrics/Timer3.java
index 9df963a..5d5c424 100644
--- a/java/com/google/gerrit/metrics/Timer3.java
+++ b/java/com/google/gerrit/metrics/Timer3.java
@@ -60,6 +60,8 @@
}
}
+ private boolean suppressLogging;
+
protected final String name;
protected final Field<F1> field1;
protected final Field<F2> field2;
@@ -104,23 +106,31 @@
field3.metadataMapper().accept(metadataBuilder, fieldValue3);
Metadata metadata = metadataBuilder.build();
- LoggingContext.getInstance()
- .addPerformanceLogRecord(() -> PerformanceLogRecord.create(name, durationMs, metadata));
+ if (!suppressLogging) {
+ LoggingContext.getInstance()
+ .addPerformanceLogRecord(() -> PerformanceLogRecord.create(name, durationMs, metadata));
+ logger.atFinest().log(
+ "%s (%s = %s, %s = %s, %s = %s) took %dms",
+ name,
+ field1.name(),
+ fieldValue1,
+ field2.name(),
+ fieldValue2,
+ field3.name(),
+ fieldValue3,
+ durationMs);
+ }
- logger.atFinest().log(
- "%s (%s = %s, %s = %s, %s = %s) took %dms",
- name,
- field1.name(),
- fieldValue1,
- field2.name(),
- fieldValue2,
- field3.name(),
- fieldValue3,
- durationMs);
doRecord(fieldValue1, fieldValue2, fieldValue3, value, unit);
RequestStateContext.abortIfCancelled();
}
+ /** Suppress logging (debug log and performance log) when values are recorded. */
+ public final Timer3<F1, F2, F3> suppressLogging() {
+ this.suppressLogging = true;
+ return this;
+ }
+
/**
* Record a value in the distribution.
*
diff --git a/java/com/google/gerrit/server/PerformanceMetrics.java b/java/com/google/gerrit/server/PerformanceMetrics.java
index 327da4d..845ed80 100644
--- a/java/com/google/gerrit/server/PerformanceMetrics.java
+++ b/java/com/google/gerrit/server/PerformanceMetrics.java
@@ -57,14 +57,16 @@
.build();
this.operationsLatency =
- metricMaker.newTimer(
- OPERATION_LATENCY_METRIC_NAME,
- new Description("Latency of performing operations")
- .setCumulative()
- .setUnit(Description.Units.MILLISECONDS),
- operationNameField,
- requestField,
- pluginField);
+ metricMaker
+ .newTimer(
+ OPERATION_LATENCY_METRIC_NAME,
+ new Description("Latency of performing operations")
+ .setCumulative()
+ .setUnit(Description.Units.MILLISECONDS),
+ operationNameField,
+ requestField,
+ pluginField)
+ .suppressLogging();
this.operationsCounter =
metricMaker.newCounter(
OPERATION_COUNT_METRIC_NAME,
@@ -81,15 +83,6 @@
@Override
public void log(String operation, long durationMs, @Nullable Metadata metadata) {
- if (OPERATION_LATENCY_METRIC_NAME.equals(operation)) {
- // Recording the timer 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;
- }
-
String requestTag = TraceContext.getTag(TraceRequestListener.TAG_REQUEST).orElse("");
String pluginTag = TraceContext.getPluginTag().orElse("");
operationsLatency.record(operation, requestTag, pluginTag, durationMs, TimeUnit.MILLISECONDS);
