デベロッパー

OpenCensus と Go クライアントライブラリを使用した Cloud Spanner レイテンシのデバッグ

2022年7月26日

Google Cloud Japan Team

※この投稿は米国時間 2022 年 7 月 15 日に、Google Cloud blog に投稿されたものの抄訳です。

「クライアント側で高レイテンシが報告されているにもかかわらず、Cloud Spanner の指標には該当のレイテンシが表示されない」といった状況に直面した経験があるかもしれません。この記事では、セッションプールの枯渇が原因でクライアントサイドのレイテンシ増加が引き起こされるケーススタディと、OpenCensus の機能と Go 用 Cloud Spanner クライアントライブラリを使用した状況診断の方法について説明します。

ケーススタディ

今回のテストの概要は次のとおりです。

Go クライアントライブラリのバージョン: 1.33.0
SessionPoolConfig: {MaxOpened: 100, MinOpened: 40, MaxIdle: 20, WriteSessions: 0.20}

セッションプールを使用することで、us-west2 の GCE VM から us-central1 の Cloud Spanner DB に対して、複数の読み取り / 書き込みエージェントが並行してトランザクションを実行します。一般的には、パフォーマンス向上させるために、クライアントを Cloud Spanner DB により近い場所に配置することが推奨されます。このケーススタディでは、あえて遠く離れたクライアントマシンを使用して、ネットワークのレイテンシを見分けやすくし、クライアントとサーバーに負荷をかけすぎることなく、セッションを適度な時間だけ使用できるようにします。

このテストの準備として、次のサンプルリーダーボードスキーマを使用しました。1000000000～9000000000 からランダムに抜き出した PlayerId をサンプルコードで使用するのではなく、このテストでは PlayerId として 1 から 1000 までの連続した ID を使用しました。エージェントがトランザクションを実行する際には、1～1000 の範囲からランダムな ID が 1 つ選ばれました。

読み取りエージェント:

（1）1 行をランダムに読み取って反復処理を実行し、読み取り専用のトランザクションを終了。
"SELECT * FROM Players p JOIN Scores s ON p.PlayerId = s.PlayerId WHERE p.PlayerId=@Id ORDER BY s.Score DESC LIMIT 10"
（2）100 ミリ秒スリーブ。

書き込みエージェント:

（1）1 つの行を挿入し、読み取り / 書き込みトランザクションを終了。
"INSERT INTO Scores(PlayerId, Score, Timestamp) VALUES (@playerID, @score, @timestamp)"
（2）100 ミリ秒スリーブ。

それぞれのシナリオで異なる同時実行が発生し、各エージェントが（1）～（2）を 10 分間繰り返しました。3 と 4、6 と 7 の間にはそれぞれ 15 分の間隔があり、これにより、セッションプールの縮小を確認できます。

https://storage.googleapis.com/gweb-cloudblog-publish/images/Screen_Shot_2022-07-13_at_2.48.38_PM.max-900x900.png

次のグラフはスループット（1 秒あたりのリクエスト数）を示しています。シナリオ 8 までは、スループットが一定の割合で増加しました。しかし、シナリオ 9 では、スループットは予測したとおりには増加しませんでした。また、サーバー側の指標には、サーバー側にボトルネックが発生していることが示されませんでした。

https://storage.googleapis.com/gweb-cloudblog-publish/images/image7_Xu5jKD8.max-1600x1600.png

ExecuteSql リクエストと Commit リクエストに対する Cloud Spanner API リクエストのレイテンシ（spanner.googleapis.com/api/request_latencies）はこのテストを通して一定で、99 パーセンタイルと、ほとんどで 0.07 秒以下に保たれていました。

https://storage.googleapis.com/gweb-cloudblog-publish/images/image6_x6zXtti.max-1300x1300.png

インスタンスの CPU 使用率は低く、推奨レート（優先度高 < 65%）を常に下回りました。

https://storage.googleapis.com/gweb-cloudblog-publish/images/image12_R5piBi5.max-1400x1400.png

OpenCensus の指標とトレースを有効にするには

OpenCensus の実例とその他の指標を確認する前に、GO の Cloud Spanner ライブラリで OpenCensus を使用する方法を確認しましょう。

シンプルなアプローチとして、次のような方法があります。

読み込んでいます...

package main

import (
	"context"
	"fmt"
	"log"
	"time"

"cloud.google.com/go/spanner"
	"contrib.go.opencensus.io/exporter/stackdriver"
	"go.opencensus.io/stats"
	"go.opencensus.io/stats/view"
	"go.opencensus.io/tag"
	"go.opencensus.io/trace"
)

