diff --git a/sdk-platform-java/gax-java/gax/src/main/java/com/google/api/gax/tracing/MetricsTracer.java b/sdk-platform-java/gax-java/gax/src/main/java/com/google/api/gax/tracing/MetricsTracer.java index 13aac8986274..0bf2c047c29e 100644 --- a/sdk-platform-java/gax-java/gax/src/main/java/com/google/api/gax/tracing/MetricsTracer.java +++ b/sdk-platform-java/gax-java/gax/src/main/java/com/google/api/gax/tracing/MetricsTracer.java @@ -38,6 +38,7 @@ import com.google.api.gax.rpc.StatusCode; import com.google.common.annotations.VisibleForTesting; import com.google.common.base.Stopwatch; +import com.google.common.base.Ticker; import java.util.HashMap; import java.util.Map; import java.util.concurrent.TimeUnit; @@ -58,18 +59,27 @@ public class MetricsTracer implements ApiTracer { public static final String DEFAULT_LANGUAGE = "Java"; private static final String OPERATION_FINISHED_STATUS_MESSAGE = "Operation has already been completed"; + private static final double NANOS_PER_MILLISECOND = 1_000_000.0; private Stopwatch attemptTimer; - private final Stopwatch operationTimer = Stopwatch.createStarted(); + private final Ticker ticker; + private final Stopwatch operationTimer; // These are RPC specific attributes and pertain to a specific API Trace private final Map attributes = new HashMap<>(); private final MetricsRecorder metricsRecorder; private final AtomicBoolean operationFinished; public MetricsTracer(MethodName methodName, MetricsRecorder metricsRecorder) { + this(methodName, metricsRecorder, Ticker.systemTicker()); + } + + @VisibleForTesting + MetricsTracer(MethodName methodName, MetricsRecorder metricsRecorder, Ticker ticker) { this.attributes.put(METHOD_ATTRIBUTE, methodName.toString()); this.attributes.put(LANGUAGE_ATTRIBUTE, DEFAULT_LANGUAGE); this.metricsRecorder = metricsRecorder; this.operationFinished = new AtomicBoolean(); + this.ticker = ticker; + this.operationTimer = Stopwatch.createStarted(ticker); } /** @@ -86,7 +96,7 @@ public void operationSucceeded() { } attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.OK.toString()); metricsRecorder.recordOperationLatency( - operationTimer.elapsed(TimeUnit.MILLISECONDS), attributes); + operationTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordOperationCount(1, attributes); } @@ -104,7 +114,7 @@ public void operationCancelled() { } attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.CANCELLED.toString()); metricsRecorder.recordOperationLatency( - operationTimer.elapsed(TimeUnit.MILLISECONDS), attributes); + operationTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordOperationCount(1, attributes); } @@ -123,7 +133,7 @@ public void operationFailed(Throwable error) { // Uses the GRPC status code representation. attributes.put(STATUS_ATTRIBUTE, ObservabilityUtils.extractStatus(error).toString()); metricsRecorder.recordOperationLatency( - operationTimer.elapsed(TimeUnit.MILLISECONDS), attributes); + operationTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordOperationCount(1, attributes); } @@ -138,7 +148,7 @@ public void operationFailed(Throwable error) { */ @Override public void attemptStarted(Object request, int attemptNumber) { - attemptTimer = Stopwatch.createStarted(); + attemptTimer = Stopwatch.createStarted(ticker); } /** @@ -148,7 +158,8 @@ public void attemptStarted(Object request, int attemptNumber) { @Override public void attemptSucceeded() { attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.OK.toString()); - metricsRecorder.recordAttemptLatency(attemptTimer.elapsed(TimeUnit.MILLISECONDS), attributes); + metricsRecorder.recordAttemptLatency( + attemptTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -159,7 +170,8 @@ public void attemptSucceeded() { @Override public void attemptCancelled() { attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.CANCELLED.toString()); - metricsRecorder.recordAttemptLatency(attemptTimer.elapsed(TimeUnit.MILLISECONDS), attributes); + metricsRecorder.recordAttemptLatency( + attemptTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -174,7 +186,8 @@ public void attemptCancelled() { @Override public void attemptFailedDuration(Throwable error, java.time.Duration delay) { attributes.put(STATUS_ATTRIBUTE, ObservabilityUtils.extractStatus(error).toString()); - metricsRecorder.recordAttemptLatency(attemptTimer.elapsed(TimeUnit.MILLISECONDS), attributes); + metricsRecorder.recordAttemptLatency( + attemptTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -198,7 +211,8 @@ public void attemptFailed(Throwable error, org.threeten.bp.Duration delay) { @Override public void attemptFailedRetriesExhausted(Throwable error) { attributes.put(STATUS_ATTRIBUTE, ObservabilityUtils.extractStatus(error).toString()); - metricsRecorder.recordAttemptLatency(attemptTimer.elapsed(TimeUnit.MILLISECONDS), attributes); + metricsRecorder.recordAttemptLatency( + attemptTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -212,7 +226,8 @@ public void attemptFailedRetriesExhausted(Throwable error) { @Override public void attemptPermanentFailure(Throwable error) { attributes.put(STATUS_ATTRIBUTE, ObservabilityUtils.extractStatus(error).toString()); - metricsRecorder.recordAttemptLatency(attemptTimer.elapsed(TimeUnit.MILLISECONDS), attributes); + metricsRecorder.recordAttemptLatency( + attemptTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordAttemptCount(1, attributes); } diff --git a/sdk-platform-java/gax-java/gax/src/test/java/com/google/api/gax/tracing/MetricsTracerTest.java b/sdk-platform-java/gax-java/gax/src/test/java/com/google/api/gax/tracing/MetricsTracerTest.java index b16820c6240e..ae7bcc312788 100644 --- a/sdk-platform-java/gax-java/gax/src/test/java/com/google/api/gax/tracing/MetricsTracerTest.java +++ b/sdk-platform-java/gax-java/gax/src/test/java/com/google/api/gax/tracing/MetricsTracerTest.java @@ -43,8 +43,10 @@ import com.google.api.gax.rpc.StatusCode.Code; import com.google.api.gax.rpc.testing.FakeStatusCode; import com.google.common.collect.ImmutableMap; +import com.google.common.testing.FakeTicker; import java.util.HashMap; import java.util.Map; +import java.util.concurrent.TimeUnit; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; import org.junit.jupiter.api.extension.ExtendWith; @@ -86,6 +88,35 @@ void testOperationSucceeded_recordsAttributes() { verifyNoMoreInteractions(metricsRecorder); } + @Test + void testOperationSucceeded_recordsFractionalMilliseconds() { + FakeTicker ticker = new FakeTicker(); + metricsTracer = + new MetricsTracer(MethodName.of("fake_service", "fake_method"), metricsRecorder, ticker); + ticker.advance(3_900_000, TimeUnit.NANOSECONDS); + + metricsTracer.operationSucceeded(); + + verify(metricsRecorder).recordOperationLatency(3.9, getAttributes(Code.OK)); + verify(metricsRecorder).recordOperationCount(1, getAttributes(Code.OK)); + verifyNoMoreInteractions(metricsRecorder); + } + + @Test + void testAttemptSucceeded_recordsFractionalMilliseconds() { + FakeTicker ticker = new FakeTicker(); + metricsTracer = + new MetricsTracer(MethodName.of("fake_service", "fake_method"), metricsRecorder, ticker); + metricsTracer.attemptStarted(new Object(), 0); + ticker.advance(4_200_000, TimeUnit.NANOSECONDS); + + metricsTracer.attemptSucceeded(); + + verify(metricsRecorder).recordAttemptLatency(4.2, getAttributes(Code.OK)); + verify(metricsRecorder).recordAttemptCount(1, getAttributes(Code.OK)); + verifyNoMoreInteractions(metricsRecorder); + } + @Test void testOperationFailed_recordsAttributes() { ApiException error0 =