このトピックでは、Spanner コンポーネントを調べてレイテンシの原因を特定し、OpenCensus を使用してそのレイテンシを可視化する方法について説明します。このトピックのコンポーネントの概要については、Spanner リクエストのレイテンシ ポイントをご覧ください。
Spanner クライアント ライブラリは、OpenCensus オブザーバビリティ フレームワークを使用して統計情報とトレースを提供します。このフレームワークは、クライアントの内部の分析情報を提供し、エンドツーエンドの（往復）レイテンシのトラブルシューティングを支援します。デフォルトでは、フレームワークは無効になっています。
準備
レイテンシ ポイントを特定するの手順に沿って、レイテンシが発生しているコンポーネントを見つけます。
クライアントの往復レイテンシをキャプチャして可視化する
クライアントのラウンドトリップ レイテンシは、クライアントが Google Front End（GFE）と Spanner API フロントエンドの両方からデータベースに送信する Spanner API リクエストの最初のバイトと、クライアントがデータベースから受信したレスポンスの最後のバイトの間の時間（ミリ秒単位）です。
クライアントの往復レイテンシをキャプチャする
次の言語に対する、クライアントの往復レイテンシをキャプチャできます。
クライアントの往復レイテンシを可視化する
指標を取得した後、Cloud Monitoring でクライアントの往復レイテンシを可視化できます。
クライアントの往復レイテンシ指標で、5 パーセンタイル レイテンシを示すグラフの例を次に示します。パーセンタイルのレイテンシを 50 パーセンタイルまたは 99 パーセンタイルのいずれかに変更するには、[Aggregator] メニューを使用します。
このプログラムでは roundtrip_latency と呼ばれる OpenCensus ビューが作成されます。
この文字列は、Cloud Monitoring にエクスポートされたときの指標の名前の一部となります。
GFE レイテンシをキャプチャして可視化する
Google Front End（GFE）のレイテンシは、Google ネットワークがクライアントからリモート プロシージャ コールを受信してから、GFE がレスポンスの最初のバイトを受信するまでの時間（ミリ秒単位）です。
GFE レイテンシをキャプチャする
次の言語に対する、クエリのレイテンシをキャプチャできます。
Go
// We are in the process of adding support in the Cloud Spanner Go Client Library
// to capture the gfe_latency metric.
import (
"context"
"fmt"
"io"
"strconv"
"strings"
spanner "cloud.google.com/go/spanner/apiv1"
gax "github.com/googleapis/gax-go/v2"
sppb "google.golang.org/genproto/googleapis/spanner/v1"
"google.golang.org/grpc"
"google.golang.org/grpc/metadata"
"contrib.go.opencensus.io/exporter/stackdriver"
"go.opencensus.io/stats"
"go.opencensus.io/stats/view"
"go.opencensus.io/tag"
)
// OpenCensus Tag, Measure and View.
var (
KeyMethod = tag.MustNewKey("grpc_client_method")
GFELatencyMs = stats.Int64("cloud.google.com/go/spanner/gfe_latency",
"Latency between Google's network receives an RPC and reads back the first byte of the response", "ms")
GFELatencyView = view.View{
Name: "cloud.google.com/go/spanner/gfe_latency",
Measure: GFELatencyMs,
Description: "Latency between Google's network receives an RPC and reads back the first byte of the response",
Aggregation: view.Distribution(0.0, 0.01, 0.05, 0.1, 0.3, 0.6, 0.8, 1.0, 2.0, 3.0, 4.0, 5.0, 6.0, 8.0, 10.0, 13.0,
16.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),
TagKeys: []tag.Key{KeyMethod}}
)
func queryWithGFELatency(w io.Writer, db string) error {
projectID, _, _, err := parseDatabaseName(db)
if err != nil {
return err
}
ctx := context.Background()
client, err := spanner.NewClient(ctx)
if err != nil {
return err
}
defer client.Close()
// Register OpenCensus views.
err = view.Register(&GFELatencyView)
if err != nil {
return err
}
// Create OpenCensus Stackdriver exporter.
sd, err := stackdriver.NewExporter(stackdriver.Options{
ProjectID: projectID,
})
if err != nil {
return err
}
// It is imperative to invoke flush before your main function exits
defer sd.Flush()
// Start the metrics exporter
sd.StartMetricsExporter()
defer sd.StopMetricsExporter()
// Create a session.
req := &sppb.CreateSessionRequest{Database: db}
session, err := client.CreateSession(ctx, req)
if err != nil {
return err
}
// Execute a SQL query and retrieve the GFE server-timing header in gRPC metadata.
req2 := &sppb.ExecuteSqlRequest{
Session: session.Name,
Sql: `SELECT SingerId, AlbumId, AlbumTitle FROM Albums`,
}
var md metadata.MD
resultSet, err := client.ExecuteSql(ctx, req2, gax.WithGRPCOptions(grpc.Header(&md)))
if err != nil {
return err
}
for _, row := range resultSet.GetRows() {
for _, value := range row.GetValues() {
fmt.Fprintf(w, "%s ", value.GetStringValue())
}
fmt.Fprintf(w, "\n")
}
// The format is: "server-timing: gfet4t7; dur=[GFE latency in ms]"
srvTiming := md.Get("server-timing")[0]
gfeLtcy, err := strconv.Atoi(strings.TrimPrefix(srvTiming, "gfet4t7; dur="))
if err != nil {
return err
}
// Record GFE t4t7 latency with OpenCensus.
ctx, err = tag.New(ctx, tag.Insert(KeyMethod, "ExecuteSql"))
if err != nil {
return err
}
stats.Record(ctx, GFELatencyMs.M(int64(gfeLtcy)))
return nil
}
GFE レイテンシを可視化する
指標を取得した後、Cloud Monitoring でクエリの GEE レイテンシを可視化できます。
以下は、GFE レイテンシ指標の 5 パーセンタイルのレイテンシを示すグラフの例です。パーセンタイルのレイテンシを 50 パーセンタイルまたは 99 パーセンタイルのいずれかに変更するには、[Aggregator] メニューを使用します。
このプログラムでは gfe_latency と呼ばれる OpenCensus ビューが作成されます。この文字列は、Cloud Monitoring にエクスポートされたときの指標の名前の一部となります。
Spanner API リクエストのレイテンシをキャプチャして可視化する
Spanner API リクエストのレイテンシは、Spanner API フロントエンドが受信したリクエストの最初のバイトから Spanner API フロントエンドが送信したレスポンスの最後のバイトまでの時間（秒単位）です。
Spanner API リクエストのレイテンシをキャプチャする
このレイテンシは、デフォルトで Cloud Monitoring の指標の一部として利用できます。キャプチャしてエクスポートする操作は必要ありません。
Spanner API リクエストのレイテンシを可視化する
Metrics Explorer グラフツールを使用すると、Cloud Monitoring で spanner.googleapis.com/api/request_latencies 指標用のグラフを可視化できます。
以下は、Spanner API リクエストのレイテンシ指標の 5 パーセンタイルのレイテンシを示すグラフの例です。パーセンタイルのレイテンシを 50 パーセンタイルまたは 99 パーセンタイルのいずれかに変更するには、[Aggregator] メニューを使用します。
クエリのレイテンシをキャプチャして可視化する
このクエリのレイテンシは、Spanner データベースで SQL クエリを実行するのにかかる時間の長さ（ミリ秒単位）です。
クエリのレイテンシをキャプチャする
次の言語に対する、クエリのレイテンシをキャプチャできます。
Java
private static final String MILLISECOND = "ms";
static final List<Double> RPC_MILLIS_BUCKET_BOUNDARIES =
Collections.unmodifiableList(
Arrays.asList(
0.0, 0.01, 0.05, 0.1, 0.3, 0.6, 0.8, 1.0, 2.0, 3.0, 4.0, 5.0, 6.0, 8.0, 10.0, 13.0,
16.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));
static final Aggregation AGGREGATION_WITH_MILLIS_HISTOGRAM =
Distribution.create(BucketBoundaries.create(RPC_MILLIS_BUCKET_BOUNDARIES));
static MeasureDouble QUERY_STATS_ELAPSED =
MeasureDouble.create(
"cloud.google.com/java/spanner/query_stats_elapsed",
"The execution of the query",
MILLISECOND);
// Register the view. It is imperative that this step exists,
// otherwise recorded metrics will be dropped and never exported.
static View QUERY_STATS_LATENCY_VIEW = View
.create(Name.create("cloud.google.com/java/spanner/query_stats_elapsed"),
"The execution of the query",
QUERY_STATS_ELAPSED,
AGGREGATION_WITH_MILLIS_HISTOGRAM,
Collections.emptyList());
static ViewManager manager = Stats.getViewManager();
private static final StatsRecorder STATS_RECORDER = Stats.getStatsRecorder();
static void captureQueryStatsMetric(DatabaseClient dbClient) {
manager.registerView(QUERY_STATS_LATENCY_VIEW);
// Enable OpenCensus exporters to export metrics to Cloud Monitoring.
// Exporters use Application Default Credentials to authenticate.
// See https://developers.google.com/identity/protocols/application-default-credentials
// for more details.
try {
StackdriverStatsExporter.createAndRegister();
} catch (IOException | IllegalStateException e) {
System.out.println("Error during StackdriverStatsExporter");
}
try (ResultSet resultSet = dbClient.singleUse()
.analyzeQuery(Statement.of("SELECT SingerId, AlbumId, AlbumTitle FROM Albums"),
QueryAnalyzeMode.PROFILE)) {
while (resultSet.next()) {
System.out.printf(
"%d %d %s", resultSet.getLong(0), resultSet.getLong(1), resultSet.getString(2));
}
Value value = resultSet.getStats().getQueryStats()
.getFieldsOrDefault("elapsed_time", Value.newBuilder().setStringValue("0 msecs").build());
double elapasedTime = Double.parseDouble(value.getStringValue().replaceAll(" msecs", ""));
STATS_RECORDER.newMeasureMap()
.put(QUERY_STATS_ELAPSED, elapasedTime)
.record();
}
}
Go
import (
"context"
"fmt"
"io"
"strconv"
"strings"
"cloud.google.com/go/spanner"
"google.golang.org/api/iterator"
"contrib.go.opencensus.io/exporter/stackdriver"
"go.opencensus.io/stats"
"go.opencensus.io/stats/view"
"go.opencensus.io/tag"
)
// OpenCensus Tag, Measure and View.
var (
QueryStatsElapsed = stats.Float64("cloud.google.com/go/spanner/query_stats_elapsed",
"The execution of the query", "ms")
QueryStatsLatencyView = view.View{
Name: "cloud.google.com/go/spanner/query_stats_elapsed",
Measure: QueryStatsElapsed,
Description: "The execution of the query",
Aggregation: view.Distribution(0.0, 0.01, 0.05, 0.1, 0.3, 0.6, 0.8, 1.0, 2.0, 3.0, 4.0, 5.0, 6.0, 8.0, 10.0, 13.0,
16.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),
TagKeys: []tag.Key{}}
)
func queryWithQueryStats(w io.Writer, db string) error {
projectID, _, _, err := parseDatabaseName(db)
if err != nil {
return err
}
ctx := context.Background()
client, err := spanner.NewClient(ctx, db)
if err != nil {
return err
}
defer client.Close()
// Register OpenCensus views.
err = view.Register(&QueryStatsLatencyView)
if err != nil {
return err
}
// Create OpenCensus Stackdriver exporter.
sd, err := stackdriver.NewExporter(stackdriver.Options{
ProjectID: projectID,
})
if err != nil {
return err
}
// It is imperative to invoke flush before your main function exits
defer sd.Flush()
// Start the metrics exporter
sd.StartMetricsExporter()
defer sd.StopMetricsExporter()
// Execute a SQL query and get the query stats.
stmt := spanner.Statement{SQL: `SELECT SingerId, AlbumId, AlbumTitle FROM Albums`}
iter := client.Single().QueryWithStats(ctx, stmt)
defer iter.Stop()
for {
row, err := iter.Next()
if err == iterator.Done {
// Record query execution time with OpenCensus.
elapasedTime := iter.QueryStats["elapsed_time"].(string)
elapasedTimeMs, err := strconv.ParseFloat(strings.TrimSuffix(elapasedTime, " msecs"), 64)
if err != nil {
return err
}
stats.Record(ctx, QueryStatsElapsed.M(elapasedTimeMs))
return nil
}
if err != nil {
return err
}
var singerID, albumID int64
var albumTitle string
if err := row.Columns(&singerID, &albumID, &albumTitle); err != nil {
return err
}
fmt.Fprintf(w, "%d %d %s\n", singerID, albumID, albumTitle)
}
}
クエリのレイテンシを可視化する
指標を取得した後、Cloud Monitoring でクエリのレイテンシを可視化できます。
以下は、クエリのレイテンシ指標の 5 パーセンタイルのレイテンシを示すグラフの例です。パーセンタイルのレイテンシを 50 パーセンタイルまたは 99 パーセンタイルのいずれかに変更するには、[Aggregator] メニューを使用します。
このプログラムでは query_stats_elapsed と呼ばれる OpenCensus ビューが作成されます。
この文字列は、Cloud Monitoring にエクスポートされたときの指標の名前の一部となります。
次のステップ