func main() {
	var (
		projectID  = "YOUR_PROJECT"
		instanceID = "YOUR_INSTNACE"
		databaseID = "YOUR_DB"
	)

if err := spanner.EnableGfeLatencyView(); err != nil {
		log.Fatalf("Failed to enable Spanner GFE latency view: %v", err)
	}
	// ヘルス チェッカーが統計データを報告できるように、セッション プールを 1 分間以上使用しなければならない場合があります。
	if err := spanner.EnableStatViews(); err != nil {
		log.Fatalf("Failed to enable Spanner stat views: %v", err)
	}

exporter, err := stackdriver.NewExporter(
		stackdriver.Options{
			ProjectID:    projectID,
			MetricPrefix: "spanner-observability-demo",
		})
	if err != nil {
		log.Fatal(err)
	}
	defer exporter.Flush()

view.RegisterExporter(exporter)
	trace.RegisterExporter(exporter)
	trace.ApplyConfig(trace.Config{DefaultSampler: trace.AlwaysSample()}) // または、サンプリング レートを調整します。例: trace.ProbabilitySampler(0.05)

if err := exporter.StartMetricsExporter(); err != nil {
		log.Fatal(err)
	}
	defer exporter.StopMetricsExporter()

// ここに 2 つ目のセクションを追加します。
}

spanner.EnableGfeLatencyView()

GFELatency 指標を有効にします。この指標については、「Cloud Spanner のデバッグで GFE Server-Timing ヘッダーを使用する」で説明しています。

spanner.EnableStatViews()

すべてのセッションプール指標を有効にします。この指標については、「OpenCensus を用いた Cloud Spanner 上のアプリケーションパフォーマンスのトラブルシューティング」で説明しています。

さらに、独自のレイテンシ指標を登録してキャプチャすることもできます。次のコードでは、「my_custom_spanner_api_call_applicaiton_latency」が独自の指標です。キャプチャされるレイテンシは、トランザクションの開始から終了までの時間差です。つまり、クライアントアプリケーションの観点から見た、エンドツーエンドの Cloud Spanner API 呼出しのレイテンシです。上述したメイン関数の下に、次のコードを追加できます。

読み込んでいます...

その後、次のようにレイテンシを測定できます。

読み込んでいます...

// ここに 3 つ目のセクションを追加します。
	db := fmt.Sprintf("projects/%s/instances/%s/databases/%s", projectID, instanceID, databaseID)
	ctx := context.Background()
	client, err := spanner.NewClientWithConfig(ctx, db, spanner.ClientConfig{SessionPoolConfig: spanner.SessionPoolConfig{MaxOpened: 10, MinOpened: 4, MaxIdle: 2, WriteSessions: 0.20}})
	if err != nil {
		log.Fatal(err)
	}
	defer client.Close()

now := time.Now()
	stmt := spanner.NewStatement("SELECT * FROM Players p JOIN Scores s ON p.PlayerId = s.PlayerId WHERE p.PlayerId=@Id ORDER BY s.Score DESC LIMIT 10")
	stmt.Params["Id"] = 1
	iter := client.Single().Query(ctx, stmt)
	if err = iter.Do(func(r *spanner.Row) error { return nil }); err != nil {
		log.Fatal(err)
	}
	latencyMs := time.Since(now).Milliseconds()
	occtx, err := tag.New(ctx, tag.Insert(tagKeyDatabase, databaseID), tag.Insert(tagKeyInstance, instanceID), tag.Insert(tagKeyOp, "write"))
	if err != nil {
		log.Fatal(err)
	}
	stats.Record(occtx, spanApiCallLatencyMs.M(latencyMs))

now = time.Now()
	_, err = client.ReadWriteTransaction(ctx, func(ctx context.Context, txn *spanner.ReadWriteTransaction) error {
		stmt := spanner.Statement{
			SQL:    `INSERT INTO Scores(PlayerId, Score, Timestamp) VALUES (@playerID, @score, @timestamp)`,
			Params: map[string]interface{}{"playerID": 1, "score": 10, "timestamp": time.Now().Format(time.RFC3339Nano)},
		}
		_, err := txn.Update(ctx, stmt)
		if err != nil {
			return err
		}
		return nil
	})
	if err != nil {
		log.Fatal(err)
	}
	latencyMs = time.Since(now).Milliseconds()
	occtx, err = tag.New(ctx, tag.Insert(tagKeyDatabase, databaseID), tag.Insert(tagKeyInstance, instanceID), tag.Insert(tagKeyOp, "write"))
	if err != nil {
		log.Fatal(err)
	}
	stats.Record(occtx, spanApiCallLatencyMs.M(latencyMs))
	time.Sleep(time.Second * 10) // 統計データが送信されるまでしばらく待ちます。プログラムの実行時間が長い場合、この待ち時間は必要ありません。

