Cloud Spannerのセッション枯渇問題の実体験と学び

本稿はJCB Tech Blog Advent Calendar 2022の12月14日の記事です。

JCB デジタルソリューション開発部アプリチームの村井です。
アプリチームではJCBが提供する様々なサービスの開発・運用をしています。
今回は私の担当するサービスを構成するアプリにて発生した問題の実体験と、そこから得られた学びについてご紹介します。
(※ログは全て検証環境で取得し、一部値をマスクしています。)

Cloud Spannerとは

Cloud Spanner（以降Spanner）とはGoogle Cloudが提供するフルマネージドなデータベースのサービスです。
リレーショナルデータベースの構造に加えて水平スケーラビリティの特性を兼ね備えていることが特徴です。またマルチリージョンによる高可用性も実現しています。
このような特徴からSpannerは金融系システムのようにミッションクリティカルなシステムに適したデータベースと言えます。
詳細は公式ページを参照してください。

問題調査とセッション枯渇原因の特定

本題です。

ある日突然、日次でSpannerにアクセスするJavaのバッチ処理アプリが正常終了しないという事象が発生しました。
エラーログなどは特に出力していなかったため、単純に処理に時間がかかっているだけなのか問題が発生しているのかは判別できない状態でした。
一方で、正常であれば数分で処理が正常終了するところ数時間も動き続けていることから、状況証拠で問題発生と見做し、調査を開始しました。

調査1

アプリのハングアップが疑われたので、まずはjstackを使ってスレッドのスタックトレースを確認しました。

"main" #1 prio=5 os_prio=0 cpu=7092.99ms elapsed=642.15s tid=0x00007f8aa0028000
nid=0xb waiting on condition  [0x00007f8aa8cf0000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at jdk.internal.misc.Unsafe.park(java.base@11.0.16.1/Native Method)
    - parking to wait for  <0x00000000f8e1b7b0> (a com.google.common.util.concurrent.SettableFuture)
    at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.16.1/LockSupport.java:234)
    at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:420)
    at com.google.common.util.concurrent.AbstractFuture$TrustedFuture.get(AbstractFuture.java:97)
    at com.google.cloud.spanner.SessionPool$WaiterFuture.pollUninterruptiblyWithTimeout
          (SessionPool.java:1580)
    at com.google.cloud.spanner.SessionPool$WaiterFuture.get(SessionPool.java:1557)
    at com.google.cloud.spanner.SessionPool$WaiterFuture.get(SessionPool.java:1534)
    at com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:62)
    at com.google.cloud.spanner.SessionPool$PooledSessionFuture.get(SessionPool.java:1291)
    at com.google.cloud.spanner.SessionPool$PooledSessionFuture.lambda$singleUse$0
          (SessionPool.java:1131)
    at com.google.cloud.spanner.SessionPool$PooledSessionFuture$$Lambda$679/0x0000000100870440
           .apply(Unknown Source)
    at com.google.cloud.spanner.SessionPool$AutoClosingReadContext.getReadContextDelegate
           (SessionPool.java:233)
    - locked <0x00000000f8e1b838> (a java.lang.Object)
    at com.google.cloud.spanner.SessionPool$AutoClosingReadContext$6.load(SessionPool.java:471)
    at com.google.cloud.spanner.SessionPool$CachedResultSetSupplier.get(SessionPool.java:152)
    at com.google.cloud.spanner.SessionPool$CachedResultSetSupplier.get(SessionPool.java:140)
    at com.google.cloud.spanner.ForwardingResultSet.next(ForwardingResultSet.java:54)
    at com.google.cloud.spanner.SessionPool$AutoClosingReadContext$1.internalNext(SessionPool.java:272)
    at com.google.cloud.spanner.SessionPool$AutoClosingReadContext$1.next(SessionPool.java:252)

lockedが表示されていました。これはスレッドが別のリソースの解放を待っていることを示しています。
間隔をあけて何度かスタックトレースを取得し直しても、表示されるトレースの内容に変化がないことから、予想通り処理がハングアップしていることがわかりました。

スタックトレースの内容から推察するに、どうやらSpannerのセッションプールで問題が起きているようです。そこでSpannerのセッションについて調べてみました。

Spannerにおけるセッションの役割

Spannerではアプリ内のSpannerクライアントがSpannerのサービスに対してあらかじめセッションを生成します。クライアントは生成したセッションをクエリ実行時に使い回すことで、Spannerのサービスとの接続にかかるオーバーヘッドを削減しています。

生成したセッションをセッションプールに蓄えておき、クエリ実行時にセッションプールからセッションを取得し、クエリ実行が終了したらセッションをセッションプールに戻す。
セッションの増減タイミングは3つ存在する。
- クライアントの作成後に設定した最小セッション数を生成する。
- クエリの同時実行数の増加/減少に合わせて設定した最大/最小セッション数の範囲でセッションを生成/破棄する。
- クライアントのプロセス終了時にセッションを全て破棄する。

調査2

次にアプリにOpenSensusを仕込み、再度事象を発生させてSpannerのセッションに関するメトリクスを取得してみました。

# HELP cloud_google_com_java_spanner_num_acquired_sessions_total
  The number of sessions acquired from the session pool.
# TYPE cloud_google_com_java_spanner_num_acquired_sessions_total counter
cloud_google_com_java_spanner_num_acquired_sessions_total
  {client_id="client-1",database="database-1",instance_id="instance-1",library_version="6.23.1",} 50.0
