こんにちは、メルペイのバックエンドエンジニアの @kazegusuri です。
メルペイではメインのデータベースとしてGoogle Cloud Spannerを利用しています。
マイクロサービスによっては秒間数千リクエストをSpannerで処理しています。
いかにSpannerをスケールできるようにして安定させられるかが会社全体として重要になっています。
本記事では数ヶ月間戦ってきたSpannerのレイテンシが高くなる問題とその解決法について紹介したいと思います。
社内への調査報告も含めて書いているため、かなり詳細で長い内容になっています。
なおこの問題の大部分はGoでSpannerを使ったときにだけ発生する問題のため、Javaなどの他の言語では該当しない可能性があります。
CreateSession問題
ここで紹介しなくても良いくらい基本的なところですが、CreateSessionが非常に遅いという問題があります。
Spannerはデフォルトの設定で使うとセッションをプールしてくれないので、リクエストのたびにセッションを作るためCreateSessionを実行します。
このCreateSessionは約600msはかかるので通常のユースケースでは発生すると間違いなく使い物になりません。
この問題を解決するにはSpannerクライアントを作成するときのオプションにある spanner.SessionPoolConfig を設定すれば良いです。
SessionPoolConfigの設定はどれも非常に重要で、ここでは説明しませんが各値がどのような影響があるかは理解しておいた方が良いです。
むしろ google-cloud-go の挙動を一通り理解しておいた方が以降の問題と戦うときに戦力になります。
Abort問題
Spannerにリクエスト時にAbortが発生して1秒以上かかるという噂が社内で広まりました。
調べてみるとStreamingReadやExecuteStreamingSqlでAbortが発生した場合に1秒以上かかっていることがわかりました。
なぜCommitではAbortしても遅延しないのにStreamingReadなどでは遅延するのか調べるために google-cloud-go の実装を完全に見直しました。
調査編
Spannerのクライアントライブラリは内部で発生したエラーを全てspanner.Error型にしています。
Abort時にはspanner.Error型から遅延時間を取得してその時間だけsleepしてからリトライするようになっています。
CommitとStreamingRead/ExecuteStreamingSqlではそのspanner.Error型の作り方に違いがありました。
Commitではエラー発生時にgRPCのTrailerを見てRetryInfoの値によって遅延時間を設定していました。
しかし、StreamingReadとExecuteStreamingSqlではTrailerをそもそも見ていません。
Abort時のリトライはRetryInfoを見ていない場合はデフォルト値で遅延するようになっており、この値が1秒だったためCommit以外のAbortで遅くなっていました。
遅延時間の判断はTrailerの中に入っているRetryInfoの値で行われるため、まずはRetryInfoがStreamingReadなどで入っているかどうかを確認することにしました。
なるべくgoogle-cloud-go自体をフォークせずに観測できるようにするために、 gRPCのInterceptorを使ってエラー発生時にTrailerに入っている値をログに残すことにしました。
Read系のAbortはCommitのAbortと違って狙って出せるようなものでもないので気長に待つしかないですが、無事エラーも何個か出てTrailerにRetryInfoが入っていることが確認できました。
解決編
ここまでの話からAbortが発生したときの遅延時間が長くなっている問題は2つの解決法があります。
- 正攻法: Read系でTrailerを見られるようにする
- 裏の手: そもそもデフォルトの遅延時間を減らす
この2つのどちらにするか迷っていたら後者の方法で既にGitHubでIssue としてあがっていました。
そのIssueはデフォルトの遅延時間を調整可能にするという内容だったので、それにのっかって実装しても良いかという質問をするとOKという話になりました。
こちらからパッチ を送りました。
そこから長い間のレビューを待っていると本当にその実装は必要なのか…？という話にもどって現状の問題を伝えるところからやりなおしに。
後日この問題についてGoogleの担当者と直接議論する機会ができました。
事前に問題について伝えていたことと相手側でも調査していたことから既に問題があるということは認識されていてどうやって直すかを議論しました。
実はこの議論の前にはすでに遅延時間を1秒から100msにする変更がマージされてリリースまでされていました！
こちらとしてはアプリケーションから遅延時間を調整できるようにしたいわけではなく短くなってくれれば良いということを伝えるとすぐにデフォルトの遅延時間を減らそうという結論になりました。
ただし100msよりもっと減らしても良さそうという話をしていて、後日更に20msまで減らす変更がマージされていました。
それぞれ google-cloud-go の v0.36.0 と v0.37.0 でリリースされたのでSpannerを使う場合は必ずこのバージョン以降を使いましょう。
余談
Abortに関連する問題として Spannerのトランザクションの中でSpannerライブラリのエラーをラップしてはいけないというものがあります。
_, err = client.ReadWriteTransaction(ctx, func(ctx context.Context, tx *spanner.ReadWriteTransaction) error {
_, err := tx.ReadRow(ctx, "Foo", spanner.Key{"foo"}, []string{...})
if err != nil {
return errors.Wrap(err, "ReadRow failed") // wrap error
}
...
return nil
}
Spannerライブラリの特徴としてデータベースからの取得とMutationの作成はコールバック関数の中で実行するようになっていて、どこかでAbortが発生したときのリトライ処理は呼び出し元で判断するようになっています。
ReadRow は spanner.Error を返しますが、呼び出し元でも spanner.Error が返ってくることを期待してエラーハンドリングを行っているため、
errors.Wrap などでReadRowのエラーをラップしてしまうと呼び出し元ではspanner.Errorではないエラーが返ってくるため、Spannerのエラーコードが取得できなくなります。
Spannerのエラーコード自体は GRPCStatus() *status.Status を実装したエラーを返すことで対処できますが、ややこしいので現状ではエラーをラップしてはいけないと覚えた方が良さそうです。
この問題自体の議論としてはこちらのIssueで行われています。
1時間毎に遅くなる問題
長時間Spannerを使ったアプリケーションを動かしていると、CreateSessionの遅延やAbort時のBackoffなどと関係なくきっかり1時間単位で遅くなるという問題が判明しました。
1時間毎に必ず起こるわけではなく、微妙にずれたものが何個か発生している状態です。
ただし、それぞれのエラーのまとまりの間隔はほぼ1時間という周期性を持っていることからSpannerのコネクション単位でなにかあると推測しました。
Spannerはライブラリ内でデフォルト4つのgRPCコネクションを作成して管理するようになっています。
4つの独立したコネクションがそれぞれで1時間単位で何か問題があると考えました。
更にややこしいのはエラーの内容や遅くなっている部分にいろいろなパターンがあることです。
google-cloud-goの内部で遅くなっている場合や、google-cloud-goからSpannerへgRPCのリクエストを送る部分が遅いなど様々です。
また遅くなり方も1秒とかではなく20秒以上かかったり、context.WithTimeoutでタイムアウトを指定しているのにそれ以上かかったりしていました。
あまりに多くの変数がある状態でどこから調査するのか難しい(特にこのときにまだAbort問題は解決していない)のでまずはいろいろな環境やパターンで試して傾向を調査することにしました。
はっきりわかっていることは1時間という周期性をもっていることです。
最低半日から数日かけてそれぞれのパターンの結果を待つということから社内では窯問題と呼ばれています。
数人の有志でそれぞれのお互いの環境でアイデアを元に窯に仕込みをして焼き上がりを待ち、その結果からみんなで議論して新しいアイデアを得る…というのを繰り返し行いました。
トークンリフレッシュ
1時間と聞いて最初に思いついたことがアクセストークンの有効期限です。
Spannerに限らずGCPのリソースにはアクセストークンを発行してそれを使ってアクセスする必要があります。
そのアクセストークンは発行すると1時間の有効期限があり有効期限内では何度も利用できるため、通常はキャッシュしてリクエスト間で使いまわします。
google-cloud-goではそれらのトークン管理を内部的に行ってくれるようになっています。
しかしこの仕組みに課題がありました。
トークン管理の仕組みが有効期限内のトークンがないときに発行する、つまり有効期限が切れたときに初めて新規トークンの発行処理を行うというようになっています。
この発行処理はgRPCのコネクション単位で同時に1つしか行われないようになっているため、Spannerへのリクエストが同時にあったとしても最初の発行処理が完了するまで全てがブロックされます。
つまり、発行処理に時間がかかった場合にそのコネクションの全てのリクエストが時間がかかってしまいます。
実際に発行処理にかかる時間を計測したところ、ほとんどは100ms以下で完了していましたがたまに1秒程度かかることは判明しました。
現状発生している問題の頻度より発行処理が非常に遅くなる頻度の方がかなり低かったため、どれくらいこれが遅延の原因になっているかは自信はなかったですが、
100ms程度でも可能であれば遅延を減らしたいためこの問題を解決することにしました。
この問題は有効期限が切れたタイミングで同期的に処理を行うことによって発生するため、有効期限が切れる前にバックグラウンドで定期的にトークンを再発行できれば良いと考えました。
Goではトークン発行の仕組みは oauth2.TokenSource を使って実装することが多く、Googleのアクセストークンもそのインターフェイスに従って実装されていて、google-cloud-goもライブラリからそれらを利用する形になっています。
google-cloud-goでは oauth2.TokenSourceの任意の実装を指定可能になっています。
goroutineを使ってバックグランドでトークンを定期的に再発行する oauth2.TokenSource を実装して google-cloud-go で使えるようにしました。
実際にこの修正を遅延する問題のあった環境に導入したところ、1時間毎に発生していた遅延が2,3割程度減るようになりました。
思ったよりも多く減ったなという感想と、やはりまだ別の問題があるという課題が残りました。
gRPC再接続
1時間という周期がありそうなものはgoogle-cloud-goやgRPCの実装を見ても他に思い浮かばずに調査が難航していました。
ある日他のチームからSpannerへのgRPCコネクションがたまにTransient Failureになるという話を聞きました。
Transient Failureというのは本来は接続を維持しているはずのSpannerへのコネクションが切断されている状態のことです。
gRPCでは切断されたとしてもバックグランドで再接続が行われますし、コネクションが多重化(subchannel)されている場合は他の生きているコネクションを使うようになっているため問題はありません。
しかしこの切断が結構発生するということで調査してみました。
調査自体は2つの方法で行いました。
1つはgRPCの内部ログを表示することです。
grpc-goではgrpclogパッケージを使っており、設定さえ行えば細かいログを残すようになります。
その中にコネクション(channel)の状態に変化があったときのログも含まれています。
もう1つはgRPCのChannelzを使うことです。
ChannelzはgRPC内部のコネクションの状態をモニタリングする仕組みとその状態にアクセスするAPIがあります。
Channelzの参照にはgdebugというWebUIのものもありますが、自作したCLIの channelzcli を使いました。
ログやChannelzを見ると1時間毎にコネクションが切断されていることがわかり、その時間にちょうど遅延が発生していることがわかりました。
GCPのサポートに確認したところSpannerサーバー側から1時間毎にコネクションを切っているのは間違いないということでした。
ここからなぜ再接続時に遅延が発生するのかという問題について調査することにしました。
google-cloud-goは複数のgRPCコネクションをライブラリ側で扱っています。
ライブラリ内でSpannerのセッション管理を行っていて、あるセッションは1つのコネクションに紐付いて管理されています。
本来なら1つのコネクションを多重化していれば、コネクションの中の一部のsubchannelが切断されたとしてもアクティブなものだけを利用するはずですが、
おそらくセッションの制約のためコネクション自体は多重化はせずに複数のコネクションを扱うようになっています。
この状態でコネクションが切断されると再接続までの間はリクエストが投げられなくなるため全てがブロックされます。
なんらかの原因で再接続までに時間がかかっていると推測して何が遅くなっているのかを調査しました。
DNS問題
もともとGKEの環境でDNSが不安定になっているという話があり別件で調査していたこともあって、DNSが何か影響しているのではないかという推測は初期からしていました。
しかしgRPCが接続を維持することと1時間の周期性から問題からは外していました。
再接続するためにはDNSを引き直すことになるのでここで再度DNSの遅延疑惑がでてきました。
一部のアプリケーションではDNSの問題に影響されないために dnscache を導入してアプリケーションレベルでキャッシュしています。
本来はインフラレベルで解決した方が良いですが、まずは問題を切り分けるためにもSpannerへのアクセス部分にも同様にdnscacheを導入することにしました。
spanner.NewClientWithConfig のオプションで option.WithGRPCDialOption を使うことでgRPCのDialOptionを指定可能であり、ここで grpc.WithContextDialerを使うとDialerの挙動をかえられるので、これを使ってdnscacheを導入可能です。
このdnscacheの修正をいれたものを問題の環境に導入したところ全ての遅延がなくなりました！
実際に問題があるGKEの中でDNSの解決を何度かやっても遅くなるケースはたまにあるものの、ほとんどの場合は遅くなることはないです。
ですがトークンリフレッシュの問題と同様に思った以上に効果がありました。
grpc-goのバグ
DNSのキャッシュで全てが解決されたと思ったら別の環境ではまだ問題が引き続き発生していました。
コネクションが切れている状態でアクセスしようとしてリトライし続けるというものでした。
google-cloud-goではgRPCのリクエストがFailFastになっているので、リクエストを投げようとしたときにコネクションが切れている(Transient Failure)とすぐにUnavailableエラーが返ってきます。
しかしライブラリ側でbackoffしながらリトライするためgRPCの再接続が完了するまで待つようになっています。
gRPCの再接続処理はバックグラウンドで行われるため、再接続自体に時間がかかるとこの挙動になり、DNSが遅い場合にも全く同じ挙動になります。
DNSのキャッシュを導入してもまだ再接続に時間がかかるということで再度調査しました。
調査をするとgrpc-goのバージョンが環境によって異なることがわかりました。
以前からChannelzを全環境で使えるようにするためgrpc-goのバージョンを1.16.0以上にしていましたが、この時点でバージョンは1.19.0まででていました。
各バージョンのdiffを見ていくと1.17.0から1.18.0でgRPCの接続周りのコードが大幅に変更されており、これが影響しているのではないかと考えました。
実際に試してみると 1.16.0と1.17.0ではこの問題は発生しないが、1.18.0と1.19.0では再接続に時間がかかる状況を再現できました。
grpc-goのIssuesを見てみるといくつか同様の報告がされていました。
手元では問題の再現と修正方法がわかっていたため既存のIssue 上で再現コードを送りました。
修正自体はすぐにされましたが、パッチリリースがなかなかされなかったため、一部の環境ではmasterブランチを直接使って問題が解決されていることを確認しました。
現在ではパッチリリースの 1.19.1 や 1.20.0 がでているので、最新のリリース版を使っていれば問題ない状況になりました。
まとめ
Spannerに関わる問題とその解決について紹介しました。
Spanner自体はスケーラブルでレスポンスも早い素晴らしいサービスです。
一方で Cloud Spanner では接続部分の問題やライブラリに言語間で差があったりします。
Javaでは多くの利用者がいるため問題は解決されてそうですが、Goでもこれだけの問題があったので他の言語で選択する場合には注意した方が良いでしょう。
しかし、いろいろな問題があったもののやはりSpanner自体のパフォーマンスはすごく良いと感じています。
現状ではかなり高負荷な環境でもSpannerへの単純なリクエストであれば95%ileで5ms以下、99%ileでも50msから100msいかないくらいのレスポンスです。
まだまだ手放しで使っていける状態ではないですが、メルペイではgoogle-cloud-goやgRPCの問題を解決してSpannerを使っていきたいと思っています。
