commit 6a269396297753d5c50076d3a88d947d311f3deb
author Edwin Kempin <ekempin@google.com> Thu Aug 01 13:42:07 2024 +0000
committer Gerrit Code Review <noreply-gerritcodereview@google.com> Thu Aug 01 13:42:07 2024 +0000
tree 9581c30f8750b30ddfa2edb524e4c698f517aca0
parent cd4b18187de1b659a9eaf9fbdea5afdaed20f8df
parent 881a979b1a0f99bb64b95e167fc889d9b751ccaa

Merge changes I354e3908,I35130071

* changes:
  TraceContext: Make wording of end log consistent with Timer metrics
  Write debug log when timer metric is started

java/com/google/gerrit/metrics/Timer0.java

diff --git a/java/com/google/gerrit/metrics/Timer0.java b/java/com/google/gerrit/metrics/Timer0.java
index a18a6ed..ac390f5 100644
--- a/java/com/google/gerrit/metrics/Timer0.java
+++ b/java/com/google/gerrit/metrics/Timer0.java
@@ -64,6 +64,9 @@
    */
   public Context start() {
     RequestStateContext.abortIfCancelled();
+    if (!suppressLogging) {
+      logger.atFine().log("Starting timer %s", name);
+    }
     return new Context(this);
   }
 

java/com/google/gerrit/metrics/Timer1.java

diff --git a/java/com/google/gerrit/metrics/Timer1.java b/java/com/google/gerrit/metrics/Timer1.java
index cdf457c..04d6247 100644
--- a/java/com/google/gerrit/metrics/Timer1.java
+++ b/java/com/google/gerrit/metrics/Timer1.java
@@ -72,6 +72,9 @@
    */
   public Context<F1> start(F1 fieldValue) {
     RequestStateContext.abortIfCancelled();
+    if (!suppressLogging) {
+      logger.atFine().log("Starting timer %s (%s = %s)", name, field.name(), fieldValue);
+    }
     return new Context<>(this, fieldValue);
   }
 

java/com/google/gerrit/metrics/Timer2.java

diff --git a/java/com/google/gerrit/metrics/Timer2.java b/java/com/google/gerrit/metrics/Timer2.java
index 9f08711..f526f05 100644
--- a/java/com/google/gerrit/metrics/Timer2.java
+++ b/java/com/google/gerrit/metrics/Timer2.java
@@ -78,6 +78,11 @@
    */
   public Context<F1, F2> start(F1 fieldValue1, F2 fieldValue2) {
     RequestStateContext.abortIfCancelled();
+    if (!suppressLogging) {
+      logger.atFine().log(
+          "Starting timer %s (%s = %s, %s = %s)",
+          name, field1.name(), fieldValue1, field2.name(), fieldValue2);
+    }
     return new Context<>(this, fieldValue1, fieldValue2);
   }
 

java/com/google/gerrit/metrics/Timer3.java

diff --git a/java/com/google/gerrit/metrics/Timer3.java b/java/com/google/gerrit/metrics/Timer3.java
index 2a01d5d..1735dc8 100644
--- a/java/com/google/gerrit/metrics/Timer3.java
+++ b/java/com/google/gerrit/metrics/Timer3.java
@@ -84,6 +84,11 @@
    */
   public Context<F1, F2, F3> start(F1 fieldValue1, F2 fieldValue2, F3 fieldValue3) {
     RequestStateContext.abortIfCancelled();
+    if (!suppressLogging) {
+      logger.atFine().log(
+          "Starting timer %s (%s = %s, %s = %s, %s = %s)",
+          name, field1.name(), fieldValue1, field2.name(), fieldValue2, field3.name(), fieldValue3);
+    }
     return new Context<>(this, fieldValue1, fieldValue2, fieldValue3);
   }
 

java/com/google/gerrit/server/logging/TraceContext.java

diff --git a/java/com/google/gerrit/server/logging/TraceContext.java b/java/com/google/gerrit/server/logging/TraceContext.java
index 284ddf5..3213422 100644
--- a/java/com/google/gerrit/server/logging/TraceContext.java
+++ b/java/com/google/gerrit/server/logging/TraceContext.java
@@ -187,12 +187,12 @@
 
     private TraceTimer(String operation) {
       this(
-          () -> logger.atFine().log("Starting timer for %s", operation),
+          () -> logger.atFine().log("Starting timer %s", operation),
           elapsedNanos -> {
             LoggingContext.getInstance()
                 .addPerformanceLogRecord(
                     () -> PerformanceLogRecord.create(operation, elapsedNanos));
-            logger.atFine().log("%s done (%.2f ms)", operation, elapsedNanos / 1000000.0);
+            logger.atFine().log("timer %s took %.2f ms", operation, elapsedNanos / 1000000.0);
           });
     }
 
@@ -200,13 +200,13 @@
       this(
           () ->
               logger.atFine().log(
-                  "Starting timer for %s (%s)", operation, metadata.toStringForLogging()),
+                  "Starting timer %s (%s)", operation, metadata.toStringForLogging()),
           elapsedNanos -> {
             LoggingContext.getInstance()
                 .addPerformanceLogRecord(
                     () -> PerformanceLogRecord.create(operation, elapsedNanos, metadata));
             logger.atFine().log(
-                "%s (%s) done (%.2f ms)",
+                "timer %s (%s) took %.2f ms",
                 operation, metadata.toStringForLogging(), elapsedNanos / 1000000.0);
           });
     }