blob: 62d8ca8ee35e908882b86ff8775d9a753aa77abb [file] [edit]
/*
Copyright 2026 Google LLC
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 spanner
import (
"context"
"fmt"
"maps"
"reflect"
"slices"
"sort"
"strings"
"sync"
"testing"
"time"
"cloud.google.com/go/spanner/apiv1/spannerpb"
. "cloud.google.com/go/spanner/internal/testutil"
"github.com/google/go-cmp/cmp"
"github.com/googleapis/gax-go/v2"
"go.opencensus.io/stats/view"
"go.opentelemetry.io/otel"
"go.opentelemetry.io/otel/attribute"
"go.opentelemetry.io/otel/sdk/metric/metricdata"
sdktrace "go.opentelemetry.io/otel/sdk/trace"
"go.opentelemetry.io/otel/sdk/trace/tracetest"
oteltrace "go.opentelemetry.io/otel/trace"
"go.opentelemetry.io/otel/trace/noop"
"google.golang.org/api/option"
"google.golang.org/grpc"
"google.golang.org/grpc/codes"
"google.golang.org/grpc/metadata"
"google.golang.org/grpc/status"
)
func TestGFELatencySinksEnabled(t *testing.T) {
origFlag := getGFELatencyMetricsFlag()
t.Cleanup(func() { setGFELatencyMetricsFlag(origFlag) })
for _, tc := range []struct {
name string
ocFlag bool
hasOpenCensusContext bool
otConfig *openTelemetryConfig
want bool
}{
{name: "no sinks", want: false},
{name: "OpenCensus flag without context", ocFlag: true, want: false},
{name: "OpenCensus context without flag", hasOpenCensusContext: true, want: false},
{name: "OpenCensus flag and context", ocFlag: true, hasOpenCensusContext: true, want: true},
{name: "OpenTelemetry disabled", otConfig: &openTelemetryConfig{}, want: false},
{name: "OpenTelemetry enabled", otConfig: &openTelemetryConfig{enabled: true}, want: true},
{name: "OpenCensus and OpenTelemetry enabled", ocFlag: true, hasOpenCensusContext: true, otConfig: &openTelemetryConfig{enabled: true}, want: true},
} {
t.Run(tc.name, func(t *testing.T) {
setGFELatencyMetricsFlag(tc.ocFlag)
if got := gfeLatencySinksEnabled(tc.hasOpenCensusContext, tc.otConfig); got != tc.want {
t.Fatalf("gfeLatencySinksEnabled(%v, %+v) = %v, want %v", tc.hasOpenCensusContext, tc.otConfig, got, tc.want)
}
})
}
}
// headerCountingStream is a grpc.ClientStream that counts calls to Header.
type headerCountingStream struct {
grpc.ClientStream
md metadata.MD
headerCalls int
}
func (s *headerCountingStream) Header() (metadata.MD, error) {
s.headerCalls++
return s.md, nil
}
func (s *headerCountingStream) Context() context.Context {
return context.Background()
}
type fakeExecuteStreamingSQLClient struct {
spannerpb.Spanner_ExecuteStreamingSqlClient
stream *headerCountingStream
}
func (c *fakeExecuteStreamingSQLClient) Header() (metadata.MD, error) {
return c.stream.Header()
}
type fakeStreamingReadClient struct {
spannerpb.Spanner_StreamingReadClient
stream *headerCountingStream
}
func (c *fakeStreamingReadClient) Header() (metadata.MD, error) {
return c.stream.Header()
}
type fakeBatchWriteClient struct {
spannerpb.Spanner_BatchWriteClient
stream *headerCountingStream
}
func (c *fakeBatchWriteClient) Header() (metadata.MD, error) {
return c.stream.Header()
}
func TestCachedStreamClientsCallHeaderOnce(t *testing.T) {
md := metadata.Pairs("server-timing", "gfet4t7; dur=123")
for _, tc := range []struct {
name string
wrap func(*headerCountingStream) grpc.ClientStream
}{
{
name: "ExecuteStreamingSql",
wrap: func(s *headerCountingStream) grpc.ClientStream {
return &cachedExecuteStreamingSQLClient{Spanner_ExecuteStreamingSqlClient: &fakeExecuteStreamingSQLClient{stream: s}}
},
},
{
name: "StreamingRead",
wrap: func(s *headerCountingStream) grpc.ClientStream {
return &cachedStreamingReadClient{Spanner_StreamingReadClient: &fakeStreamingReadClient{stream: s}}
},
},
{
name: "BatchWrite",
wrap: func(s *headerCountingStream) grpc.ClientStream {
return &cachedBatchWriteClient{Spanner_BatchWriteClient: &fakeBatchWriteClient{stream: s}}
},
},
} {
t.Run(tc.name, func(t *testing.T) {
stream := &headerCountingStream{md: md}
client := tc.wrap(stream)
for i := 0; i < 3; i++ {
got, err := client.Header()
if err != nil {
t.Fatalf("Header() failed: %v", err)
}
if !reflect.DeepEqual(got, md) {
t.Fatalf("Header() = %v, want %v", got, md)
}
}
if stream.headerCalls != 1 {
t.Fatalf("underlying Header() calls = %d, want 1", stream.headerCalls)
}
})
}
}
func TestCaptureStreamServerTiming(t *testing.T) {
md := metadata.Pairs("server-timing", "gfet4t7; dur=123", "server-timing", "afe; dur=45")
tracer := sdktrace.NewTracerProvider().Tracer("test")
nonRecordingSpan := oteltrace.SpanFromContext(context.Background())
for _, tc := range []struct {
name string
builtInEnabled bool
recording bool
noTracer bool
noAttempt bool
wantHeaderCalls int
wantSpanAttrs map[string]float64
}{
{name: "built-in metrics disabled and span not recording"},
{name: "nil tracer and span recording", noTracer: true, recording: true, wantHeaderCalls: 1, wantSpanAttrs: map[string]float64{"gfe.latency_ms": 123, "afe.latency_ms": 45}},
{name: "nil tracer and span not recording", noTracer: true},
{name: "no current attempt and span not recording", builtInEnabled: true, noAttempt: true},
{name: "no current attempt and span recording", builtInEnabled: true, noAttempt: true, recording: true, wantHeaderCalls: 1, wantSpanAttrs: map[string]float64{"gfe.latency_ms": 123, "afe.latency_ms": 45}},
{name: "built-in metrics enabled", builtInEnabled: true, wantHeaderCalls: 1},
{name: "span recording", recording: true, wantHeaderCalls: 1, wantSpanAttrs: map[string]float64{"gfe.latency_ms": 123, "afe.latency_ms": 45}},
{name: "built-in metrics enabled and span recording", builtInEnabled: true, recording: true, wantHeaderCalls: 1, wantSpanAttrs: map[string]float64{"gfe.latency_ms": 123, "afe.latency_ms": 45}},
} {
t.Run(tc.name, func(t *testing.T) {
span := nonRecordingSpan
if tc.recording {
_, span = tracer.Start(context.Background(), "stream")
}
var mt *builtinMetricsTracer
if !tc.noTracer {
mt = &builtinMetricsTracer{builtInEnabled: tc.builtInEnabled, currOp: &opTracer{}}
if !tc.noAttempt {
mt.currOp.currAttempt = &attemptTracer{}
}
}
stream := &headerCountingStream{md: md}
captureStreamServerTiming(span, mt, stream)
if stream.headerCalls != tc.wantHeaderCalls {
t.Fatalf("Header() calls = %d, want %d", stream.headerCalls, tc.wantHeaderCalls)
}
if tc.wantHeaderCalls > 0 && !tc.noTracer && !tc.noAttempt {
if got, want := mt.currOp.currAttempt.serverTimingMetrics[gfeTimingHeader], 123*time.Millisecond; got != want {
t.Errorf("server timing %q = %v, want %v", gfeTimingHeader, got, want)
}
}
if tc.recording {
gotSpanAttrs := map[string]float64{}
for _, attr := range span.(sdktrace.ReadOnlySpan).Attributes() {
gotSpanAttrs[string(attr.Key)] = attr.Value.AsFloat64()
}
if len(tc.wantSpanAttrs) == 0 && len(gotSpanAttrs) != 0 {
t.Errorf("span attributes = %v, want none", gotSpanAttrs)
}
for k, want := range tc.wantSpanAttrs {
if got, ok := gotSpanAttrs[k]; !ok || got != want {
t.Errorf("span attribute %q = %v (present %v), want %v", k, got, ok, want)
}
}
}
})
}
}
// streamHeaderCounter counts Header calls on the gRPC client streams created
// for each method.
type streamHeaderCounter struct {
mu sync.Mutex
calls map[string]int
}
func (c *streamHeaderCounter) interceptor(ctx context.Context, desc *grpc.StreamDesc, cc *grpc.ClientConn, method string, streamer grpc.Streamer, opts ...grpc.CallOption) (grpc.ClientStream, error) {
s, err := streamer(ctx, desc, cc, method, opts...)
if err != nil {
return s, err
}
return &countedClientStream{ClientStream: s, counter: c, method: method}, nil
}
func (c *streamHeaderCounter) get(method string) int {
c.mu.Lock()
defer c.mu.Unlock()
return c.calls[method]
}
type countedClientStream struct {
grpc.ClientStream
counter *streamHeaderCounter
method string
}
func (s *countedClientStream) Header() (metadata.MD, error) {
s.counter.mu.Lock()
s.counter.calls[s.method]++
s.counter.mu.Unlock()
return s.ClientStream.Header()
}
// TestStreamHeadersOnlyReadWhenUsed runs single and partitioned queries and
// reads through the public client, and verifies that the stream headers are
// read once per stream only when a sink uses them, and that every enabled sink
// still records the latency of each method.
func TestStreamHeadersOnlyReadWhenUsed(t *testing.T) {
const (
executeStreamingSQL = "/google.spanner.v1.Spanner/ExecuteStreamingSql"
streamingRead = "/google.spanner.v1.Spanner/StreamingRead"
)
// The mock server sends "gfet4t7; dur=123" for StreamingRead. Send a
// different value for ExecuteStreamingSql to tell the methods apart.
queryTiming := grpc.StreamInterceptor(func(srv any, stream grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
if info.FullMethod == executeStreamingSQL {
if err := stream.SetHeader(metadata.Pairs("server-timing", "gfet4t7; dur=456")); err != nil {
return err
}
}
return handler(srv, stream)
})
// Other tests in this package enable OpenCensus GFE latency metrics and
// install a recording tracer provider, so set every sink explicitly.
origOTFlag := IsOpenTelemetryMetricsEnabled()
origOCFlag := getGFELatencyMetricsFlag()
origTracerProvider := otel.GetTracerProvider()
t.Cleanup(func() {
setOpenTelemetryMetricsFlag(origOTFlag)
setGFELatencyMetricsFlag(origOCFlag)
otel.SetTracerProvider(origTracerProvider)
})
for _, tc := range []struct {
name string
openCensus, openTelemetry, builtIn bool
tracing bool
wantHeaderCallsPerMethod int
}{
{name: "no sinks", wantHeaderCallsPerMethod: 0},
{name: "OpenCensus", openCensus: true, wantHeaderCallsPerMethod: 2},
{name: "OpenTelemetry", openTelemetry: true, wantHeaderCallsPerMethod: 2},
{name: "built-in metrics", builtIn: true, wantHeaderCallsPerMethod: 2},
{name: "tracing", tracing: true, wantHeaderCallsPerMethod: 2},
{name: "all sinks", openCensus: true, openTelemetry: true, builtIn: true, tracing: true, wantHeaderCallsPerMethod: 2},
} {
t.Run(tc.name, func(t *testing.T) {
ctx := context.Background()
setGFELatencyMetricsFlag(tc.openCensus)
setOpenTelemetryMetricsFlag(tc.openTelemetry)
if err := view.Register(GFELatencyView); err != nil {
t.Fatal(err)
}
defer view.Unregister(GFELatencyView)
spans := tracetest.NewInMemoryExporter()
if tc.tracing {
tp := sdktrace.NewTracerProvider(sdktrace.WithSyncer(spans))
defer tp.Shutdown(ctx)
otel.SetTracerProvider(tp)
} else {
otel.SetTracerProvider(noop.NewTracerProvider())
}
config := ClientConfig{DisableNativeMetrics: true}
otReader, otProvider := newTestMeterProvider()
config.OpenTelemetryMeterProvider = otProvider
builtInReader, builtInProvider := newTestMeterProvider()
if tc.builtIn {
config.ClientMetricsProvider = builtInProvider
}
counter := &streamHeaderCounter{calls: map[string]int{}}
server, opts, serverTeardown := NewMockedSpannerInMemTestServer(t, queryTiming)
defer serverTeardown()
opts = append(opts, option.WithGRPCDialOption(grpc.WithChainStreamInterceptor(counter.interceptor)))
client, err := NewClientWithConfig(ctx, "projects/p/instances/i/databases/d", config, opts...)
if err != nil {
t.Fatal(err)
}
defer client.Close()
columns := []string{"SingerId", "AlbumId", "AlbumTitle"}
if err := client.Single().Query(ctx, NewStatement(SelectSingerIDAlbumIDAlbumTitleFromAlbums)).Do(func(*Row) error { return nil }); err != nil {
t.Fatalf("Query failed: %v", err)
}
if err := client.Single().Read(ctx, "Albums", AllKeys(), columns).Do(func(*Row) error { return nil }); err != nil {
t.Fatalf("Read failed: %v", err)
}
txn, err := client.BatchReadOnlyTransaction(ctx, StrongRead())
if err != nil {
t.Fatal(err)
}
defer txn.Cleanup(ctx)
queryPartitions, err := txn.PartitionQuery(ctx, NewStatement(SelectSingerIDAlbumIDAlbumTitleFromAlbums), PartitionOptions{MaxPartitions: 1})
if err != nil {
t.Fatal(err)
}
readPartitions, err := txn.PartitionRead(ctx, "Albums", AllKeys(), columns, PartitionOptions{MaxPartitions: 1})
if err != nil {
t.Fatal(err)
}
for _, p := range []*Partition{queryPartitions[0], readPartitions[0]} {
if err := server.TestSpanner.PutPartitionResult(p.pt, server.CreateSingleRowSingersResult(0)); err != nil {
t.Fatal(err)
}
if err := txn.Execute(ctx, p).Do(func(*Row) error { return nil }); err != nil {
t.Fatalf("Execute failed: %v", err)
}
}
for _, method := range []string{executeStreamingSQL, streamingRead} {
if got := counter.get(method); got != tc.wantHeaderCallsPerMethod {
t.Errorf("%s Header() calls = %d, want %d", method, got, tc.wantHeaderCallsPerMethod)
}
}
// Partitioned queries and reads both record under "Execute".
sinkLatency := map[string]int64{"query": 456, "ReadWithOptions": 123, "Execute": 456 + 123}
sinkMethods := slices.Collect(maps.Keys(sinkLatency))
wantOT := map[string]int64{}
if tc.openTelemetry {
wantOT = sinkLatency
}
if got := latencySumsByAttr(t, collectTestMetrics(t, otReader), metricsPrefix+"gfe_latency", string(attributeKeyMethod), sinkMethods...); !reflect.DeepEqual(got, wantOT) {
t.Errorf("OpenTelemetry GFE latency sums = %v, want %v", got, wantOT)
}
wantOC := map[string]int64{}
if tc.openCensus {
wantOC = sinkLatency
}
if got := openCensusLatencySums(t, sinkMethods); !reflect.DeepEqual(got, wantOC) {
t.Errorf("OpenCensus GFE latency sums = %v, want %v", got, wantOC)
}
wantBuiltIn := map[string]int64{}
if tc.builtIn {
wantBuiltIn = map[string]int64{"Spanner.ExecuteStreamingSql": 2 * 456, "Spanner.StreamingRead": 2 * 123}
}
gotBuiltIn := latencySumsByAttr(t, collectTestMetrics(t, builtInReader), clientMetricsPrefix+metricNameGFELatencies, metricLabelKeyMethod, "Spanner.ExecuteStreamingSql", "Spanner.StreamingRead")
if !reflect.DeepEqual(gotBuiltIn, wantBuiltIn) {
t.Errorf("built-in GFE latency sums = %v, want %v", gotBuiltIn, wantBuiltIn)
}
var gotSpanLatencies []float64
for _, span := range spans.GetSpans() {
if span.Name != "cloud.google.com/go/spanner.RowIterator" {
continue
}
for _, attr := range span.Attributes {
if attr.Key == "gfe.latency_ms" {
gotSpanLatencies = append(gotSpanLatencies, attr.Value.AsFloat64())
}
}
}
var wantSpanLatencies []float64
if tc.tracing {
wantSpanLatencies = []float64{123, 123, 456, 456}
}
sort.Float64s(gotSpanLatencies)
if !reflect.DeepEqual(gotSpanLatencies, wantSpanLatencies) {
t.Errorf("RowIterator span gfe.latency_ms = %v, want %v", gotSpanLatencies, wantSpanLatencies)
}
})
}
}
// latencySumsByAttr returns the sum of the histogram named name for each of the
// given values of the attribute key.
func latencySumsByAttr(t *testing.T, rm metricdata.ResourceMetrics, name, key string, values ...string) map[string]int64 {
t.Helper()
sums := map[string]int64{}
m, ok := findTestMetric(rm, name)
if !ok {
return sums
}
add := func(attrs attribute.Set, sum int64) {
v, _ := attrs.Value(attribute.Key(key))
if slices.Contains(values, v.AsString()) {
sums[v.AsString()] += sum
}
}
switch data := m.Data.(type) {
case metricdata.Histogram[int64]:
for _, dp := range data.DataPoints {
add(dp.Attributes, dp.Sum)
}
case metricdata.Histogram[float64]:
for _, dp := range data.DataPoints {
add(dp.Attributes, int64(dp.Sum))
}
default:
t.Fatalf("metric %q data type = %T, want a histogram", name, m.Data)
}
return sums
}
func TestGFELatencyHeaderOptions(t *testing.T) {
origFlag := getGFELatencyMetricsFlag()
t.Cleanup(func() { setGFELatencyMetricsFlag(origFlag) })
for _, tc := range []struct {
name string
ocFlag bool
hasOpenCensusContext bool
otConfig *openTelemetryConfig
wantHeader bool
}{
{name: "no sinks"},
{name: "OpenCensus flag without context", ocFlag: true},
{name: "OpenCensus flag and context", ocFlag: true, hasOpenCensusContext: true, wantHeader: true},
{name: "OpenTelemetry disabled", otConfig: &openTelemetryConfig{}},
{name: "OpenTelemetry enabled", otConfig: &openTelemetryConfig{enabled: true}, wantHeader: true},
} {
t.Run(tc.name, func(t *testing.T) {
setGFELatencyMetricsFlag(tc.ocFlag)
var md metadata.MD
var settings gax.CallSettings
for _, opt := range gfeLatencyHeaderOptions(&md, tc.hasOpenCensusContext, tc.otConfig) {
opt.Resolve(&settings)
}
var gotHeader bool
for _, opt := range settings.GRPC {
if h, ok := opt.(grpc.HeaderCallOption); ok && h.HeaderAddr == &md {
gotHeader = true
}
}
if gotHeader != tc.wantHeader || len(settings.GRPC) > 1 {
t.Fatalf("gfeLatencyHeaderOptions() gRPC options = %v, want header capture %v", settings.GRPC, tc.wantHeader)
}
})
}
}
// headerRequestCounter counts, per method, the calls that request the response
// headers with grpc.Header. Installed with grpc.WithUnaryInterceptor and
// grpc.WithStreamInterceptor, it runs before every chained interceptor, so it
// only sees the requests made by the Spanner client call sites.
type headerRequestCounter struct {
mu sync.Mutex
calls map[string]int
}
func (c *headerRequestCounter) count(method string, opts []grpc.CallOption) {
c.mu.Lock()
defer c.mu.Unlock()
for _, opt := range opts {
// Request ID options use a grpc.Header option that already holds the
// outgoing request ID; they do not capture response headers for a sink.
if h, ok := opt.(grpc.HeaderCallOption); ok && len(*h.HeaderAddr) == 0 {
c.calls[method]++
}
}
}
func (c *headerRequestCounter) unary(ctx context.Context, method string, req, reply any, cc *grpc.ClientConn, invoker grpc.UnaryInvoker, opts ...grpc.CallOption) error {
c.count(method, opts)
return invoker(ctx, method, req, reply, cc, opts...)
}
func (c *headerRequestCounter) stream(ctx context.Context, desc *grpc.StreamDesc, cc *grpc.ClientConn, method string, streamer grpc.Streamer, opts ...grpc.CallOption) (grpc.ClientStream, error) {
c.count(method, opts)
return streamer(ctx, desc, cc, method, opts...)
}
func (c *headerRequestCounter) get() map[string]int {
c.mu.Lock()
defer c.mu.Unlock()
return maps.Clone(c.calls)
}
// TestResponseHeadersOnlyRequestedWhenUsed runs the unary calls that feed the
// GFE latency sinks, and a BatchWrite, through the public client. It verifies
// that the response headers are only requested when a sink uses them, that
// every enabled sink still records the latency of each call, and that server
// timing span attributes are unchanged.
func TestResponseHeadersOnlyRequestedWhenUsed(t *testing.T) {
const (
beginTransaction = "/google.spanner.v1.Spanner/BeginTransaction"
executeSQL = "/google.spanner.v1.Spanner/ExecuteSql"
executeBatchDml = "/google.spanner.v1.Spanner/ExecuteBatchDml"
commit = "/google.spanner.v1.Spanner/Commit"
partitionQuery = "/google.spanner.v1.Spanner/PartitionQuery"
partitionRead = "/google.spanner.v1.Spanner/PartitionRead"
createSession = "/google.spanner.v1.Spanner/CreateSession"
batchWrite = "/google.spanner.v1.Spanner/BatchWrite"
)
// The mock server sends "gfet4t7; dur=123" for CreateSession. Send a
// different value for every other method to tell them apart.
gfeLatency := map[string]int64{
beginTransaction: 11,
executeSQL: 22,
executeBatchDml: 33,
commit: 44,
partitionQuery: 55,
partitionRead: 66,
batchWrite: 77,
}
serverTiming := func(method string) metadata.MD {
return metadata.Pairs("server-timing", fmt.Sprintf("gfet4t7; dur=%d", gfeLatency[method]))
}
unaryTiming := grpc.UnaryInterceptor(func(ctx context.Context, req any, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (any, error) {
if _, ok := gfeLatency[info.FullMethod]; ok {
if err := grpc.SetHeader(ctx, serverTiming(info.FullMethod)); err != nil {
return nil, err
}
}
return handler(ctx, req)
})
batchWriteTiming := grpc.StreamInterceptor(func(srv any, stream grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
if info.FullMethod == batchWrite {
if err := stream.SetHeader(serverTiming(batchWrite)); err != nil {
return err
}
}
return handler(srv, stream)
})
// Other tests in this package enable OpenCensus GFE latency metrics and
// install a recording tracer provider, so set every sink explicitly.
origOTFlag := IsOpenTelemetryMetricsEnabled()
origOCFlag := getGFELatencyMetricsFlag()
origTracerProvider := otel.GetTracerProvider()
t.Cleanup(func() {
setOpenTelemetryMetricsFlag(origOTFlag)
setGFELatencyMetricsFlag(origOCFlag)
otel.SetTracerProvider(origTracerProvider)
})
// The sink method names of the calls below, and the GFE latency each
// records once.
sinkLatency := map[string]int64{
"begin_BeginTransaction": 11,
"update": 22,
"batchUpdateWithOptions": 33,
"commit": 44,
"partitionQuery": 55,
"PartitionReadUsingIndexWithOptions": 66,
"executePdml_ExecuteSql": 22,
"executeCreateSession": 123,
"createSession": 123,
}
sinkMethods := append(slices.Collect(maps.Keys(sinkLatency)), "BatchWrite")
// The calls below request the headers of these methods once each, except
// ExecuteSql, which runs for both an update and a partitioned update, and
// CreateSession, which runs for the multiplexed session and createSession.
sinkHeaderRequests := map[string]int{
createSession: 2,
beginTransaction: 1,
executeSQL: 2,
executeBatchDml: 1,
commit: 1,
partitionQuery: 1,
partitionRead: 1,
}
for _, tc := range []struct {
name string
openCensus, openTelemetry, builtIn bool
tracing bool
wantHeaderRequests map[string]int
}{
{name: "no sinks", wantHeaderRequests: map[string]int{}},
{name: "tracing", tracing: true, wantHeaderRequests: map[string]int{}},
{name: "built-in metrics", builtIn: true, wantHeaderRequests: map[string]int{}},
{name: "OpenCensus", openCensus: true, wantHeaderRequests: sinkHeaderRequests},
{name: "OpenTelemetry", openTelemetry: true, wantHeaderRequests: sinkHeaderRequests},
{name: "all sinks", openCensus: true, openTelemetry: true, builtIn: true, tracing: true, wantHeaderRequests: sinkHeaderRequests},
} {
t.Run(tc.name, func(t *testing.T) {
ctx := context.Background()
setGFELatencyMetricsFlag(tc.openCensus)
setOpenTelemetryMetricsFlag(tc.openTelemetry)
if err := view.Register(GFELatencyView); err != nil {
t.Fatal(err)
}
defer view.Unregister(GFELatencyView)
spans := tracetest.NewInMemoryExporter()
if tc.tracing {
tp := sdktrace.NewTracerProvider(sdktrace.WithSyncer(spans))
defer tp.Shutdown(ctx)
otel.SetTracerProvider(tp)
} else {
otel.SetTracerProvider(noop.NewTracerProvider())
}
otReader, otProvider := newTestMeterProvider()
config := ClientConfig{DisableNativeMetrics: true, OpenTelemetryMeterProvider: otProvider}
builtInReader, builtInProvider := newTestMeterProvider()
if tc.builtIn {
config.ClientMetricsProvider = builtInProvider
}
headerRequests := &headerRequestCounter{calls: map[string]int{}}
streamHeaders := &streamHeaderCounter{calls: map[string]int{}}
_, opts, serverTeardown := NewMockedSpannerInMemTestServer(t, unaryTiming, batchWriteTiming)
defer serverTeardown()
opts = append(opts,
option.WithGRPCDialOption(grpc.WithUnaryInterceptor(headerRequests.unary)),
option.WithGRPCDialOption(grpc.WithStreamInterceptor(headerRequests.stream)),
option.WithGRPCDialOption(grpc.WithChainStreamInterceptor(streamHeaders.interceptor)),
)
client, err := NewClientWithConfig(ctx, "projects/p/instances/i/databases/d", config, opts...)
if err != nil {
t.Fatal(err)
}
defer client.Close()
// BeginTransaction.
ro := client.ReadOnlyTransaction()
if err := ro.Query(ctx, NewStatement(SelectSingerIDAlbumIDAlbumTitleFromAlbums)).Do(func(*Row) error { return nil }); err != nil {
t.Fatalf("Query failed: %v", err)
}
ro.Close()
// ExecuteSql, ExecuteBatchDml and Commit.
if _, err := client.ReadWriteTransaction(ctx, func(ctx context.Context, tx *ReadWriteTransaction) error {
if _, err := tx.Update(ctx, NewStatement(UpdateBarSetFoo)); err != nil {
return err
}
_, err := tx.BatchUpdate(ctx, []Statement{NewStatement(UpdateBarSetFoo)})
return err
}); err != nil {
t.Fatalf("ReadWriteTransaction failed: %v", err)
}
// PartitionQuery and PartitionRead.
txn, err := client.BatchReadOnlyTransaction(ctx, StrongRead())
if err != nil {
t.Fatal(err)
}
if _, err := txn.PartitionQuery(ctx, NewStatement(SelectSingerIDAlbumIDAlbumTitleFromAlbums), PartitionOptions{MaxPartitions: 1}); err != nil {
t.Fatal(err)
}
if _, err := txn.PartitionRead(ctx, "Albums", AllKeys(), []string{"SingerId"}, PartitionOptions{MaxPartitions: 1}); err != nil {
t.Fatal(err)
}
txn.Cleanup(ctx)
// ExecuteSql of a partitioned update.
if _, err := client.PartitionedUpdate(ctx, NewStatement(UpdateBarSetFoo)); err != nil {
t.Fatalf("PartitionedUpdate failed: %v", err)
}
// CreateSession of a regular session.
if _, err := client.sc.createSession(ctx); err != nil {
t.Fatalf("createSession failed: %v", err)
}
iter := client.BatchWrite(ctx, []*MutationGroup{{Mutations: []*Mutation{Insert("Albums", []string{"SingerId"}, []any{1})}}})
if err := iter.Do(func(*spannerpb.BatchWriteResponse) error { return nil }); err != nil {
t.Fatalf("BatchWrite failed: %v", err)
}
if got := headerRequests.get(); !reflect.DeepEqual(got, tc.wantHeaderRequests) {
t.Errorf("header requests = %v, want %v", got, tc.wantHeaderRequests)
}
// As for streaming queries and reads, BatchWrite reads the headers
// of its stream once if built-in metrics or tracing use them.
wantBatchWriteHeaders := 0
if tc.builtIn || tc.tracing {
wantBatchWriteHeaders = 1
}
if got := streamHeaders.get(batchWrite); got != wantBatchWriteHeaders {
t.Errorf("BatchWrite Header() calls = %d, want %d", got, wantBatchWriteHeaders)
}
wantOT := map[string]int64{}
if tc.openTelemetry {
wantOT = sinkLatency
}
if got := latencySumsByAttr(t, collectTestMetrics(t, otReader), metricsPrefix+"gfe_latency", string(attributeKeyMethod), sinkMethods...); !reflect.DeepEqual(got, wantOT) {
t.Errorf("OpenTelemetry GFE latency sums = %v, want %v", got, wantOT)
}
wantOC := map[string]int64{}
if tc.openCensus {
wantOC = sinkLatency
}
if got := openCensusLatencySums(t, sinkMethods); !reflect.DeepEqual(got, wantOC) {
t.Errorf("OpenCensus GFE latency sums = %v, want %v", got, wantOC)
}
builtInMetrics := collectTestMetrics(t, builtInReader)
// The built-in metrics interceptor records every unary call,
// including the BeginTransaction of the batch transaction and of
// the partitioned update. BatchWrite records the GFE latency of its
// stream.
builtInLatency := map[string]int64{
"Spanner.BatchWrite": 77,
"Spanner.CreateSession": 2 * 123,
"Spanner.BeginTransaction": 3 * 11,
"Spanner.ExecuteSql": 2 * 22,
"Spanner.ExecuteBatchDml": 33,
"Spanner.Commit": 44,
"Spanner.PartitionQuery": 55,
"Spanner.PartitionRead": 66,
}
wantBuiltIn := map[string]int64{}
if tc.builtIn {
wantBuiltIn = builtInLatency
}
if got := latencySumsByAttr(t, builtInMetrics, clientMetricsPrefix+metricNameGFELatencies, metricLabelKeyMethod, slices.Collect(maps.Keys(builtInLatency))...); !reflect.DeepEqual(got, wantBuiltIn) {
t.Errorf("built-in GFE latency sums = %v, want %v", got, wantBuiltIn)
}
// The built-in metrics interceptor sets the server timing span
// attributes of unary calls independently of the sinks, and
// BatchWrite sets them on the span of its iterator. The partition
// calls do not start a span.
gotSpanLatencies := map[float64]bool{}
for _, span := range spans.GetSpans() {
for _, attr := range span.Attributes {
if attr.Key == "gfe.latency_ms" {
gotSpanLatencies[attr.Value.AsFloat64()] = true
}
}
}
wantSpanLatencies := map[float64]bool{}
if tc.tracing {
wantSpanLatencies = map[float64]bool{11: true, 22: true, 33: true, 44: true, 77: true, 123: true}
}
if !reflect.DeepEqual(gotSpanLatencies, wantSpanLatencies) {
t.Errorf("span gfe.latency_ms values = %v, want %v", gotSpanLatencies, wantSpanLatencies)
}
})
}
}
// openCensusLatencySums returns the sum of the OpenCensus GFE latency view
// for each of the given methods.
func openCensusLatencySums(t *testing.T, methods []string) map[string]int64 {
t.Helper()
rows, err := view.RetrieveData(GFELatencyView.Name)
if err != nil {
t.Fatal(err)
}
sums := map[string]int64{}
for _, row := range rows {
for _, tag := range row.Tags {
if tag.Key == tagKeyMethod && slices.Contains(methods, tag.Value) {
sums[tag.Value] += int64(row.Data.(*view.DistributionData).Sum())
}
}
}
return sums
}
// TestStreamCreationFailureRecordsBuiltInMetrics verifies that a query, read
// or BatchWrite whose stream fails to open records one failed attempt and
// operation for the streaming method.
func TestStreamCreationFailureRecordsBuiltInMetrics(t *testing.T) {
reject := grpc.WithChainStreamInterceptor(func(ctx context.Context, desc *grpc.StreamDesc, cc *grpc.ClientConn, method string, streamer grpc.Streamer, opts ...grpc.CallOption) (grpc.ClientStream, error) {
return nil, status.Error(codes.InvalidArgument, "rejected before sending")
})
for _, tc := range []struct {
name string
method string
run func(context.Context, *Client) error
}{
{
name: "query",
method: "Spanner.ExecuteStreamingSql",
run: func(ctx context.Context, client *Client) error {
return client.Single().Query(ctx, NewStatement(SelectSingerIDAlbumIDAlbumTitleFromAlbums)).Do(func(*Row) error { return nil })
},
},
{
name: "read",
method: "Spanner.StreamingRead",
run: func(ctx context.Context, client *Client) error {
return client.Single().Read(ctx, "Albums", AllKeys(), []string{"SingerId"}).Do(func(*Row) error { return nil })
},
},
{
name: "BatchWrite",
method: "Spanner.BatchWrite",
run: func(ctx context.Context, client *Client) error {
return client.BatchWrite(ctx, []*MutationGroup{{[]*Mutation{Insert("Albums", []string{"SingerId"}, []any{1})}}}).Do(func(*spannerpb.BatchWriteResponse) error { return nil })
},
},
} {
t.Run(tc.name, func(t *testing.T) {
ctx := context.Background()
reader, provider := newTestMeterProvider()
_, opts, serverTeardown := NewMockedSpannerInMemTestServer(t)
defer serverTeardown()
opts = append(opts, option.WithGRPCDialOption(reject))
client, err := NewClientWithConfig(ctx, "projects/p/instances/i/databases/d", ClientConfig{DisableNativeMetrics: true, ClientMetricsProvider: provider}, opts...)
if err != nil {
t.Fatal(err)
}
defer client.Close()
if err := tc.run(ctx, client); ErrCode(err) != codes.InvalidArgument {
t.Fatalf("error = %v, want code %v", err, codes.InvalidArgument)
}
want := map[string]int64{
"attempt_count": 1,
"attempt_latencies": 1,
"gfe_connectivity_error_count": 1,
"operation_count": 1,
"operation_latencies": 1,
}
got := builtInMetricValues(collectTestMetrics(t, reader), tc.method, "InvalidArgument")
if diff := cmp.Diff(want, got); diff != "" {
t.Errorf("built-in metrics of %s mismatch (-want +got):\n%s", tc.method, diff)
}
})
}
}
// builtInMetricValues returns the value of each built-in client metric
// recorded for the given method and status code, keyed by metric name without its
// prefix. Counters are summed and histograms report their number of
// recordings.
func builtInMetricValues(rm metricdata.ResourceMetrics, method, code string) map[string]int64 {
values := map[string]int64{}
matches := func(a attribute.Set) bool {
m, _ := a.Value(attribute.Key(metricLabelKeyMethod))
s, _ := a.Value(attribute.Key(metricLabelKeyStatus))
return m.AsString() == method && s.AsString() == code
}
for _, sm := range rm.ScopeMetrics {
for _, m := range sm.Metrics {
name := strings.TrimPrefix(m.Name, clientMetricsPrefix)
switch data := m.Data.(type) {
case metricdata.Sum[int64]:
for _, dp := range data.DataPoints {
if matches(dp.Attributes) {
values[name] += dp.Value
}
}
case metricdata.Histogram[float64]:
for _, dp := range data.DataPoints {
if matches(dp.Attributes) {
values[name] += int64(dp.Count)
}
}
}
}
}
return values
}
// TestBatchWriteRecordsServerTiming verifies that, as for streaming queries
// and reads, the server-timing header of a BatchWrite stream is recorded in
// the built-in GFE latency metric and on the BatchWriteResponseIterator span.
func TestBatchWriteRecordsServerTiming(t *testing.T) {
const batchWrite = "/google.spanner.v1.Spanner/BatchWrite"
batchWriteTiming := grpc.StreamInterceptor(func(srv any, stream grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
if info.FullMethod == batchWrite {
if err := stream.SetHeader(metadata.Pairs("server-timing", "gfet4t7; dur=789")); err != nil {
return err
}
}
return handler(srv, stream)
})
origTracerProvider := otel.GetTracerProvider()
t.Cleanup(func() { otel.SetTracerProvider(origTracerProvider) })
ctx := context.Background()
spans := tracetest.NewInMemoryExporter()
tp := sdktrace.NewTracerProvider(sdktrace.WithSyncer(spans))
defer tp.Shutdown(ctx)
otel.SetTracerProvider(tp)
reader, provider := newTestMeterProvider()
_, opts, serverTeardown := NewMockedSpannerInMemTestServer(t, batchWriteTiming)
defer serverTeardown()
client, err := NewClientWithConfig(ctx, "projects/p/instances/i/databases/d", ClientConfig{DisableNativeMetrics: true, ClientMetricsProvider: provider}, opts...)
if err != nil {
t.Fatal(err)
}
defer client.Close()
mgs := []*MutationGroup{{[]*Mutation{Insert("Albums", []string{"SingerId"}, []any{1})}}}
if err := client.BatchWrite(ctx, mgs).Do(func(*spannerpb.BatchWriteResponse) error { return nil }); err != nil {
t.Fatalf("BatchWrite failed: %v", err)
}
want := map[string]int64{"Spanner.BatchWrite": 789}
if got := latencySumsByAttr(t, collectTestMetrics(t, reader), clientMetricsPrefix+metricNameGFELatencies, metricLabelKeyMethod, "Spanner.BatchWrite"); !reflect.DeepEqual(got, want) {
t.Errorf("built-in GFE latency sums = %v, want %v", got, want)
}
// Both the BatchWrite span and the span of the iterator are ended.
var gotSpanNames []string
for _, span := range spans.GetSpans() {
if strings.HasPrefix(span.Name, "cloud.google.com/go/spanner.BatchWrite") {
gotSpanNames = append(gotSpanNames, span.Name)
}
}
sort.Strings(gotSpanNames)
if diff := cmp.Diff([]string{"cloud.google.com/go/spanner.BatchWrite", "cloud.google.com/go/spanner.BatchWriteResponseIterator"}, gotSpanNames); diff != "" {
t.Errorf("ended spans mismatch (-want +got):\n%s", diff)
}
var gotSpanLatencies []float64
for _, span := range spans.GetSpans() {
if span.Name != "cloud.google.com/go/spanner.BatchWriteResponseIterator" {
continue
}
for _, attr := range span.Attributes {
if attr.Key == "gfe.latency_ms" {
gotSpanLatencies = append(gotSpanLatencies, attr.Value.AsFloat64())
}
}
}
if wantSpanLatencies := []float64{789}; !reflect.DeepEqual(gotSpanLatencies, wantSpanLatencies) {
t.Errorf("BatchWriteResponseIterator span gfe.latency_ms = %v, want %v", gotSpanLatencies, wantSpanLatencies)
}
}