このトピックでは、Spanner コンポーネントを調べてレイテンシの原因を特定し、OpenCensus を使用してそのレイテンシを可視化する方法について説明します。このトピックのコンポーネントの概要については、Spanner リクエストのレイテンシ ポイントをご覧ください。
Spanner クライアント ライブラリは、OpenCensus オブザーバビリティ フレームワークを使用して統計情報とトレースを提供します。このフレームワークは、クライアントの内部の分析情報を提供し、エンドツーエンドの(往復)レイテンシのトラブルシューティングを支援します。デフォルトでは、フレームワークは無効になっています。
準備
レイテンシ ポイントを特定するの手順に沿って、レイテンシが発生しているコンポーネントを見つけます。
クライアントの往復レイテンシをキャプチャして可視化する
クライアントのラウンドトリップ レイテンシは、クライアントが Google Front End(GFE)と Spanner API フロントエンドの両方からデータベースに送信する Spanner API リクエストの最初のバイトと、クライアントがデータベースから受信したレスポンスの最後のバイトの間の時間(ミリ秒単位)です。
クライアントの往復レイテンシをキャプチャする
次の言語に対する、クライアントの往復レイテンシをキャプチャできます。
クライアントの往復レイテンシを可視化する
指標を取得した後、Cloud Monitoring でクライアントの往復レイテンシを可視化できます。
クライアントの往復レイテンシ指標で、5 パーセンタイル レイテンシを示すグラフの例を次に示します。パーセンタイルのレイテンシを 50 パーセンタイルまたは 99 パーセンタイルのいずれかに変更するには、[Aggregator] メニューを使用します。
このプログラムでは roundtrip_latency
と呼ばれる OpenCensus ビューが作成されます。
この文字列は、Cloud Monitoring にエクスポートされたときの指標の名前の一部となります。
![Cloud Monitoring クライアントの往復レイテンシ](https://cloud.google.com/static/spanner/docs/images/cloud-monitoring-roundtrip-latency.png?hl=ja)
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 にエクスポートされたときの指標の名前の一部となります。
![Cloud Monitoring GFE のレイテンシ。](https://cloud.google.com/static/spanner/docs/images/cloud-monitoring-google-front-end-latency.png?hl=ja)
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] メニューを使用します。
![Cloud Monitoring API リクエストのレイテンシ](https://cloud.google.com/static/spanner/docs/images/cloud-monitoring-spanner-front-end-latency.png?hl=ja)
クエリのレイテンシをキャプチャして可視化する
このクエリのレイテンシは、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 にエクスポートされたときの指標の名前の一部となります。
![Cloud Monitoring クエリのレイテンシ](https://cloud.google.com/static/spanner/docs/images/cloud-monitoring-query-stats-latency.png?hl=ja)
次のステップ