Cloud Spanner で観測される謎の Lock time を紐解く

概要

Cloud Spanner をお使いのお客様から、高負荷の状況において、ロック競合が起きるはずがないのにロックが起きるのは何故かというお問い合わせをサポートにいただくことがあります。今回はそのような例と、なぜそれが起こるかについて説明したいと思います。

ロックが発生するコードの例

例えば、以下のコードを１つのクライアントから同時実行数 1 で繰り返し実行するとします。直列で１つの read-write トランザクションを実行した後に、次の read-write トランザクションを実行することを繰り返すので、アプリケーションの観点では衝突は発生しません。

SingerId=1の行に対し、

• <Read> の部分では FirstName, LastName の読み込みを行う。
• その後の mutation では、LastName と SingerInfo に対して書き込みを行う。

ということを繰り返します。

txStartTime := time.Now()
txnTag := fmt.Sprintf("txn_at:%s", txStartTime.Format(time.RFC3339Nano))
_, err := client.ReadWriteTransactionWithOptions(ctx, func(ctx context.Context, tx *spanner.ReadWriteTransaction) error {
    // <Read> ここから
    q := tx.Query(ctx, spanner.Statement{SQL: "SELECT FirstName, LastName FROM Singers WHERE SingerId = 1"})
    defer q.Stop()
    if _, err := q.Next(); err != nil {
        log.Errorf("Error q.Next(): %v", err)
        return err
    }
    // </Read> ここまで
    var ms []*spanner.Mutation
    ms = append(ms, spanner.Update(
        "Singers",
        []string{"SingerId", "LastName", "SingerInfo"},
        []interface{}{1, uuid.New().String(), uuid.New().String()}),
    )
    if err := tx.BufferWrite(ms); err != nil {
        log.Errorf("Error tx.BufferWrite(): %v", err)
        return err
    }
    return nil
}, spanner.TransactionOptions{TransactionTag: txnTag})

このコードをベースに、

• A. <Read>部分を実行せず mutation のみを実行する時間帯
• B. <Read> と mutation の両方を実行する時間帯

に分けて、実行を繰り返してみます。（[A. を１時間, B. を１時間] × ３セット）

観測された Lock wait time

結果として、<Read> 部分が実行されず、mutation のみがread-write トランザクションで行われていた時間帯は Lock wait time が発生しない一方で、<Read> も read-write トランザクション内で実行された時間帯は、非常に小さい値ながら、Lock wait time が発生することがあります。

Lock stats を確認すると以下のような結果が得られ、ロック待ちが発生していました。
あたかも、先行するトランザクション（タグ：txn_at:2024-07-31T20:56:57.828298166Z）と、その後にやってきたトランザクション（タグ：txn_at:2024-07-31T20:56:57.837331198Z]）が衝突しているように見えます。

SAMPLE_LOCK_REQUESTS

• [Singers.LastName,Exclusive,txn_at:2024-07-31T20:56:57.828298166Z]
• [Singers.LastName,ReaderShared,txn_at:2024-07-31T20:56:57.837331198Z]

SELECT
  INTERVAL_END,
  CAST(ROW_RANGE_START_KEY AS STRING) ROW_RANGE_START_KEY,
  LOCK_WAIT_SECONDS,
  SAMPLE_LOCK_REQUESTS
FROM
  `SPANNER_SYS`.`LOCK_STATS_TOP_10MINUTE`
ORDER BY INTERVAL_END DESC
LIMIT 1;

INTERVAL_END	ROW_RANGE_START_KEY	LOCK_WAIT_SECONDS	SAMPLE_LOCK_REQUESTS
2024-07-31T21:00:00Z	singers(1)	0.000055	[[Singers.LastName,Exclusive,txn_at:2024-07-31T20:56:57.828298166Z], [Singers.LastName,ReaderShared,txn_at:2024-07-31T20:56:57.837331198Z]]

Lock wait time が発生する理由

どうしてこのようなことが起こるのでしょうか？

