diff --git a/google-cloud-spanner/clirr-ignored-differences.xml b/google-cloud-spanner/clirr-ignored-differences.xml index d6d36b0e147..28e22e4a86c 100644 --- a/google-cloud-spanner/clirr-ignored-differences.xml +++ b/google-cloud-spanner/clirr-ignored-differences.xml @@ -758,6 +758,13 @@ boolean isEnableGRPCBuiltInMetrics() + + + 7012 + com/google/cloud/spanner/SpannerOptions$SpannerEnvironment + boolean isEnableAFEServerTiming() + + 7012 @@ -899,7 +906,7 @@ com/google/cloud/spanner/connection/Connection java.lang.String getDefaultSequenceKind() - + 7012 diff --git a/google-cloud-spanner/src/main/java/com/google/cloud/spanner/BuiltInMetricsConstant.java b/google-cloud-spanner/src/main/java/com/google/cloud/spanner/BuiltInMetricsConstant.java index 050484ae66e..2e0266cec5c 100644 --- a/google-cloud-spanner/src/main/java/com/google/cloud/spanner/BuiltInMetricsConstant.java +++ b/google-cloud-spanner/src/main/java/com/google/cloud/spanner/BuiltInMetricsConstant.java @@ -27,6 +27,7 @@ import io.opentelemetry.sdk.metrics.InstrumentType; import io.opentelemetry.sdk.metrics.View; import java.util.Collection; +import java.util.List; import java.util.Map; import java.util.Set; import java.util.stream.Collectors; @@ -39,6 +40,9 @@ public class BuiltInMetricsConstant { static final String SPANNER_METER_NAME = "spanner-java"; static final String GRPC_METER_NAME = "grpc-java"; static final String GFE_LATENCIES_NAME = "gfe_latencies"; + static final String AFE_LATENCIES_NAME = "afe_latencies"; + static final String GFE_CONNECTIVITY_ERROR_NAME = "gfe_connectivity_error_count"; + static final String AFE_CONNECTIVITY_ERROR_NAME = "afe_connectivity_error_count"; static final String OPERATION_LATENCIES_NAME = "operation_latencies"; static final String ATTEMPT_LATENCIES_NAME = "attempt_latencies"; static final String OPERATION_LATENCY_NAME = "operation_latency"; @@ -52,7 +56,10 @@ public class BuiltInMetricsConstant { ATTEMPT_LATENCIES_NAME, OPERATION_COUNT_NAME, ATTEMPT_COUNT_NAME, - GFE_LATENCIES_NAME) + GFE_LATENCIES_NAME, + AFE_LATENCIES_NAME, + GFE_CONNECTIVITY_ERROR_NAME, + AFE_CONNECTIVITY_ERROR_NAME) .stream() .map(m -> METER_NAME + '/' + m) .collect(Collectors.toSet()); @@ -110,14 +117,14 @@ public class BuiltInMetricsConstant { static final Set GRPC_LB_RLS_ATTRIBUTES = ImmutableSet.of("grpc.lb.rls.data_plane_target", "grpc.lb.pick_result"); + static List BUCKET_BOUNDARIES = + ImmutableList.of( + 0.0, 0.5, 1.0, 2.0, 3.0, 4.0, 5.0, 6.0, 7.0, 8.0, 9.0, 10.0, 11.0, 12.0, 13.0, 14.0, 15.0, + 16.0, 17.0, 18.0, 19.0, 20.0, 25.0, 30.0, 40.0, 50.0, 65.0, 80.0, 100.0, 130.0, 160.0, + 200.0, 250.0, 300.0, 400.0, 500.0, 650.0, 800.0, 1000.0, 2000.0, 5000.0, 10000.0, 20000.0, + 50000.0, 100000.0, 200000.0, 400000.0, 800000.0, 1600000.0, 3200000.0); static Aggregation AGGREGATION_WITH_MILLIS_HISTOGRAM = - Aggregation.explicitBucketHistogram( - ImmutableList.of( - 0.0, 0.5, 1.0, 2.0, 3.0, 4.0, 5.0, 6.0, 7.0, 8.0, 9.0, 10.0, 11.0, 12.0, 13.0, 14.0, - 15.0, 16.0, 17.0, 18.0, 19.0, 20.0, 25.0, 30.0, 40.0, 50.0, 65.0, 80.0, 100.0, 130.0, - 160.0, 200.0, 250.0, 300.0, 400.0, 500.0, 650.0, 800.0, 1000.0, 2000.0, 5000.0, - 10000.0, 20000.0, 50000.0, 100000.0, 200000.0, 400000.0, 800000.0, 1600000.0, - 3200000.0)); + Aggregation.explicitBucketHistogram(BUCKET_BOUNDARIES); static final Collection GRPC_METRICS_ENABLED_BY_DEFAULT = ImmutableList.of( @@ -145,14 +152,6 @@ static Map getAllViews() { BuiltInMetricsConstant.AGGREGATION_WITH_MILLIS_HISTOGRAM, InstrumentType.HISTOGRAM, "ms"); - defineView( - views, - BuiltInMetricsConstant.SPANNER_METER_NAME, - BuiltInMetricsConstant.GFE_LATENCIES_NAME, - BuiltInMetricsConstant.GFE_LATENCIES_NAME, - BuiltInMetricsConstant.AGGREGATION_WITH_MILLIS_HISTOGRAM, - InstrumentType.HISTOGRAM, - "ms"); defineView( views, BuiltInMetricsConstant.GAX_METER_NAME, diff --git a/google-cloud-spanner/src/main/java/com/google/cloud/spanner/BuiltInMetricsRecorder.java b/google-cloud-spanner/src/main/java/com/google/cloud/spanner/BuiltInMetricsRecorder.java index a12da470b61..0229bb02dcf 100644 --- a/google-cloud-spanner/src/main/java/com/google/cloud/spanner/BuiltInMetricsRecorder.java +++ b/google-cloud-spanner/src/main/java/com/google/cloud/spanner/BuiltInMetricsRecorder.java @@ -23,6 +23,7 @@ import io.opentelemetry.api.common.Attributes; import io.opentelemetry.api.common.AttributesBuilder; import io.opentelemetry.api.metrics.DoubleHistogram; +import io.opentelemetry.api.metrics.LongCounter; import io.opentelemetry.api.metrics.Meter; import java.util.Map; @@ -35,6 +36,9 @@ class BuiltInMetricsRecorder extends OpenTelemetryMetricsRecorder { private final DoubleHistogram gfeLatencyRecorder; + private final DoubleHistogram afeLatencyRecorder; + private final LongCounter gfeHeaderMissingCountRecorder; + private final LongCounter afeHeaderMissingCountRecorder; /** * Creates the following instruments for the following metrics: @@ -59,6 +63,27 @@ class BuiltInMetricsRecorder extends OpenTelemetryMetricsRecorder { .setDescription( "Latency between Google's network receiving an RPC and reading back the first byte of the response") .setUnit("ms") + .setExplicitBucketBoundariesAdvice(BuiltInMetricsConstant.BUCKET_BOUNDARIES) + .build(); + this.afeLatencyRecorder = + meter + .histogramBuilder(serviceName + '/' + BuiltInMetricsConstant.AFE_LATENCIES_NAME) + .setDescription( + "Latency between Spanner API Frontend receiving an RPC and starting to write back the response.") + .setExplicitBucketBoundariesAdvice(BuiltInMetricsConstant.BUCKET_BOUNDARIES) + .setUnit("ms") + .build(); + this.gfeHeaderMissingCountRecorder = + meter + .counterBuilder(serviceName + '/' + BuiltInMetricsConstant.GFE_CONNECTIVITY_ERROR_NAME) + .setDescription("Number of requests that failed to reach the Google network.") + .setUnit("1") + .build(); + this.afeHeaderMissingCountRecorder = + meter + .counterBuilder(serviceName + '/' + BuiltInMetricsConstant.AFE_CONNECTIVITY_ERROR_NAME) + .setDescription("Number of requests that failed to reach the Spanner API Frontend.") + .setUnit("1") .build(); } @@ -69,8 +94,25 @@ class BuiltInMetricsRecorder extends OpenTelemetryMetricsRecorder { * @param gfeLatency Attempt Latency in ms * @param attributes Map of the attributes to store */ - void recordGFELatency(double gfeLatency, Map attributes) { - gfeLatencyRecorder.record(gfeLatency, toOtelAttributes(attributes)); + void recordServerTimingHeaderMetrics( + Long gfeLatency, + Long afeLatency, + Long gfeHeaderMissingCount, + Long afeHeaderMissingCount, + Map attributes) { + io.opentelemetry.api.common.Attributes otelAttributes = toOtelAttributes(attributes); + if (gfeLatency != null) { + gfeLatencyRecorder.record(gfeLatency, otelAttributes); + } + if (gfeHeaderMissingCount > 0) { + gfeHeaderMissingCountRecorder.add(gfeHeaderMissingCount, otelAttributes); + } + if (afeLatency != null) { + afeLatencyRecorder.record(afeLatency, otelAttributes); + } + if (afeHeaderMissingCount > 0) { + afeHeaderMissingCountRecorder.add(afeHeaderMissingCount, otelAttributes); + } } Attributes toOtelAttributes(Map attributes) { diff --git a/google-cloud-spanner/src/main/java/com/google/cloud/spanner/BuiltInMetricsTracer.java b/google-cloud-spanner/src/main/java/com/google/cloud/spanner/BuiltInMetricsTracer.java index 6faff5ad6d7..79b80b20797 100644 --- a/google-cloud-spanner/src/main/java/com/google/cloud/spanner/BuiltInMetricsTracer.java +++ b/google-cloud-spanner/src/main/java/com/google/cloud/spanner/BuiltInMetricsTracer.java @@ -37,8 +37,10 @@ class BuiltInMetricsTracer extends MetricsTracer implements ApiTracer { private final BuiltInMetricsRecorder builtInOpenTelemetryMetricsRecorder; // These are RPC specific attributes and pertain to a specific API Trace private final Map attributes = new HashMap<>(); - private Long gfeLatency = null; + private Long afeLatency = null; + private long gfeHeaderMissingCount = 0; + private long afeHeaderMissingCount = 0; BuiltInMetricsTracer( MethodName methodName, BuiltInMetricsRecorder builtInOpenTelemetryMetricsRecorder) { @@ -54,10 +56,9 @@ class BuiltInMetricsTracer extends MetricsTracer implements ApiTracer { @Override public void attemptSucceeded() { super.attemptSucceeded(); - if (gfeLatency != null) { - attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.OK.toString()); - builtInOpenTelemetryMetricsRecorder.recordGFELatency(gfeLatency, attributes); - } + attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.OK.toString()); + builtInOpenTelemetryMetricsRecorder.recordServerTimingHeaderMetrics( + gfeLatency, afeLatency, gfeHeaderMissingCount, afeHeaderMissingCount, attributes); } /** @@ -67,10 +68,9 @@ public void attemptSucceeded() { @Override public void attemptCancelled() { super.attemptCancelled(); - if (gfeLatency != null) { - attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.CANCELLED.toString()); - builtInOpenTelemetryMetricsRecorder.recordGFELatency(gfeLatency, attributes); - } + attributes.put(STATUS_ATTRIBUTE, StatusCode.Code.CANCELLED.toString()); + builtInOpenTelemetryMetricsRecorder.recordServerTimingHeaderMetrics( + gfeLatency, afeLatency, gfeHeaderMissingCount, afeHeaderMissingCount, attributes); } /** @@ -84,10 +84,9 @@ public void attemptCancelled() { @Override public void attemptFailedDuration(Throwable error, java.time.Duration delay) { super.attemptFailedDuration(error, delay); - if (gfeLatency != null) { - attributes.put(STATUS_ATTRIBUTE, extractStatus(error)); - builtInOpenTelemetryMetricsRecorder.recordGFELatency(gfeLatency, attributes); - } + attributes.put(STATUS_ATTRIBUTE, extractStatus(error)); + builtInOpenTelemetryMetricsRecorder.recordServerTimingHeaderMetrics( + gfeLatency, afeLatency, gfeHeaderMissingCount, afeHeaderMissingCount, attributes); } /** @@ -100,10 +99,9 @@ public void attemptFailedDuration(Throwable error, java.time.Duration delay) { @Override public void attemptFailedRetriesExhausted(Throwable error) { super.attemptFailedRetriesExhausted(error); - if (gfeLatency != null) { - attributes.put(STATUS_ATTRIBUTE, extractStatus(error)); - builtInOpenTelemetryMetricsRecorder.recordGFELatency(gfeLatency, attributes); - } + attributes.put(STATUS_ATTRIBUTE, extractStatus(error)); + builtInOpenTelemetryMetricsRecorder.recordServerTimingHeaderMetrics( + gfeLatency, afeLatency, gfeHeaderMissingCount, afeHeaderMissingCount, attributes); } /** @@ -116,16 +114,27 @@ public void attemptFailedRetriesExhausted(Throwable error) { @Override public void attemptPermanentFailure(Throwable error) { super.attemptPermanentFailure(error); - if (gfeLatency != null) { - attributes.put(STATUS_ATTRIBUTE, extractStatus(error)); - builtInOpenTelemetryMetricsRecorder.recordGFELatency(gfeLatency, attributes); - } + attributes.put(STATUS_ATTRIBUTE, extractStatus(error)); + builtInOpenTelemetryMetricsRecorder.recordServerTimingHeaderMetrics( + gfeLatency, afeLatency, gfeHeaderMissingCount, afeHeaderMissingCount, attributes); } void recordGFELatency(Long gfeLatency) { this.gfeLatency = gfeLatency; } + void recordAFELatency(Long afeLatency) { + this.afeLatency = afeLatency; + } + + void recordGfeHeaderMissingCount(Long value) { + this.gfeHeaderMissingCount = value; + } + + void recordAfeHeaderMissingCount(Long value) { + this.afeHeaderMissingCount = value; + } + @Override public void addAttributes(Map attributes) { super.addAttributes(attributes); diff --git a/google-cloud-spanner/src/main/java/com/google/cloud/spanner/CompositeTracer.java b/google-cloud-spanner/src/main/java/com/google/cloud/spanner/CompositeTracer.java index 5268e9046f8..afc202342d8 100644 --- a/google-cloud-spanner/src/main/java/com/google/cloud/spanner/CompositeTracer.java +++ b/google-cloud-spanner/src/main/java/com/google/cloud/spanner/CompositeTracer.java @@ -198,4 +198,28 @@ public void recordGFELatency(Long gfeLatency) { } } } + + public void recordGfeHeaderMissingCount(Long value) { + for (ApiTracer child : children) { + if (child instanceof BuiltInMetricsTracer) { + ((BuiltInMetricsTracer) child).recordGfeHeaderMissingCount(value); + } + } + } + + public void recordAFELatency(Long afeLatency) { + for (ApiTracer child : children) { + if (child instanceof BuiltInMetricsTracer) { + ((BuiltInMetricsTracer) child).recordAFELatency(afeLatency); + } + } + } + + public void recordAfeHeaderMissingCount(Long value) { + for (ApiTracer child : children) { + if (child instanceof BuiltInMetricsTracer) { + ((BuiltInMetricsTracer) child).recordAfeHeaderMissingCount(value); + } + } + } } diff --git a/google-cloud-spanner/src/main/java/com/google/cloud/spanner/spi/v1/GapicSpannerRpc.java b/google-cloud-spanner/src/main/java/com/google/cloud/spanner/spi/v1/GapicSpannerRpc.java index 2a0ac1839dd..7f661c013de 100644 --- a/google-cloud-spanner/src/main/java/com/google/cloud/spanner/spi/v1/GapicSpannerRpc.java +++ b/google-cloud-spanner/src/main/java/com/google/cloud/spanner/spi/v1/GapicSpannerRpc.java @@ -689,6 +689,10 @@ private static boolean isEmulatorEnabled(SpannerOptions options, String emulator && options.getHost().endsWith(emulatorHost); } + public static boolean isEnableAFEServerTiming() { + return "false".equalsIgnoreCase(System.getenv("SPANNER_DISABLE_AFE_SERVER_TIMING")); + } + private static final RetrySettings ADMIN_REQUESTS_LIMIT_EXCEEDED_RETRY_SETTINGS = RetrySettings.newBuilder() .setInitialRetryDelayDuration(Duration.ofSeconds(5L)) @@ -1993,6 +1997,9 @@ private GrpcCallContext createBaseCallContext() { if (endToEndTracingEnabled) { context = context.withExtraHeaders(metadataProvider.newEndToEndTracingHeader()); } + if (isEnableAFEServerTiming()) { + context = context.withExtraHeaders(metadataProvider.newAfeServerTimingHeader()); + } return context .withStreamWaitTimeoutDuration(waitTimeout) .withStreamIdleTimeoutDuration(idleTimeout); diff --git a/google-cloud-spanner/src/main/java/com/google/cloud/spanner/spi/v1/HeaderInterceptor.java b/google-cloud-spanner/src/main/java/com/google/cloud/spanner/spi/v1/HeaderInterceptor.java index b972ecdcef4..0f132593565 100644 --- a/google-cloud-spanner/src/main/java/com/google/cloud/spanner/spi/v1/HeaderInterceptor.java +++ b/google-cloud-spanner/src/main/java/com/google/cloud/spanner/spi/v1/HeaderInterceptor.java @@ -72,6 +72,7 @@ class HeaderInterceptor implements ClientInterceptor { private static final Metadata.Key SERVER_TIMING_HEADER_KEY = Metadata.Key.of("server-timing", Metadata.ASCII_STRING_MARSHALLER); private static final String GFE_TIMING_HEADER = "gfet4t7"; + private static final String AFE_TIMING_HEADER = "afe"; private static final Metadata.Key GOOGLE_CLOUD_RESOURCE_PREFIX_KEY = Metadata.Key.of("google-cloud-resource-prefix", Metadata.ASCII_STRING_MARSHALLER); private static final Pattern SERVER_TIMING_PATTERN = @@ -174,13 +175,25 @@ private void processHeader( if (compositeTracer != null) { compositeTracer.recordGFELatency(gfeLatency); } - if (span != null) { span.setAttribute("gfe_latency", String.valueOf(gfeLatency)); } } else { measureMap.put(SPANNER_GFE_HEADER_MISSING_COUNT, 1L).record(tagContext); spannerRpcMetrics.recordGfeHeaderMissingCount(1L, attributes); + if (compositeTracer != null) { + compositeTracer.recordGfeHeaderMissingCount(1L); + } + } + + // Record AFE metrics + if (compositeTracer != null && GapicSpannerRpc.isEnableAFEServerTiming()) { + if (serverTimingMetrics.containsKey(AFE_TIMING_HEADER)) { + long afeLatency = serverTimingMetrics.get(AFE_TIMING_HEADER); + compositeTracer.recordAFELatency(afeLatency); + } else { + compositeTracer.recordAfeHeaderMissingCount(1L); + } } } catch (NumberFormatException e) { LOGGER.log(LEVEL, "Invalid server-timing object in header: {}", serverTiming); diff --git a/google-cloud-spanner/src/main/java/com/google/cloud/spanner/spi/v1/SpannerMetadataProvider.java b/google-cloud-spanner/src/main/java/com/google/cloud/spanner/spi/v1/SpannerMetadataProvider.java index 2ebc4925788..e9c74847275 100644 --- a/google-cloud-spanner/src/main/java/com/google/cloud/spanner/spi/v1/SpannerMetadataProvider.java +++ b/google-cloud-spanner/src/main/java/com/google/cloud/spanner/spi/v1/SpannerMetadataProvider.java @@ -38,6 +38,8 @@ class SpannerMetadataProvider { private final String resourceHeaderKey; private static final String ROUTE_TO_LEADER_HEADER_KEY = "x-goog-spanner-route-to-leader"; private static final String END_TO_END_TRACING_HEADER_KEY = "x-goog-spanner-end-to-end-tracing"; + private static final String AFE_SERVER_TIMING_HEADER_KEY = + "x-goog-spanner-enable-afe-server-timing"; private static final Pattern[] RESOURCE_TOKEN_PATTERNS = { Pattern.compile("^(?projects/[^/]*/instances/[^/]*/databases/[^/]*)(.*)?"), Pattern.compile("^(?projects/[^/]*/instances/[^/]*)(.*)?") @@ -47,6 +49,8 @@ class SpannerMetadataProvider { ImmutableMap.of(ROUTE_TO_LEADER_HEADER_KEY, Collections.singletonList("true")); private static final Map> END_TO_END_TRACING_HEADER_MAP = ImmutableMap.of(END_TO_END_TRACING_HEADER_KEY, Collections.singletonList("true")); + private static final Map> AFE_SERVER_TIMING_HEADER_MAP = + ImmutableMap.of(AFE_SERVER_TIMING_HEADER_KEY, Collections.singletonList("true")); private SpannerMetadataProvider(Map headers, String resourceHeaderKey) { this.resourceHeaderKey = resourceHeaderKey; @@ -96,6 +100,10 @@ Map> newEndToEndTracingHeader() { return END_TO_END_TRACING_HEADER_MAP; } + Map> newAfeServerTimingHeader() { + return AFE_SERVER_TIMING_HEADER_MAP; + } + private Map, String> constructHeadersAsMetadata( Map headers) { ImmutableMap.Builder, String> headersAsMetadataBuilder = diff --git a/google-cloud-spanner/src/test/java/com/google/cloud/spanner/AbstractNettyMockServerTest.java b/google-cloud-spanner/src/test/java/com/google/cloud/spanner/AbstractNettyMockServerTest.java index 8e8da054b08..afb550b5c6a 100644 --- a/google-cloud-spanner/src/test/java/com/google/cloud/spanner/AbstractNettyMockServerTest.java +++ b/google-cloud-spanner/src/test/java/com/google/cloud/spanner/AbstractNettyMockServerTest.java @@ -47,6 +47,9 @@ abstract class AbstractNettyMockServerTest { protected static AtomicInteger fakeServerTiming = new AtomicInteger(new Random().nextInt(1000) + 1); + protected static AtomicInteger fakeAFEServerTiming = + new AtomicInteger(new Random().nextInt(500) + 1); + protected Spanner spanner; @BeforeClass @@ -72,7 +75,9 @@ public ServerCall.Listener interceptCall( public void sendHeaders(Metadata headers) { headers.put( Metadata.Key.of("server-timing", Metadata.ASCII_STRING_MARSHALLER), - String.format("gfet4t7; dur=%d", fakeServerTiming.get())); + String.format( + "afe; dur=%d, gfet4t7; dur=%d", + fakeAFEServerTiming.get(), fakeServerTiming.get())); super.sendHeaders(headers); } }, diff --git a/google-cloud-spanner/src/test/java/com/google/cloud/spanner/OpenTelemetryBuiltInMetricsTracerTest.java b/google-cloud-spanner/src/test/java/com/google/cloud/spanner/OpenTelemetryBuiltInMetricsTracerTest.java index d2db2e4bca0..b26a76471d7 100644 --- a/google-cloud-spanner/src/test/java/com/google/cloud/spanner/OpenTelemetryBuiltInMetricsTracerTest.java +++ b/google-cloud-spanner/src/test/java/com/google/cloud/spanner/OpenTelemetryBuiltInMetricsTracerTest.java @@ -24,12 +24,12 @@ import static org.junit.Assert.assertThrows; import static org.junit.Assert.assertTrue; import static org.junit.Assert.fail; +import static org.junit.Assume.assumeFalse; +import static org.junit.Assume.assumeTrue; import com.google.api.gax.longrunning.OperationTimedPollAlgorithm; import com.google.api.gax.retrying.RetrySettings; import com.google.api.gax.tracing.ApiTracerFactory; -import com.google.api.gax.tracing.MetricsTracerFactory; -import com.google.api.gax.tracing.OpenTelemetryMetricsRecorder; import com.google.cloud.NoCredentials; import com.google.cloud.spanner.MockSpannerServiceImpl.SimulatedExecutionTime; import com.google.cloud.spanner.MockSpannerServiceImpl.StatementResult; @@ -38,7 +38,9 @@ import com.google.common.collect.ImmutableList; import com.google.common.collect.Range; import io.grpc.ManagedChannelBuilder; +import io.grpc.Server; import io.grpc.Status; +import io.grpc.netty.shaded.io.grpc.netty.NettyServerBuilder; import io.opentelemetry.api.OpenTelemetry; import io.opentelemetry.api.common.Attributes; import io.opentelemetry.sdk.OpenTelemetrySdk; @@ -47,6 +49,9 @@ import io.opentelemetry.sdk.metrics.data.LongPointData; import io.opentelemetry.sdk.metrics.data.MetricData; import io.opentelemetry.sdk.testing.exporter.InMemoryMetricReader; +import java.io.IOException; +import java.lang.reflect.Field; +import java.net.InetSocketAddress; import java.time.Duration; import java.util.Collection; import java.util.List; @@ -61,49 +66,37 @@ @RunWith(JUnit4.class) public class OpenTelemetryBuiltInMetricsTracerTest extends AbstractNettyMockServerTest { - private static final Statement SELECT_RANDOM = Statement.of("SELECT * FROM random"); - private static final Statement UPDATE_RANDOM = Statement.of("UPDATE random SET foo=1 WHERE id=1"); private static InMemoryMetricReader metricReader; - - private static OpenTelemetry openTelemetry; - - private static Map attributes; - - private static Attributes expectedCommonBaseAttributes; - private static Attributes expectedCommonRequestAttributes; + private static Map attributes = + BuiltInMetricsProvider.INSTANCE.createClientAttributes(); + private static Attributes expectedCommonBaseAttributes = + Attributes.builder() + .put(BuiltInMetricsConstant.CLIENT_NAME_KEY, "spanner-java/") + .put(BuiltInMetricsConstant.CLIENT_UID_KEY, attributes.get("client_uid")) + .put(BuiltInMetricsConstant.INSTANCE_ID_KEY, "i") + .put(BuiltInMetricsConstant.DATABASE_KEY, "d") + .put(BuiltInMetricsConstant.DIRECT_PATH_ENABLED_KEY, "false") + .build();; + private static Attributes expectedCommonRequestAttributes = + Attributes.builder().put(BuiltInMetricsConstant.DIRECT_PATH_USED_KEY, "false").build();; private static final long MIN_LATENCY = 0; private DatabaseClient client; - @BeforeClass - public static void setup() { + public ApiTracerFactory createMetricsTracerFactory() { metricReader = InMemoryMetricReader.create(); - BuiltInMetricsProvider provider = BuiltInMetricsProvider.INSTANCE; - SdkMeterProviderBuilder meterProvider = SdkMeterProvider.builder().registerMetricReader(metricReader); - BuiltInMetricsConstant.getAllViews().forEach(meterProvider::registerView); + OpenTelemetry openTelemetry = + OpenTelemetrySdk.builder().setMeterProvider(meterProvider.build()).build(); - String client_name = "spanner-java/"; - openTelemetry = OpenTelemetrySdk.builder().setMeterProvider(meterProvider.build()).build(); - attributes = provider.createClientAttributes(); - - expectedCommonBaseAttributes = - Attributes.builder() - .put(BuiltInMetricsConstant.CLIENT_NAME_KEY, client_name) - .put(BuiltInMetricsConstant.CLIENT_UID_KEY, attributes.get("client_uid")) - .put(BuiltInMetricsConstant.INSTANCE_ID_KEY, "i") - .put(BuiltInMetricsConstant.DATABASE_KEY, "d") - .put(BuiltInMetricsConstant.DIRECT_PATH_ENABLED_KEY, "false") - .build(); - - expectedCommonRequestAttributes = - Attributes.builder().put(BuiltInMetricsConstant.DIRECT_PATH_USED_KEY, "false").build(); + return new BuiltInMetricsTracerFactory( + new BuiltInMetricsRecorder(openTelemetry, BuiltInMetricsConstant.METER_NAME), attributes); } @BeforeClass @@ -114,18 +107,14 @@ public static void setupResults() { } @After - public void clearRequests() { + public void clearRequests() throws IOException { mockSpanner.clearRequests(); + metricReader.close(); } @Override public void createSpannerInstance() { SpannerOptions.Builder builder = SpannerOptions.newBuilder(); - - ApiTracerFactory metricsTracerFactory = - new BuiltInMetricsTracerFactory( - new BuiltInMetricsRecorder(openTelemetry, BuiltInMetricsConstant.METER_NAME), - attributes); // Set a quick polling algorithm to prevent this from slowing down the test unnecessarily. builder .getDatabaseAdminStubSettingsBuilder() @@ -154,7 +143,7 @@ public void createSpannerInstance() { // Setting this to false so that Spanner Options does not register Metrics Tracer // factory again. .setBuiltInMetricsEnabled(false) - .setApiTracerFactory(metricsTracerFactory) + .setApiTracerFactory(createMetricsTracerFactory()) .build() .getService(); client = spanner.getDatabaseClient(DatabaseId.of("test-project", "i", "d")); @@ -203,6 +192,91 @@ public void testMetricsSingleUseQuery() { getMetricData(metricReader, BuiltInMetricsConstant.GFE_LATENCIES_NAME); long gfeLatencyValue = getAggregatedValue(gfeLatencyMetricData, expectedAttributes); assertEquals(fakeServerTiming.get(), gfeLatencyValue, 0); + + assertFalse( + checkIfMetricExists(metricReader, BuiltInMetricsConstant.GFE_CONNECTIVITY_ERROR_NAME)); + assertFalse(checkIfMetricExists(metricReader, BuiltInMetricsConstant.AFE_LATENCIES_NAME)); + assertFalse( + checkIfMetricExists(metricReader, BuiltInMetricsConstant.AFE_CONNECTIVITY_ERROR_NAME)); + } + + private boolean isJava8() { + return JavaVersionUtil.getJavaMajorVersion() == 8; + } + + private boolean isWindows() { + return System.getProperty("os.name").toLowerCase().contains("windows"); + } + + @Test + public void testMetricsSingleUseQueryWithAfeEnabled() throws Exception { + assumeTrue(isJava8() && !isWindows()); + assumeFalse(System.getenv().containsKey("SPANNER_DISABLE_AFE_SERVER_TIMING")); + + Class classOfMap = System.getenv().getClass(); + Field field = classOfMap.getDeclaredField("m"); + field.setAccessible(true); + Map writeableEnvironmentVariables = + (Map) field.get(System.getenv()); + + try { + writeableEnvironmentVariables.put("SPANNER_DISABLE_AFE_SERVER_TIMING", "false"); + + Stopwatch stopwatch = Stopwatch.createStarted(); + try (ResultSet resultSet = client.singleUse().executeQuery(SELECT_RANDOM)) { + assertTrue(resultSet.next()); + assertFalse(resultSet.next()); + } + + long elapsed = stopwatch.elapsed(TimeUnit.MILLISECONDS); + Attributes expectedAttributes = + expectedCommonBaseAttributes + .toBuilder() + .putAll(expectedCommonRequestAttributes) + .put(BuiltInMetricsConstant.STATUS_KEY, "OK") + .put(BuiltInMetricsConstant.METHOD_KEY, "Spanner.ExecuteStreamingSql") + .build(); + + MetricData operationLatencyMetricData = + getMetricData(metricReader, BuiltInMetricsConstant.OPERATION_LATENCIES_NAME); + assertNotNull(operationLatencyMetricData); + long operationLatencyValue = + getAggregatedValue(operationLatencyMetricData, expectedAttributes); + assertThat(operationLatencyValue).isIn(Range.closed(MIN_LATENCY, elapsed)); + + MetricData attemptLatencyMetricData = + getMetricData(metricReader, BuiltInMetricsConstant.ATTEMPT_LATENCIES_NAME); + assertNotNull(attemptLatencyMetricData); + long attemptLatencyValue = getAggregatedValue(attemptLatencyMetricData, expectedAttributes); + assertThat(attemptLatencyValue).isIn(Range.closed(MIN_LATENCY, elapsed)); + + MetricData operationCountMetricData = + getMetricData(metricReader, BuiltInMetricsConstant.OPERATION_COUNT_NAME); + assertNotNull(operationCountMetricData); + assertThat(getAggregatedValue(operationCountMetricData, expectedAttributes)).isEqualTo(1); + + MetricData attemptCountMetricData = + getMetricData(metricReader, BuiltInMetricsConstant.ATTEMPT_COUNT_NAME); + assertNotNull(attemptCountMetricData); + assertThat(getAggregatedValue(attemptCountMetricData, expectedAttributes)).isEqualTo(1); + + MetricData gfeLatencyMetricData = + getMetricData(metricReader, BuiltInMetricsConstant.GFE_LATENCIES_NAME); + long gfeLatencyValue = getAggregatedValue(gfeLatencyMetricData, expectedAttributes); + assertEquals(fakeServerTiming.get(), gfeLatencyValue, 0); + + assertFalse( + checkIfMetricExists(metricReader, BuiltInMetricsConstant.GFE_CONNECTIVITY_ERROR_NAME)); + + MetricData afeLatencyMetricData = + getMetricData(metricReader, BuiltInMetricsConstant.AFE_LATENCIES_NAME); + long afeLatencyValue = getAggregatedValue(afeLatencyMetricData, expectedAttributes); + assertEquals(fakeAFEServerTiming.get(), afeLatencyValue, 0); + assertFalse( + checkIfMetricExists(metricReader, BuiltInMetricsConstant.AFE_CONNECTIVITY_ERROR_NAME)); + } finally { + writeableEnvironmentVariables.remove("GOOGLE_CLOUD_SPANNER_MULTIPLEXED_SESSIONS"); + } } @Test @@ -275,10 +349,6 @@ public void testNoNetworkConnection() { return null; }); - ApiTracerFactory metricsTracerFactory = - new MetricsTracerFactory( - new OpenTelemetryMetricsRecorder(openTelemetry, BuiltInMetricsConstant.METER_NAME), - attributes); Spanner spanner = builder .setProjectId("test-project") @@ -296,7 +366,7 @@ public void testNoNetworkConnection() { // Setting this to false so that Spanner Options does not register Metrics Tracer // factory again. .setBuiltInMetricsEnabled(false) - .setApiTracerFactory(metricsTracerFactory) + .setApiTracerFactory(createMetricsTracerFactory()) .build() .getService(); String instance = "i"; @@ -339,6 +409,58 @@ public void testNoNetworkConnection() { 1, getAggregatedValue(attemptCountMetricData, expectedAttributesCreateSessionFailed)); } + @Test + public void testNoServerTimingHeader() throws IOException, InterruptedException { + // Create Spanner Object without headers + InetSocketAddress addressNoHeader = new InetSocketAddress("localhost", 0); + Server serverNoHeader = + NettyServerBuilder.forAddress(addressNoHeader).addService(mockSpanner).build().start(); + String endpoint = address.getHostString() + ":" + serverNoHeader.getPort(); + Spanner spannerNoHeader = + SpannerOptions.newBuilder() + .setProjectId("test-project") + .setChannelConfigurator(ManagedChannelBuilder::usePlaintext) + .setHost("http://" + endpoint) + .setCredentials(NoCredentials.getInstance()) + .setSessionPoolOption( + SessionPoolOptions.newBuilder() + .setWaitForMinSessionsDuration(Duration.ofSeconds(5L)) + .setFailOnSessionLeak() + .setSkipVerifyingBeginTransactionForMuxRW(true) + .build()) + // Setting this to false so that Spanner Options does not register Metrics Tracer + // factory again. + .setBuiltInMetricsEnabled(false) + .setApiTracerFactory(createMetricsTracerFactory()) + .build() + .getService(); + DatabaseClient databaseClientNoHeader = + spannerNoHeader.getDatabaseClient(DatabaseId.of("test-project", "i", "d")); + + databaseClientNoHeader + .readWriteTransaction() + .run(transaction -> transaction.executeUpdate(UPDATE_RANDOM)); + + Attributes expectedAttributes = + expectedCommonBaseAttributes + .toBuilder() + .putAll(expectedCommonRequestAttributes) + .put(BuiltInMetricsConstant.STATUS_KEY, "OK") + .put(BuiltInMetricsConstant.METHOD_KEY, "Spanner.ExecuteSql") + .build(); + + MetricData gfeConnectivityMetricData = + getMetricData(metricReader, BuiltInMetricsConstant.GFE_CONNECTIVITY_ERROR_NAME); + assertThat(getAggregatedValue(gfeConnectivityMetricData, expectedAttributes)).isEqualTo(1); + assertFalse(checkIfMetricExists(metricReader, BuiltInMetricsConstant.AFE_LATENCIES_NAME)); + assertFalse(checkIfMetricExists(metricReader, BuiltInMetricsConstant.GFE_LATENCIES_NAME)); + assertFalse( + checkIfMetricExists(metricReader, BuiltInMetricsConstant.AFE_CONNECTIVITY_ERROR_NAME)); + spannerNoHeader.close(); + serverNoHeader.shutdown(); + serverNoHeader.awaitTermination(); + } + private MetricData getMetricData(InMemoryMetricReader reader, String metricName) { String fullMetricName = BuiltInMetricsConstant.METER_NAME + "/" + metricName; Collection allMetricData; @@ -372,6 +494,26 @@ private MetricData getMetricData(InMemoryMetricReader reader, String metricName) return null; } + private boolean checkIfMetricExists(InMemoryMetricReader reader, String metricName) { + String fullMetricName = BuiltInMetricsConstant.METER_NAME + "/" + metricName; + + for (int attemptsLeft = 1000; attemptsLeft > 0; attemptsLeft--) { + boolean exists = + reader.collectAllMetrics().stream().anyMatch(md -> md.getName().equals(fullMetricName)); + if (exists) { + return true; + } + try { + Thread.sleep(1); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + throw new RuntimeException(e); + } + } + + return false; + } + private long getAggregatedValue(MetricData metricData, Attributes attributes) { switch (metricData.getType()) { case HISTOGRAM: diff --git a/google-cloud-spanner/src/test/java/com/google/cloud/spanner/spi/v1/SpannerMetadataProviderTest.java b/google-cloud-spanner/src/test/java/com/google/cloud/spanner/spi/v1/SpannerMetadataProviderTest.java index c4fdd6200af..8073b11735e 100644 --- a/google-cloud-spanner/src/test/java/com/google/cloud/spanner/spi/v1/SpannerMetadataProviderTest.java +++ b/google-cloud-spanner/src/test/java/com/google/cloud/spanner/spi/v1/SpannerMetadataProviderTest.java @@ -105,6 +105,17 @@ public void testNewEndToEndTracingHeader() { assertTrue(Maps.difference(extraHeaders, expectedHeaders).areEqual()); } + @Test + public void testNewAfeServerTimingHeader() { + SpannerMetadataProvider metadataProvider = + SpannerMetadataProvider.create(ImmutableMap.of(), "header1"); + Map> extraHeaders = metadataProvider.newAfeServerTimingHeader(); + Map> expectedHeaders = + ImmutableMap.>of( + "x-goog-spanner-enable-afe-server-timing", ImmutableList.of("true")); + assertTrue(Maps.difference(extraHeaders, expectedHeaders).areEqual()); + } + private String getResourceHeaderValue( SpannerMetadataProvider headerProvider, String resourceTokenTemplate) { Metadata metadata = headerProvider.newMetadata(resourceTokenTemplate, "projects/p");