ケーススタディからの測定結果

サーバー側からクライアントへ収集した統計情報を確認してみましょう。下の図は、Cloud Spanner のエンドツーエンドレイテンシガイドより引用したものです。4 → 3 → 2 → 1 の順に結果を参照します。

https://storage.googleapis.com/gweb-cloudblog-publish/images/image13_QAR6fDr.max-800x800.png

クエリのレイテンシ

クエリのレイテンシを可視化する便利なアプローチの一つとして、Query Insights を使用する方法があります。選択した時間範囲内でデータベースに最も負荷を与えているクエリとタグの概要を取得できます。このシナリオでは、読み取りリクエストの平均レイテンシ（ミリ秒）は 1.84 でした。なお、「SELECT 1」クエリはセッションを維持するためにセッションプールライブラリから発行されます。

https://storage.googleapis.com/gweb-cloudblog-publish/images/image14_4yjUexk.max-1700x1700.png

さらに詳しく調べるには、クエリの統計情報を使用できます。残念ながら、これらのツールではミューテーションデータは利用できませんが、ミューテーションとのロックの競合が心配な場合は、ロックの統計情報を確認できます。

Cloud Spanner API リクエストのレイテンシ

このレイテンシ指標は、前述の Query Insights のクエリレイテンシと比較して大きく乖離しています。後ほどトレースで確認できるとおり、INSERT クエリには ExecuteSql 呼び出しと Commit 呼び出しが含まれることに注意してください。また、ExecuteSql にはセッション管理リクエストによるノイズが多少含まれている点にも留意してください。クエリレイテンシと Cloud Spanner API リクエストのレイテンシの間にギャップが生じる理由は、主に 2 つあります。まず、Query Insights では平均レイテンシが示される一方で、以下の統計データは 99 パーセンタイルのものだということです。次に、Cloud Spanner API フロントエンドが Cloud Spanner Database から遠く離れていたことです。us-west2 と us-central1 の間のネットワークレイテンシはレイテンシの主要因です。

https://storage.googleapis.com/gweb-cloudblog-publish/images/image11_Ryt3M9C.max-1600x1600.png

Google Front End のレイテンシ

GFE レイテンシ指標（OpenCensus/cloud.google.com/go/spanner/gfe_latency）には、基本的に Cloud Spanner API リクエストのレイテンシと同じ内容が示されます。

Cloud Spanner API リクエストのレイテンシと Google Front End のレイテンシを比較することで、このテストを通して Google Front End と Cloud Spanner API フロントエンドの間に大きなレイテンシの差はなかったと解釈できます。

https://storage.googleapis.com/gweb-cloudblog-publish/images/image4_aMoBxK4.max-1500x1500.png

[クライアント] カスタム指標

my_custom_spanner_api_call_applicaiton_latency は、最後のシナリオでより高いレイテンシを示しています。先ほどご覧いただいたように、Cloud Spanner API リクエストのレイテンシと Google Front End のレイテンシのサーバーサイド指標には、午後 11:00 の時点ではそれほど高いレイテンシは表示されていませんでした。

https://storage.googleapis.com/gweb-cloudblog-publish/images/image15_O3h8vVG.max-1300x1300.png

[クライアント] セッションプール指標

各指標の意味は次のとおりです。

num_in_use_sessions: 使用されているセッションの数。
num_read_sessions: 読み取り専用トランザクションに備えてアイドル状態になっているセッションの数。
num_write_prepared_sessions: 読み取り / 書き込みトランザクションに備えてアイドル状態になっているセッションの数
num_sessions_being_prepared: その時点で BeginTransaction 呼び出しを実行するために使用されているセッションの数。BeginTransaction 呼び出しが終了すると、この数は減少します（なお、この呼び出しは Java と C++ のクライアントライブラリでは使用されません。これらのライブラリは、インライン化された BeginTransaction のメカニズムに従い、事前にトランザクションに備えることはありません）。

最後のシナリオの午後 11:00 頃には、num_in_use_sessions は常に最大値の 100 近くまで増加し、一部は num_sessions_being_prepared の状態にあったことがわかります。これは、最後のシナリオでは一貫してセッションプールにアイドル状態のセッションが存在しなかったことを意味します。

これらすべてを考慮すると、my_custom_spanner_api_call_applicaiton_latency での高レイテンシ（アプリケーションコードでキャプチャされたエンドツーエンドの呼び出しレイテンシ）は、セッションプールにアイドルセッションがなかったことが原因で発生したと推測できます。

https://storage.googleapis.com/gweb-cloudblog-publish/images/image9_dCAW4ko.max-1500x1500.png

Cloud Trace

