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

// Copyright (C) 2015 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.metrics;

import static java.util.concurrent.TimeUnit.NANOSECONDS;

import com.google.common.collect.ImmutableList;
import com.google.common.flogger.FluentLogger;
import com.google.gerrit.extensions.registration.RegistrationHandle;
import com.google.gerrit.server.cancellation.RequestStateContext;
import com.google.gerrit.server.logging.LoggingContext;
import com.google.gerrit.server.logging.Metadata;
import com.google.gerrit.server.logging.PerformanceLogRecord;
import java.util.concurrent.TimeUnit;

/**
 * Records elapsed time for an operation or span.
 *
 * <p>Typical usage in a try-with-resources block:
 *
 * <pre>
 * try (Timer1.Context ctx = timer.start(field)) {
 * }
 * </pre>
 *
 * @param <F1> type of the field.
 */
public abstract class Timer1<F1> implements RegistrationHandle {
  private static final FluentLogger logger = FluentLogger.forEnclosingClass();

  public static class Context<F1> extends TimerContext {
    private final Timer1<F1> timer;
    private final F1 fieldValue;

    Context(Timer1<F1> timer, Metadata metadata, F1 fieldValue) {
      super(timer.name, metadata);
      this.timer = timer;
      this.fieldValue = fieldValue;
    }

    @Override
    public void record(long elapsed, ImmutableList<String> parentOperations, Metadata metadata) {
      timer.record(fieldValue, elapsed, NANOSECONDS, parentOperations, metadata);
    }
  }

  private boolean suppressLogging;

  protected final String name;
  protected final Field<F1> field;

  public Timer1(String name, Field<F1> field) {
    this.name = name;
    this.field = field;
  }

  /**
   * Begin a timer for the current block, value will be recorded when closed.
   *
   * @param fieldValue bucket to record the timer
   * @return timer context
   */
  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, getMetadata(fieldValue), fieldValue);
  }

  /**
   * Record a value in the distribution.
   *
   * @param fieldValue bucket to record the timer
   * @param value value to record
   * @param unit time unit of the value
   */
  public final void record(F1 fieldValue, long value, TimeUnit unit) {
    record(
        fieldValue,
        value,
        unit,
        LoggingContext.getInstance().getRunningOperations().toOperationNames(),
        getMetadata(fieldValue));
  }

  /**
   * Record a value in the distribution.
   *
   * @param fieldValue bucket to record the timer
   * @param value value to record
   * @param unit time unit of the value
   * @param parentOperations the parent operations that called the operation for which the latency
   *     is recorded by this timer
   * @param metadata metadata that should be recorded/logged
   */
  private final void record(
      F1 fieldValue,
      long value,
      TimeUnit unit,
      ImmutableList<String> parentOperations,
      Metadata metadata) {
    long durationNanos = unit.toNanos(value);

    if (!suppressLogging) {
      LoggingContext.getInstance()
          .addPerformanceLogRecord(
              () -> PerformanceLogRecord.create(name, durationNanos, parentOperations, metadata));
      logger.atFinest().log(
          "%s (%s = %s) took %.2f ms", name, field.name(), fieldValue, durationNanos / 1000000.0);
    }

    doRecord(fieldValue, value, unit);
    RequestStateContext.abortIfCancelled();
  }

  private Metadata getMetadata(F1 fieldValue) {
    Metadata.Builder metadataBuilder = Metadata.builder();
    field.metadataMapper().accept(metadataBuilder, fieldValue);
    return metadataBuilder.build();
  }

  /** 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.
   *
   * @param fieldValue bucket to record the timer
   * @param value value to record
   * @param unit time unit of the value
   */
  protected abstract void doRecord(F1 fieldValue, long value, TimeUnit unit);
}