From 7c286b9e0aa05e9cc9f58453ee7cfa331193631a Mon Sep 17 00:00:00 2001 From: Rahul Yadav Date: Fri, 1 May 2026 10:11:00 +0530 Subject: [PATCH 1/3] fix(gax): record fractional latency metrics --- .../google/api/gax/tracing/MetricsTracer.java | 36 ++++++++++++------- .../api/gax/tracing/MetricsTracerTest.java | 31 ++++++++++++++++ 2 files changed, 54 insertions(+), 13 deletions(-) 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..afa426b29cf5 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; @@ -59,17 +60,25 @@ public class MetricsTracer implements ApiTracer { private static final String OPERATION_FINISHED_STATUS_MESSAGE = "Operation has already been completed"; 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); } /** @@ -85,8 +94,7 @@ public void operationSucceeded() { throw new IllegalStateException(OPERATION_FINISHED_STATUS_MESSAGE); } attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.OK.toString()); - metricsRecorder.recordOperationLatency( - operationTimer.elapsed(TimeUnit.MILLISECONDS), attributes); + metricsRecorder.recordOperationLatency(elapsedMillis(operationTimer), attributes); metricsRecorder.recordOperationCount(1, attributes); } @@ -103,8 +111,7 @@ public void operationCancelled() { throw new IllegalStateException(OPERATION_FINISHED_STATUS_MESSAGE); } attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.CANCELLED.toString()); - metricsRecorder.recordOperationLatency( - operationTimer.elapsed(TimeUnit.MILLISECONDS), attributes); + metricsRecorder.recordOperationLatency(elapsedMillis(operationTimer), attributes); metricsRecorder.recordOperationCount(1, attributes); } @@ -122,8 +129,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); + metricsRecorder.recordOperationLatency(elapsedMillis(operationTimer), attributes); metricsRecorder.recordOperationCount(1, attributes); } @@ -138,7 +144,7 @@ public void operationFailed(Throwable error) { */ @Override public void attemptStarted(Object request, int attemptNumber) { - attemptTimer = Stopwatch.createStarted(); + attemptTimer = Stopwatch.createStarted(ticker); } /** @@ -148,7 +154,7 @@ 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(elapsedMillis(attemptTimer), attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -159,7 +165,7 @@ public void attemptSucceeded() { @Override public void attemptCancelled() { attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.CANCELLED.toString()); - metricsRecorder.recordAttemptLatency(attemptTimer.elapsed(TimeUnit.MILLISECONDS), attributes); + metricsRecorder.recordAttemptLatency(elapsedMillis(attemptTimer), attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -174,7 +180,7 @@ 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(elapsedMillis(attemptTimer), attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -198,7 +204,7 @@ 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(elapsedMillis(attemptTimer), attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -212,7 +218,7 @@ 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(elapsedMillis(attemptTimer), attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -236,6 +242,10 @@ public void addAttributes(Map attributes) { } ; + private static double elapsedMillis(Stopwatch stopwatch) { + return stopwatch.elapsed(TimeUnit.NANOSECONDS) / 1_000_000.0; + } + @VisibleForTesting Map getAttributes() { return 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 = From 85c57c2c4d5613248054133388a78388935acfb1 Mon Sep 17 00:00:00 2001 From: Rahul Yadav Date: Fri, 1 May 2026 10:23:37 +0530 Subject: [PATCH 2/3] fix spanner test --- .../google/api/gax/tracing/MetricsTracer.java | 19 ++++++++----------- 1 file changed, 8 insertions(+), 11 deletions(-) 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 afa426b29cf5..ab18d53140c2 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 @@ -94,7 +94,7 @@ public void operationSucceeded() { throw new IllegalStateException(OPERATION_FINISHED_STATUS_MESSAGE); } attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.OK.toString()); - metricsRecorder.recordOperationLatency(elapsedMillis(operationTimer), attributes); + metricsRecorder.recordOperationLatency(operationTimer.elapsed(TimeUnit.NANOSECONDS) / 1_000_000.0, attributes); metricsRecorder.recordOperationCount(1, attributes); } @@ -111,7 +111,7 @@ public void operationCancelled() { throw new IllegalStateException(OPERATION_FINISHED_STATUS_MESSAGE); } attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.CANCELLED.toString()); - metricsRecorder.recordOperationLatency(elapsedMillis(operationTimer), attributes); + metricsRecorder.recordOperationLatency(operationTimer.elapsed(TimeUnit.NANOSECONDS) / 1_000_000.0, attributes); metricsRecorder.recordOperationCount(1, attributes); } @@ -129,7 +129,7 @@ public void operationFailed(Throwable error) { } // Uses the GRPC status code representation. attributes.put(STATUS_ATTRIBUTE, ObservabilityUtils.extractStatus(error).toString()); - metricsRecorder.recordOperationLatency(elapsedMillis(operationTimer), attributes); + metricsRecorder.recordOperationLatency(operationTimer.elapsed(TimeUnit.NANOSECONDS) / 1_000_000.0, attributes); metricsRecorder.recordOperationCount(1, attributes); } @@ -154,7 +154,7 @@ public void attemptStarted(Object request, int attemptNumber) { @Override public void attemptSucceeded() { attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.OK.toString()); - metricsRecorder.recordAttemptLatency(elapsedMillis(attemptTimer), attributes); + metricsRecorder.recordAttemptLatency(attemptTimer.elapsed(TimeUnit.NANOSECONDS) / 1_000_000.0, attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -165,7 +165,7 @@ public void attemptSucceeded() { @Override public void attemptCancelled() { attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.CANCELLED.toString()); - metricsRecorder.recordAttemptLatency(elapsedMillis(attemptTimer), attributes); + metricsRecorder.recordAttemptLatency(attemptTimer.elapsed(TimeUnit.NANOSECONDS) / 1_000_000.0, attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -180,7 +180,7 @@ public void attemptCancelled() { @Override public void attemptFailedDuration(Throwable error, java.time.Duration delay) { attributes.put(STATUS_ATTRIBUTE, ObservabilityUtils.extractStatus(error).toString()); - metricsRecorder.recordAttemptLatency(elapsedMillis(attemptTimer), attributes); + metricsRecorder.recordAttemptLatency(attemptTimer.elapsed(TimeUnit.NANOSECONDS) / 1_000_000.0, attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -204,7 +204,7 @@ 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(elapsedMillis(attemptTimer), attributes); + metricsRecorder.recordAttemptLatency(attemptTimer.elapsed(TimeUnit.NANOSECONDS) / 1_000_000.0, attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -218,7 +218,7 @@ public void attemptFailedRetriesExhausted(Throwable error) { @Override public void attemptPermanentFailure(Throwable error) { attributes.put(STATUS_ATTRIBUTE, ObservabilityUtils.extractStatus(error).toString()); - metricsRecorder.recordAttemptLatency(elapsedMillis(attemptTimer), attributes); + metricsRecorder.recordAttemptLatency(attemptTimer.elapsed(TimeUnit.NANOSECONDS) / 1_000_000.0, attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -242,9 +242,6 @@ public void addAttributes(Map attributes) { } ; - private static double elapsedMillis(Stopwatch stopwatch) { - return stopwatch.elapsed(TimeUnit.NANOSECONDS) / 1_000_000.0; - } @VisibleForTesting Map getAttributes() { From 55f9faa099aeb7d5f46d35d58aa10886ecb016af Mon Sep 17 00:00:00 2001 From: Rahul Yadav Date: Fri, 1 May 2026 10:24:42 +0530 Subject: [PATCH 3/3] refactor --- .../google/api/gax/tracing/MetricsTracer.java | 26 ++++++++++++------- 1 file changed, 17 insertions(+), 9 deletions(-) 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 ab18d53140c2..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 @@ -59,6 +59,7 @@ 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 Ticker ticker; private final Stopwatch operationTimer; @@ -94,7 +95,8 @@ public void operationSucceeded() { throw new IllegalStateException(OPERATION_FINISHED_STATUS_MESSAGE); } attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.OK.toString()); - metricsRecorder.recordOperationLatency(operationTimer.elapsed(TimeUnit.NANOSECONDS) / 1_000_000.0, attributes); + metricsRecorder.recordOperationLatency( + operationTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordOperationCount(1, attributes); } @@ -111,7 +113,8 @@ public void operationCancelled() { throw new IllegalStateException(OPERATION_FINISHED_STATUS_MESSAGE); } attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.CANCELLED.toString()); - metricsRecorder.recordOperationLatency(operationTimer.elapsed(TimeUnit.NANOSECONDS) / 1_000_000.0, attributes); + metricsRecorder.recordOperationLatency( + operationTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordOperationCount(1, attributes); } @@ -129,7 +132,8 @@ public void operationFailed(Throwable error) { } // Uses the GRPC status code representation. attributes.put(STATUS_ATTRIBUTE, ObservabilityUtils.extractStatus(error).toString()); - metricsRecorder.recordOperationLatency(operationTimer.elapsed(TimeUnit.NANOSECONDS) / 1_000_000.0, attributes); + metricsRecorder.recordOperationLatency( + operationTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordOperationCount(1, attributes); } @@ -154,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.NANOSECONDS) / 1_000_000.0, attributes); + metricsRecorder.recordAttemptLatency( + attemptTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -165,7 +170,8 @@ public void attemptSucceeded() { @Override public void attemptCancelled() { attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.CANCELLED.toString()); - metricsRecorder.recordAttemptLatency(attemptTimer.elapsed(TimeUnit.NANOSECONDS) / 1_000_000.0, attributes); + metricsRecorder.recordAttemptLatency( + attemptTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -180,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.NANOSECONDS) / 1_000_000.0, attributes); + metricsRecorder.recordAttemptLatency( + attemptTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -204,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.NANOSECONDS) / 1_000_000.0, attributes); + metricsRecorder.recordAttemptLatency( + attemptTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -218,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.NANOSECONDS) / 1_000_000.0, attributes); + metricsRecorder.recordAttemptLatency( + attemptTimer.elapsed(TimeUnit.NANOSECONDS) / NANOS_PER_MILLISECOND, attributes); metricsRecorder.recordAttemptCount(1, attributes); } @@ -242,7 +251,6 @@ public void addAttributes(Map attributes) { } ; - @VisibleForTesting Map getAttributes() { return attributes;