Cloud Trace を調査することで、この推測について重ねて確認できます。前のシナリオの午後 10 時頃には、ReadWriteTransaction の開始後すぐに、「読み取り / 書き込みセッションを取得」したことがトレースイベントで確認できます。

https://storage.googleapis.com/gweb-cloudblog-publish/images/image8_hAomuQx.max-2000x2000.png

一方で、午後 11:00 頃の最後のシナリオでは、読み取り / 書き込みセッションを取得できなかったためにトランザクションが低速であったことが次のトレースに示されています。「読み取り / 書き込みセッションが取得可能になるまで待機中」の状態が繰り返されています。また、トランザクションでは読み取り専用セッションしか取得できず「読み取り専用セッションを取得」のステータスになっていたため、BeginTransaction 呼び出しを行うことによって読み取り / 書き込みトランザクションを開始する必要がありました。

https://storage.googleapis.com/gweb-cloudblog-publish/images/image1_kiX949q.max-2000x2000.png

備考

このケーススタディと指標の確認にはいくつかの注意事項があります。

1）ExecuteSql と ExecuteStreamingSql では、レイテンシの変動がありました。これは、ExecuteSql または ExecuteStreamingSql が作成されるときに、内部で PrepareQuery が実行され、コンパイルされたクエリプランと実行プランがキャッシュに保存されることが原因です（Cloud Spanner の ExecuteQuery リクエストの裏側をご覧ください）。キャッシュは Cloud Spanner API レイヤで発生します。リクエストが別のサーバーを通過した場合は、そのサーバーがリクエストをキャッシュに保存する必要があります。PrepareQuery 呼び出しが行われることで、Cloud Spanner API フロントエンドと Cloud Spanner データベース間に新たなラウンドトリップが加わります。

2）指標、特にロングテールの指標（99 パーセンタイルなど）に注目すると、サーバーサイドのレイテンシがクライアントのレイテンシよりも長く見えるという奇妙なレイテンシ結果が表示されることもあります。このようなことは通常は起こりませんが、間隔、タイミング、測定ポイントの分布といった、さまざまなサンプリング方法の違いに起因して発生する場合があります。全体的な傾向を把握したい場合には、95 パーセンタイルや 50 パーセンタイルなどのより一般的な統計データを確認することをおすすめします。

3）Google Front End のレイテンシと比較すると、クライアントサイドの指標（たとえば my_custom_spanner_api_call_applicaiton_latency）には、プールからセッションを取得する時間だけでなく、さまざまなレイテンシ要因も含まれています。その他のレイテンシ要因には、次のものがあります。

中断されたトランザクションまたは gRPC エラーに対する自動再試行（クライアントライブラリによって異なる）。カスタムタイムアウトおよび再試行を構成できます。
追加のセッションの作成（Cloud Spanner API リクエストのレイテンシで BatchCreateSessions レイテンシが急増します）。
読み取り / 書き込みトランザクションの BeginTransaction。これらは、プール内の読み取り / 書き込みセッション用に自動的に準備されます。BeginTransaction 呼び出しは、読み取り / 書き込みセッションが不足しているため、読み取り / 書き込みセッションに読み取りセッションを使用しなければならない場合や、読み取り / 書き込みセッションが無効、あるいは中断された場合にも発生する可能性があります。
クライアントと Google Front End 間のラウンドトリップ時間。
TCP レベル（TCP 3 ウェイハンドシェイク）と TLS レベル（TLS ハンドシェイク）での接続の確立。

セッションプールの指標に枯渇の問題が表れていない場合、その他の要因を確認する必要があります。

4）アプリケーションコードの外部で ExecuteSql 呼び出しが発生することがあります。これらは、セッションを維持するためにセッションプールライブラリが送信した ping リクエストであると考えられます。

5）クライアントで読み取り / 書き込みトランザクションが非常に頻繁に実行され、読み取り / 書き込みトランザクションのリクエストが読み取り専用セッションを取得するケースがトレースで多く確認される場合には、WriteSessions の比率を高く設定すると便利です。これは、読み取り / 書き込みセッションが実際に使用される前に、事前に BeginTransaction を呼び出すためです。「書き込みセッションの割合を管理する」では、各ライブラリのデフォルト値について説明しています。一方、トラフィック量が少なく、クライアントでセッションが長時間アイドル状態になることが多い場合は、WriteSessions の比率を 0 に設定するとより高い効果が期待できます。セッションがあまり使用されていない場合、準備されたトランザクションがすでに無効になっており、中断される可能性があります。このエラーによるコストは、事前に読み取り / 書き込みトランザクションを準備する場合に比べて高くなります。

6）BatchCreateSessions リクエストはコストと時間のかかるオペレーションです。そのため、セッションプールの MinOpened と MaxOpened を同じ値に設定することをおすすめします。