• トランザクションが成功した後も、トランザクションによる変更が実際のテーブルに反映されるまで Cloud Spanner は、ロックを保持し続けます。このことで、他のトランザクションによってデータが変更されないことを保証しています。
• Cloud Spanner は、Paxos アルゴリズムを採用しており、複数のレプリカ間でコミットの合意が取れ、耐久性（commit されたデータは commit された状態を保つ）が担保されるとすぐに、トランザクションが成功した旨をクライアントに返却します。これは、ユーザ視点でのトランザクションの遅延を低くするための仕組みであり、実際のデータの変更はトランザクションが成功したことをクライアントに返すと同時に行われます。
• そのため、次のトランザクションがやってきたときには、まだ変更が反映されておらず、ロックが開放されていないことが稀に起こり、結果として非常に短い時間ながらも Lock wait time が現れることがあります。
• つまり、単一のスプリットの書き込みにおける「8.リーダーがクライアントに応答し、トランザクションが commit されたことを通知します。」の後の「9.クライアントへの応答と同時に、トランザクションのミューテーションがデータに適用されます。」のフェーズで次のトランザクションが同じミューテーション領域に読み書きを行う場合に、ロックモードの競合に応じた待ちが発生する可能性があります。

では、なぜ読み込み処理があったときのみ、ロックの開放待ちが発生していたのでしょうか？

• <Read> の部分を実行した場合、該当行の LastName 列に対して、ReaderShared ロックがかかります。その後、トランザクションがコミット処理にて実際にその列を変更するタイミングで、Exclusive ロックにアップグレードされます。この場合は、上記で説明した理由から、後続のトランザクションが同一行の LastName に 、ReaderShared ロックをかける際に、先行するトランザクションの Exclusive ロックと競合することがあります。
• 一方で <Read> の部分を実行しなかった場合、mutation の処理は blind-write になるため、WriterShared ロックがかかります。WriterShared ロック同士は競合を起こさないため、ロック解放待ちは発生しません。
• 参考：ロックモードの競合

以上がアプリケーションのトランザクション同士が競合するはずがないのに Lock wait time が観測される例となります。

アプリケーション由来でない Lock wait time の例

これまでとは別の話として、 Lock insights 上でTotal lock wait time のみが現れるものの、ロックの統計情報（SPANNER_SYS.LOCK_STATS*）のテーブルを見ても何も得られないことがあります。

これは、この記事書いている時点（2024年8月）の仕様として、Total lock wait time には Cloud Spanner のシステム内部のロック情報も反映される一方で、ロックの統計情報（SPANNER_SYS.LOCK_STATS*）のテーブルには、ユーザートランザクションに関する情報しか反映されないためです。

たとえば、以下の Total lock wait time は、read-only トランザクションを用いて "SELECT * FROM Singers TABLESAMPLE RESERVOIR (1 ROWS)" を同時実行数 50 で繰り返し実行した際のものです。

この TABLESAMPLE RESERVOIR (1 ROWS) を用いたクエリは、対象となるテーブル（または セカンダリインデックス）のスキャン範囲において、フルスキャンを実行します。意図的に CPU 負荷の高い処理を実行し、マニュアルでのウォームアップを行うことで、split 分割を促した際に取得したものです。

Total lock wait time が 0.05s 程度にまで上がっているタイミングで、Cloud Spanner 内部では split 分割と他ノードへの移動が発生しており、それに関連するシステムテーブルで一時的に発生したロックの情報が Total lock wait に現れていました。

まとめ

これらのように、原因究明が難しい Lock wait time を観測することが、特に高負荷の環境においてはあるかもしれません。ただ、その値がトランザクションの実行時間に比べ、遥かに小さく、高い負荷をかけても大きく伸びていない場合には気にしていただく必要はなく、Cloud Spanner の仕組みの中で自然に発生してしまう類のロックだとご理解ください。

一方で、そのロックが遅延の中で占める割合が無視できないように見える場合には、実際にアプリケーションがロック競合を起こすロジックを調査する必要があります。また、Lock time は大きくないけれども、トランザクションの遅延が大きいといった問題がある場合は、ホットスポット（同じサーバーに多くのリクエストが送信され、サーバーのリソースが飽和し、遅延が大きくなる可能性がある状況）などの問題が起こっている可能性があるかもしれません。気になるパフォーマンスの問題がありましたら、Google Cloud サポートまでお問い合わせください。