# HELP cloud_google_com_java_spanner_num_released_sessions_total
  The number of sessions released by the user and pool maintainer.
# TYPE cloud_google_com_java_spanner_num_released_sessions_total counter
cloud_google_com_java_spanner_num_released_sessions_total
  {client_id="client-1",database="database-1",instance_id="instance-1",library_version="6.23.1",} 0.0
# HELP cloud_google_com_java_spanner_num_sessions_in_pool The number of sessions in the pool.
# TYPE cloud_google_com_java_spanner_num_sessions_in_pool gauge
cloud_google_com_java_spanner_num_sessions_in_pool
  {client_id="client-1",database="database-1",instance_id="instance-1",library_version="6.23.1",
  Type="num_sessions_being_prepared",} 0.0
cloud_google_com_java_spanner_num_sessions_in_pool
  {client_id="client-1",database="database-1",instance_id="instance-1",library_version="6.23.1",
  Type="num_in_use_sessions",} 50.0
cloud_google_com_java_spanner_num_sessions_in_pool
  {client_id="client-1",database="database-1",instance_id="instance-1",library_version="6.23.1",
  Type="num_read_sessions",} 0.0
cloud_google_com_java_spanner_num_sessions_in_pool
  {client_id="client-1",database="database-1",instance_id="instance-1",library_version="6.23.1",
  Type="num_write_prepared_sessions",} 0.0

その結果以下が読み取れました。

アプリ起動時から合計で50セッションが要求された（セッションプールから取り出された）。
アプリ起動時から合計で0セッションが解放された（セッションプールに戻された）。
メトリクス取得時点で50セッションが使用中である。

ここで50という値はアプリに設定している最大セッション数です。

つまり、アプリは以下の状態を遷移し、セッション枯渇を引き起こしていたことが判明しました。

クエリ実行で使用したセッションが使用中のまま解放されない。
解放されないため、セッションを（最大セッション数まで）追加生成して処理を継続。
追加したセッションも使い切り、後続処理はセッション解放を待ち続ける。

調査3

一度クエリ実行で使用したセッションが解放されないことを根本原因と特定できたため、アプリの実装を調査しました。
その結果Spannerクライアントを用いた実装においてセッションの解放されないパターンが存在しました。
問題のあったソースコードの例を下記に記載します。

import com.google.cloud.spring.data.spanner.core.SpannerQueryOptions;
import com.google.cloud.spring.data.spanner.core.SpannerTemplate;
import com.google.cloud.spanner.ResultSet;

@Autowired
SpannerTemplate spannerTemplate;

ResultSet resultSet = spannerTemplate.executeQuery(
    Statement.of("select * from table where id = 1"), new SpannerQueryOptions());

resultSet.next();

int count = (int)resultSet.getLong(0);

動作としてはexecuteQuery()を使ってクエリを実行し、ResultSetで結果を受け取り、next()を繰り返してレコードを1行ずつ読み出すイメージです。
この時セッションが使用される訳ですが、セッションが解放される条件は以下になります。

resultSet.next()でfalseが返却される（＝次の行を読み出せなかった）場合
resultSet.close()が呼ばれた場合

問題のあったソースコードではSELECT句の実行結果をnext()で読み出していますが、クエリの実行結果が1件以上存在する場合、1回のnext()でfalseが返却されることはないためセッションが解放されません。
逆にクエリの実行結果が1件も存在しなかった場合、1回のnext()でfalseが返却されるため、セッション解放が行われます。
また、書き込みを実行するクエリにおいては使用するメソッドが異なり、そちらではセッション解放が裏で行われるようです。

対策

本アプリの実装ではクエリ実行結果は1件しか返却されないことが明確であったため、resultSetをtry-with-resourceで括ることにより、スコープを抜けると同時にclose処理が呼び出されるようにしました。
もちろん明示的にclose()を呼び出しても同じです。
結果が複数件返却される場合にはnext()がfalseを返却するまでforループを回すことで対処可能です。

try (ResultSet resultSet = spannerTemplate.executeQuery(
    Statement.of("select * from table where id = 1"),
    new SpannerQueryOptions());) {

    resultSet.next();

    int count = (int)resultSet.getLong(0);
}

学び

セッション枯渇を知った

セッション枯渇という事象を初めて知りました。セッション管理のような目に見えない処理はライブラリの内部で上手くハンドリングしてくれるものだと思っていたのですが、今回のようにアプリ側の実装次第で容易に起こりうるものだと実感し、少し恐怖を覚えました。今回発生した問題を通してセッション枯渇という観点を知ったことと、具体的なSpannerアクセス実装の注意点を分析できたことは、今後同じ問題を起こさないための良い経験となりました。

問題解決のアプローチが良かった

今回は事象の把握から原因の特定までの流れが良かったと思います。闇雲にソースコードを追うのではなく、まずはどのような問題が起きているのかを把握した上で、原因に当たりをつけてソースコードを読む、というアプローチを今後も意識していきます。
普段使用することのないjstackの理解が深まった点も良かったです。javaアプリをデバッグする際は積極的に活用したいと思います。

テストデータは実環境に合わせて作成する

アプリのテスト時にセッション枯渇を検知できなかった点が反省すべき点です。テスト時にもセッションが解放されない問題は発生していたものの、テストデータの件数が少なくバッチ処理（クライアントのプロセス）が正常終了していたため、枯渇する前にセッションが全て破棄され、問題が顕在化していませんでした。
実環境のデータのボリューム、特徴に可能な限り近いテストデータを作成してテストすることを徹底していきます。