Include timer metrics into trace

This allows us to see from a trace how long operations took that are
captured by timer metrics.

Example log entry on push:
[2018-08-29 10:28:37,080] [ReceiveCommits-1] TRACE com.google.gerrit.metrics.Timer0.Context : http/server/rest_api/change_json/to_change_info_latency took 24ms [CONTEXT forced=true RECEIVE_ID="foo-1535531316769-7edf2a7b" TRACE_ID="1535531316773-7edf2a7b" ]

Change-Id: Ib0024cce95693d99781aee8a2b78b777c7c4ce3b
Signed-off-by: Edwin Kempin <ekempin@google.com>

Documentation/user-request-tracing.txt

@@ -58,4 +58,5 @@ that correspond to the request can be found.
 * index queries (with parameters and matches)
 * reindex events
 * permission checks (e.g. which rule is responsible for a deny)
+* timer metrics
 * all other logs

java/com/google/gerrit/metrics/DisabledMetricMaker.java

@@ -68,7 +68,7 @@ public class DisabledMetricMaker extends MetricMaker {
 
   @Override
   public Timer0 newTimer(String name, Description desc) {
-    return new Timer0() {
+    return new Timer0(name) {
       @Override
       public void record(long value, TimeUnit unit) {}
 
@@ -79,7 +79,7 @@ public class DisabledMetricMaker extends MetricMaker {
 
   @Override
   public <F1> Timer1<F1> newTimer(String name, Description desc, Field<F1> field1) {
-    return new Timer1<F1>() {
+    return new Timer1<F1>(name) {
       @Override
       public void record(F1 field1, long value, TimeUnit unit) {}
 
@@ -91,7 +91,7 @@ public class DisabledMetricMaker extends MetricMaker {
   @Override
   public <F1, F2> Timer2<F1, F2> newTimer(
       String name, Description desc, Field<F1> field1, Field<F2> field2) {
-    return new Timer2<F1, F2>() {
+    return new Timer2<F1, F2>(name) {
       @Override
       public void record(F1 field1, F2 field2, long value, TimeUnit unit) {}
 
@@ -103,7 +103,7 @@ public class DisabledMetricMaker extends MetricMaker {
   @Override
   public <F1, F2, F3> Timer3<F1, F2, F3> newTimer(
       String name, Description desc, Field<F1> field1, Field<F2> field2, Field<F3> field3) {
-    return new Timer3<F1, F2, F3>() {
+    return new Timer3<F1, F2, F3>(name) {
       @Override
       public void record(F1 field1, F2 field2, F3 field3, long value, TimeUnit unit) {}
 

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

@@ -16,6 +16,7 @@ package com.google.gerrit.metrics;
 
 import static java.util.concurrent.TimeUnit.NANOSECONDS;
 
+import com.google.common.flogger.FluentLogger;
 import com.google.gerrit.extensions.registration.RegistrationHandle;
 import java.util.concurrent.TimeUnit;
 
@@ -31,6 +32,8 @@ import java.util.concurrent.TimeUnit;
  */
 public abstract class Timer0 implements RegistrationHandle {
   public static class Context extends TimerContext {
+    private static final FluentLogger logger = FluentLogger.forEnclosingClass();
+
     private final Timer0 timer;
 
     Context(Timer0 timer) {
@@ -39,10 +42,17 @@ public abstract class Timer0 implements RegistrationHandle {
 
     @Override
     public void record(long elapsed) {
+      logger.atFinest().log("%s took %dms", timer.name, TimeUnit.NANOSECONDS.toMillis(elapsed));
       timer.record(elapsed, NANOSECONDS);
     }
   }
 
+  protected final String name;
+
+  public Timer0(String name) {
+    this.name = name;
+  }
+
   /**
    * Begin a timer for the current block, value will be recorded when closed.
    *

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

@@ -16,6 +16,7 @@ package com.google.gerrit.metrics;
 
 import static java.util.concurrent.TimeUnit.NANOSECONDS;
 
+import com.google.common.flogger.FluentLogger;
 import com.google.gerrit.extensions.registration.RegistrationHandle;
 import java.util.concurrent.TimeUnit;
 
@@ -33,6 +34,8 @@ import java.util.concurrent.TimeUnit;
  */
 public abstract class Timer1<F1> implements RegistrationHandle {
   public static class Context extends TimerContext {
+    private static final FluentLogger logger = FluentLogger.forEnclosingClass();
+
     private final Timer1<Object> timer;
     private final Object field1;
 
@@ -44,10 +47,18 @@ public abstract class Timer1<F1> implements RegistrationHandle {
 
     @Override
     public void record(long elapsed) {
+      logger.atFinest().log(
+          "%s (%s) took %dms", timer.name, field1, TimeUnit.NANOSECONDS.toMillis(elapsed));
       timer.record(field1, elapsed, NANOSECONDS);
     }
   }
 
+  protected final String name;
+
+  public Timer1(String name) {
+    this.name = name;
+  }
+
   /**
    * Begin a timer for the current block, value will be recorded when closed.
    *

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

@@ -16,6 +16,7 @@ package com.google.gerrit.metrics;
 
 import static java.util.concurrent.TimeUnit.NANOSECONDS;
 
+import com.google.common.flogger.FluentLogger;
 import com.google.gerrit.extensions.registration.RegistrationHandle;
 import java.util.concurrent.TimeUnit;
 
@@ -34,6 +35,8 @@ import java.util.concurrent.TimeUnit;
  */
 public abstract class Timer2<F1, F2> implements RegistrationHandle {
   public static class Context extends TimerContext {
+    private static final FluentLogger logger = FluentLogger.forEnclosingClass();
+
     private final Timer2<Object, Object> timer;
     private final Object field1;
     private final Object field2;
@@ -47,10 +50,19 @@ public abstract class Timer2<F1, F2> implements RegistrationHandle {
 
     @Override
     public void record(long elapsed) {
+      logger.atFinest().log(
+          "%s (%s, %s) took %dms",
+          timer.name, field1, field2, TimeUnit.NANOSECONDS.toMillis(elapsed));
       timer.record(field1, field2, elapsed, NANOSECONDS);
     }
   }
 
+  protected final String name;
+
+  public Timer2(String name) {
+    this.name = name;
+  }
+
   /**
    * Begin a timer for the current block, value will be recorded when closed.
    *

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

@@ -16,6 +16,7 @@ package com.google.gerrit.metrics;
 
 import static java.util.concurrent.TimeUnit.NANOSECONDS;
 
+import com.google.common.flogger.FluentLogger;
 import com.google.gerrit.extensions.registration.RegistrationHandle;
 import java.util.concurrent.TimeUnit;
 
@@ -35,6 +36,8 @@ import java.util.concurrent.TimeUnit;
  */
 public abstract class Timer3<F1, F2, F3> implements RegistrationHandle {
   public static class Context extends TimerContext {
+    private static final FluentLogger logger = FluentLogger.forEnclosingClass();
+
     private final Timer3<Object, Object, Object> timer;
     private final Object field1;
     private final Object field2;
@@ -50,10 +53,19 @@ public abstract class Timer3<F1, F2, F3> implements RegistrationHandle {
 
     @Override
     public void record(long elapsed) {
+      logger.atFinest().log(
+          "%s (%s, %s, %s) took %dms",
+          timer.name, field1, field2, field3, TimeUnit.NANOSECONDS.toMillis(elapsed));
       timer.record(field1, field2, field3, elapsed, NANOSECONDS);
     }
   }
 
+  protected final String name;
+
+  public Timer3(String name) {
+    this.name = name;
+  }
+
   /**
    * Begin a timer for the current block, value will be recorded when closed.
    *

java/com/google/gerrit/metrics/dropwizard/BucketedTimer.java

@@ -26,7 +26,7 @@ import java.util.concurrent.ConcurrentHashMap;
 /** Abstract timer broken down into buckets by {@link Field} values. */
 abstract class BucketedTimer implements BucketedMetric {
   private final DropWizardMetricMaker metrics;
-  private final String name;
+  protected final String name;
   private final Description.FieldOrdering ordering;
   protected final Field<?>[] fields;
   protected final TimerImpl total;

java/com/google/gerrit/metrics/dropwizard/DropWizardMetricMaker.java

@@ -393,11 +393,10 @@ public class DropWizardMetricMaker extends MetricMaker {
   }
 
   class TimerImpl extends Timer0 {
-    private final String name;
     final com.codahale.metrics.Timer metric;
 
     private TimerImpl(String name, com.codahale.metrics.Timer metric) {
-      this.name = name;
+      super(name);
       this.metric = metric;
     }
 

java/com/google/gerrit/metrics/dropwizard/TimerImpl1.java

@@ -27,7 +27,7 @@ class TimerImpl1<F1> extends BucketedTimer implements BucketedMetric {
   }
 
   Timer1<F1> timer() {
-    return new Timer1<F1>() {
+    return new Timer1<F1>(name) {
       @Override
       public void record(F1 field1, long value, TimeUnit unit) {
         total.record(value, unit);

java/com/google/gerrit/metrics/dropwizard/TimerImplN.java

@@ -30,7 +30,7 @@ class TimerImplN extends BucketedTimer implements BucketedMetric {
   }
 
   <F1, F2> Timer2<F1, F2> timer2() {
-    return new Timer2<F1, F2>() {
+    return new Timer2<F1, F2>(name) {
       @Override
       public void record(F1 field1, F2 field2, long value, TimeUnit unit) {
         total.record(value, unit);
@@ -45,7 +45,7 @@ class TimerImplN extends BucketedTimer implements BucketedMetric {
   }
 
   <F1, F2, F3> Timer3<F1, F2, F3> timer3() {
-    return new Timer3<F1, F2, F3>() {
+    return new Timer3<F1, F2, F3>(name) {
       @Override
       public void record(F1 field1, F2 field2, F3 field3, long value, TimeUnit unit) {
         total.record(value, unit);