トランザクションの統計情報

Spanner にはトランザクションに関する統計情報を保存する組み込みテーブルが用意されています。SQL ステートメントを使用すると、これらの SPANNER_SYS.TXN_STATS* テーブルから 統計情報を取得できます。

トランザクションの統計情報を使用するタイミング

トランザクションの統計情報は、パフォーマンスの問題を調査する際に便利です。たとえば、データベース内に、パフォーマンスや 秒間クエリ数（QPS: Queries Per Second）に影響を与える可能性のある、実行速度の遅いトランザクションがあるかどうかを確認できます。もう 1 つのシナリオは、クライアント アプリケーションでトランザクション実行レイテンシが高くなっている場合です。トランザクションの統計情報を分析すると、レイテンシに影響する可能性がある潜在的なボトルネック（特定の列に対する大量の更新など）を検出できます。

対象

SPANNER_SYS データは SQL インターフェースを介してのみ使用できます。例えば:

  • Google Cloud コンソールのデータベースの Spanner Studio ページ

  • gcloud spanner databases execute-sql コマンド

  • トランザクションの分析情報ダッシュボード

  • executeQueryAPI

Spanner が提供する他の単一読み取りメソッドは、SPANNER_SYS をサポートしていません。

トランザクション別にグループ化されたレイテンシ統計

次のテーブルでは、特定の期間中に TOP リソースを消費するトランザクションの統計情報が追跡されます。

  • SPANNER_SYS.TXN_STATS_TOP_MINUTE: 1 分間隔で集計されたトランザクション統計。

  • SPANNER_SYS.TXN_STATS_TOP_10MINUTE: 10 分間隔で集計されたトランザクション統計。

  • SPANNER_SYS.TXN_STATS_TOP_HOUR: 1 時間間隔で集計されたトランザクション統計。

これらのテーブルには以下のプロパティがあります。

  • 各テーブルには、テーブル名で指定された長さの、時間間隔が重複しないデータが含まれています。

  • 時間間隔はクロックの時刻に基づきます。1 分の間隔は現在の分が終わるときに終了し、10 分の間隔は正時に始まって 10 分ごとに終了し、1 時間の間隔は正時になるたびに終了します。

    たとえば、午前 11 時 59 分 30 秒に SQL クエリで使用可能な最新の時間間隔は次のとおりです。

    • 1 分: 午前 11:58:00～11:58:59
    • 10 分: 午前 11:40:00～11:49:59
    • 1 時間: 午前 10:00:00～10:59:59

  • Spanner は、トランザクションの FPRINT（フィンガープリント）別に統計情報をグループ化します。トランザクション タグが存在する場合は、FPRINT がタグのハッシュです。存在しない場合は、トランザクションに関連するオペレーションに基づいて計算されたハッシュになります。

  • 統計情報は FPRINT に基づいてグループ化されるため、同じトランザクションが任意の時間間隔で複数回実行されても、これらのテーブルには 1 つのエントリしか表示されません。

  • 各行には、指定された期間中に Spanner が統計をキャプチャした特定のトランザクションのすべての実行に関する統計が含まれています。

  • 期間中にテーブルで実行されたすべてのトランザクションの統計情報を Spanner が保存できない場合、特定の期間中のレイテンシ、commit の試行回数、バイト数が最も高いトランザクションが優先されます。

  • テーブル内のすべての列は null 値を許容できます。

テーブル スキーマ

列名 型 説明
INTERVAL_END TIMESTAMP 発生したトランザクションの実行を含む時間間隔の終了。
TRANSACTION_TAG STRING このトランザクション オペレーションの省略可能なトランザクション タグ。タグの使用に関する詳細は、トランザクション タグによるトラブルシューティングをご覧ください。同じタグ文字列を持つ複数のトランザクションの統計情報は、「TRANSACTION_TAG」に一致するタグ文字列がある 1 行にグループ化されます。
FPRINT INT64 TRANSACTION_TAG のハッシュ（存在する場合）。それ以外の場合、ハッシュはトランザクションに関連するオペレーションに基づいて計算されます。INTERVAL_END と FPRINT は、これらのテーブルの一意のキーとして機能します。
READ_COLUMNS ARRAY<STRING> トランザクションが読み取った列のセット。
WRITE_CONSTRUCTIVE_COLUMNS ARRAY<STRING> トランザクションによって建設的に書き込まれた（つまり、新しい値に割り当てられた）列のセット。

変更ストリームでは、変更ストリームで監視される列とテーブルへの書き込みにトランザクションが関係する場合、WRITE_CONSTRUCTIVE_COLUMNS には、変更ストリーム名を先頭に付けた .data と._exists 1 が含まれます。
WRITE_DELETE_TABLES ARRAY<STRING> トランザクションによって行が削除または置換されたテーブルのセット。
ATTEMPT_COUNT INT64 トランザクションが試行された合計回数（「commit」を呼び出す前に中止された試行を含む）。
COMMIT_ATTEMPT_COUNT INT64 トランザクションの commit 試行の合計回数。トランザクションの commit メソッドへの呼び出し数と一致する必要があります。
COMMIT_ABORT_COUNT INT64 中止されたトランザクション試行の合計回数（トランザクションの commit メソッドを呼び出す前に中止されたものを含む）。
COMMIT_RETRY_COUNT INT64 前に試行され、中止された再試行の合計回数です。ロック競合や一時的なイベントが原因で、Spanner トランザクションが commit の前に複数回試行されることがあります。再試行回数に対して再試行回数が多い場合は、調査が必要な問題がある可能性があります。詳細については、このページのトランザクションと commit 数についてをご覧ください。
COMMIT_FAILED_PRECONDITION_COUNT INT64 失敗した前提条件エラー（UNIQUE インデックス違反、行がすでに存在する、行が見つからないなど）が返ったトランザクション commit の試行の合計回数。
AVG_PARTICIPANTS FLOAT64 各 commit 試行の平均参加者数。参加者の詳細については、Spanner の読み取りと書き込みのライフサイクルをご覧ください。
AVG_TOTAL_LATENCY_SECONDS FLOAT64 トランザクションの最初のオペレーションから commit または中断までにかかった平均秒数。
AVG_COMMIT_LATENCY_SECONDS FLOAT64 commit オペレーションの実行にかかった平均秒数。
AVG_BYTES FLOAT64 トランザクションが書き込んだ平均バイト数。
TOTAL_LATENCY_DISTRIBUTION ARRAY<STRUCT>

commit レイテンシの合計のヒストグラムとは、最初のトランザクション オペレーションの開始時間からトランザクションのすべての試行の commit の時間または中断までの時間です。

トランザクションが複数回中止され、正常に commit した場合、最終的に commit が成功するまで、各試行ごとにレイテンシが測定されます。値は秒単位で測定されます。

この配列には単一の要素が含まれ、次のタイプがあります。
ARRAY<STRUCT<
  COUNT INT64,
  MEAN FLOAT64,
  SUM_OF_SQUARED_DEVIATION FLOAT64,
  NUM_FINITE_BUCKETS INT64,
  GROWTH_FACTOR FLOAT64,
  SCALE FLOAT64,
  BUCKET_COUNTS ARRAY<INT64>>>
値の詳細については、分散をご覧ください。

分散から目的のパーセンタイル レイテンシを計算するには、SPANNER_SYS.DISTRIBUTION_PERCENTILE(distribution, n FLOAT64) 関数を使用します。この関数は推定 n 番目のパーセンタイルを返します。関連する例については、トランザクションの 99 パーセンタイル レイテンシを確認するをご覧ください。

詳細については、パーセンタイルと分散値の指標をご覧ください。
OPERATIONS_BY_TABLE ARRAY<STRUCT>

テーブルごとのトランザクションによる INSERT または UPDATE オペレーションの影響。これは、行が影響を受ける回数と、書き込まれるバイト数によって示されます。

この列は、テーブルの負荷を可視化し、トランザクションがテーブルに書き込むレートに関する分析情報を提供します。

次のように配列を指定します。
ARRAY<STRUCT<
  TABLE STRING(MAX),
  INSERT_OR_UPDATE_COUNT INT64,
  INSERT_OR_UPDATE_BYTES INT64>>

1 _exists は、特定の行が存在するかどうかを確認するために使用する内部フィールドです。

クエリの例

このセクションには、トランザクションの統計を取得する SQL ステートメントの例がいくつか含まれています。これらの SQL ステートメントは、クライアント ライブラリ、gcloud spanner、または Google Cloud Console を使用して実行できます。

特定の期間における各トランザクションの基本的な統計を一覧表示する

次のクエリは、直前の 1 分間における上位トランザクションの元データを返します。

SELECT fprint,
       read_columns,
       write_constructive_columns,
       write_delete_tables,
       avg_total_latency_seconds,
       avg_commit_latency_seconds,
       operations_by_table,
       avg_bytes
FROM spanner_sys.txn_stats_top_minute
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.txn_stats_top_minute);
クエリ出力
fprint read_columns write_constructive_columns write_delete_tables avg_total_latency_seconds avg_commit_latency_seconds operations_by_table avg_bytes
40015598317 [] ["Routes.name", "Cars.model"] ["Users"] 0.006578737 0.006547737 [["Cars",1107,30996],["Routes",560,26880]] 25286
20524969030 ["id", "no"] [] [] 0.001732442 0.000247442 [] 0
77848338483 [] [] ["Cars", "Routes"] 0.033467418 0.000251418 [] 0

commit レイテンシの平均が最も高いトランザクションを一覧表示する

次のクエリは、過去 1 時間における commit の平均レイテンシが高いトランザクションを、commit の平均レイテンシが高い順に返します。

SELECT fprint,
       read_columns,
       write_constructive_columns,
       write_delete_tables,
       avg_total_latency_seconds,
       avg_commit_latency_seconds,
       avg_bytes
FROM spanner_sys.txn_stats_top_hour
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.txn_stats_top_hour)
ORDER BY avg_commit_latency_seconds DESC;
クエリ出力
fprint read_columns write_constructive_columns write_delete_tables avg_total_latency_seconds avg_commit_latency_seconds avg_bytes
40015598317 [] ["Routes.name", "Cars.model"] ["Users"] 0.006578737 0.006547737 25286
77848338483 [] [] ["Cars", "Routes"] 0.033467418 0.000251418 0
20524969030 ["id", "no"] [] [] 0.001732442 0.000247442 0

特定の列を読み取るトランザクションの平均レイテンシを調べる

次のクエリは、1 時間の統計情報から列 ADDRESS を読み取るトランザクションの平均レイテンシ情報を返します。

SELECT fprint,
       read_columns,
       write_constructive_columns,
       write_delete_tables,
       avg_total_latency_seconds
FROM spanner_sys.txn_stats_top_hour
WHERE 'ADDRESS' IN UNNEST(read_columns)
ORDER BY avg_total_latency_seconds DESC;
クエリ出力
fprint read_columns write_constructive_columns write_delete_tables avg_total_latency_seconds
77848338483 ["ID", "ADDRESS"] [] ["Cars", "Routes"] 0.033467418
40015598317 ["ID", "NAME", "ADDRESS"] [] ["Users"] 0.006578737

変更された平均バイト数によってトランザクションを一覧表示する

次のクエリは、過去 1 時間にサンプリングされたトランザクションを、トランザクションによって変更された平均バイト数で返します。

SELECT fprint,
       read_columns,
       write_constructive_columns,
       write_delete_tables,
       avg_bytes
FROM spanner_sys.txn_stats_top_hour
ORDER BY avg_bytes DESC;
クエリ出力
fprint read_columns write_constructive_columns write_delete_tables avg_bytes
40015598317 [] [] ["Users"] 25286
77848338483 [] [] ["Cars", "Routes"] 12005
20524969030 ["ID", "ADDRESS"] [] ["Users"] 10923

統計情報の集計

SPANNER_SYS には、Spanner が特定の期間に統計をキャプチャした、すべてのトランザクションの集計データを保存するテーブルもあります。

  • SPANNER_SYS.TXN_STATS_TOTAL_MINUTE: 1 分間隔でのすべてのトランザクションの統計情報の集計
  • SPANNER_SYS.TXN_STATS_TOTAL_10MINUTE: 10 分間隔でのすべてのトランザクションの統計情報の集計
  • SPANNER_SYS.TXN_STATS_TOTAL_HOUR: 1 時間間隔でのすべてのトランザクションの統計情報の集計

統計情報の集計テーブルには次のプロパティがあります。

  • 各テーブルには、テーブル名で指定された長さの、時間間隔が重複しないデータが含まれています。

  • 時間間隔は時刻に基づきます。1 分の間隔は現在の分が終わるときに終了し、10 分の間隔は正時に始まって 10 分ごとに終了し、1 時間の間隔は正時になるたびに終了します。

    たとえば、午前 11 時 59 分 30 秒の時点で、トランザクション統計の集計の SQL クエリに使用できる最新の間隔は次のとおりです。

    • 1 分: 午前 11:58:00～11:58:59
    • 10 分: 午前 11:40:00～11:49:59
    • 1 時間: 午前 10:00:00～10:59:59

  • 各行には、指定した期間中にデータベースに対して実行されたすべてのトランザクションの統計がまとめて含まれています。時間間隔ごとに 1 行のみとなります。

  • SPANNER_SYS.TXN_STATS_TOTAL_* テーブルにキャプチャされた統計には、Spanner が SPANNER_SYS.TXN_STATS_TOP_* テーブルでキャプチャしなかったトランザクションが含まれる場合があります。

  • これらの表の一部の列は、Cloud Monitoring で指標として公開されます。公開される指標は次のとおりです。

    • commit の試行回数
    • commit の再試行回数
    • トランザクションの参加者
    • トランザクション レイテンシ
    • 書き込みバイト数

    詳細については、Spanner の指標をご覧ください。

テーブル スキーマ

列名 型 説明
INTERVAL_END TIMESTAMP 統計情報が収集された時間間隔の終了。
ATTEMPT_COUNT INT64 トランザクションの試行の合計回数（「commit」を呼び出す前に中止された試行を含む）。
COMMIT_ATTEMPT_COUNT INT64 トランザクションの commit 試行の合計回数。トランザクションの commit メソッドへの呼び出し数と一致する必要があります。
COMMIT_ABORT_COUNT INT64 中止されたトランザクション試行の合計回数（トランザクションの commit メソッドを呼び出す前に中止されたものを含む）。
COMMIT_RETRY_COUNT INT64 前に試行された、中止された再試行の試行回数。ロック競合や一時的なイベントが原因で、Spanner トランザクションが commit の前に複数回試行されることがあります。再試行回数に対して再試行回数が多い場合は、調査が必要な問題がある可能性があります。詳細については、このページのトランザクションと commit 数についてをご覧ください。
COMMIT_FAILED_PRECONDITION_COUNT INT64 失敗した前提条件エラー（UNIQUE インデックス違反、行がすでに存在する、行が見つからないなど）が返ったトランザクション commit の試行の合計回数。
AVG_PARTICIPANTS FLOAT64 各 commit 試行の平均参加者数。参加者の詳細については、Spanner の読み取りと書き込みのライフサイクルをご覧ください。
AVG_TOTAL_LATENCY_SECONDS FLOAT64 トランザクションの最初のオペレーションから commit または中断までにかかった平均秒数。
AVG_COMMIT_LATENCY_SECONDS FLOAT64 commit オペレーションの実行にかかった平均秒数。
AVG_BYTES FLOAT64 トランザクションが書き込んだ平均バイト数。
TOTAL_LATENCY_DISTRIBUTION ARRAY<STRUCT>

commit レイテンシの合計のヒストグラムとは、最初のトランザクション オペレーションの開始時間からすべてのトランザクション試行の commit 時間または中断までの時間です。

トランザクションが複数回中止され、正常に commit した場合、最終的に commit が成功するまで、各試行ごとにレイテンシが測定されます。値は秒単位で測定されます。

この配列には単一の要素が含まれ、次のタイプがあります。
ARRAY<STRUCT<
  COUNT INT64,
  MEAN FLOAT64,
  SUM_OF_SQUARED_DEVIATION FLOAT64,
  NUM_FINITE_BUCKETS INT64,
  GROWTH_FACTOR FLOAT64,
  SCALE FLOAT64,
  BUCKET_COUNTS ARRAY<INT64>>>
値の詳細については、分散をご覧ください。

分散から目的のパーセンタイル レイテンシを計算するには、SPANNER_SYS.DISTRIBUTION_PERCENTILE(distribution, n FLOAT64) 関数を使用します。この関数は推定 n 番目のパーセンタイルを返します。例については、トランザクションの 99 パーセンタイル レイテンシを確認するをご覧ください。

詳細については、パーセンタイルと分散値の指標をご覧ください。
OPERATIONS_BY_TABLE ARRAY<STRUCT>

テーブルごとのすべてのトランザクションによる INSERT または UPDATE オペレーションの影響。これは、行が影響を受ける回数と、書き込まれるバイト数によって示されます。

この列は、テーブルの負荷を可視化し、トランザクションがテーブルに書き込むレートに関する分析情報を提供します。

次のように配列を指定します。
ARRAY<STRUCT<
  TABLE STRING(MAX),
  INSERT_OR_UPDATE_COUNT INT64,
  INSERT_OR_UPDATE_BYTES INT64>>

クエリの例

このセクションには、トランザクションの統計を取得する SQL ステートメントの例がいくつか含まれています。これらの SQL ステートメントは、クライアント ライブラリ、gcloud spanner、または Google Cloud Console を使用して実行できます。

すべてのトランザクションに対する commit 試行の合計回数を確認する

次のクエリは、最新の完全な 1 分間のすべてのトランザクションに対する commit の合計回数を返します。

SELECT interval_end,
       commit_attempt_count
FROM spanner_sys.txn_stats_total_minute
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.txn_stats_total_minute)
ORDER BY interval_end;
クエリ出力
interval_end commit_attempt_count
2020-01-17 11:46:00-08:00 21

集計された統計情報には、任意の期間の interval_end ごとに 1 つのエントリしかないため、結果は 1 行のみとなります。

すべてのトランザクションでの commit レイテンシの合計を確認する

次のクエリは、過去 10 分間におけるすべてのトランザクションの commit レイテンシの合計を返します。

SELECT (avg_commit_latency_seconds * commit_attempt_count / 60 / 60)
  AS total_commit_latency_hours
FROM spanner_sys.txn_stats_total_10minute
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.txn_stats_total_10minute);
クエリ出力
total_commit_latency_hours
0.8967

集計された統計情報には、任意の期間の interval_end ごとに 1 つのエントリしかないため、結果は 1 行のみとなります。

トランザクションの 99 パーセンタイル レイテンシを確認する

次のクエリは、過去 10 分間に実行されたトランザクションの 99 パーセンタイルのレイテンシを返します。

SELECT interval_end, avg_total_latency_seconds,
       SPANNER_SYS.DISTRIBUTION_PERCENTILE(total_latency_distribution[OFFSET(0)], 99.0)
  AS percentile_latency
FROM spanner_sys.txn_stats_total_10minute
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.txn_stats_total_10minute)
ORDER BY interval_end;
クエリ出力
interval_end avg_total_latency_seconds percentile_latency
2022-08-17 11:46:00-08:00 0.34576998305986395 9.00296190476190476

平均レイテンシと 99 パーセンタイルのレイテンシに大きな差があることに注意してください。99 パーセンタイルのレイテンシは、レイテンシが高い外れ値のトランザクションを特定するのに役立ちます。

集計された統計情報には、任意の期間の interval_end ごとに 1 つのエントリしかないため、結果は 1 行のみとなります。

データの保持

Spanner は、少なくとも次の期間中に各テーブルのデータを保持します。

  • SPANNER_SYS.TXN_STATS_TOP_MINUTE および SPANNER_SYS.TXN_STATS_TOTAL_MINUTE: 過去 6 時間を対象とする間隔。

  • SPANNER_SYS.TXN_STATS_TOP_10MINUTE および SPANNER_SYS.TXN_STATS_TOTAL_10MINUTE: 過去 4 日間を対象とするインターフェース。

  • SPANNER_SYS.TXN_STATS_TOP_HOUR および SPANNER_SYS.TXN_STATS_TOTAL_HOUR: 過去 30 日間を対象とする間隔。

Spanner のトランザクションの統計情報には、アプリケーションによるデータベースの使用状況についての分析情報があり、パフォーマンスの問題を調査する際に役立ちます。たとえば、競合を引き起こしている可能性がある実行速度の遅いトランザクションの有無を確認したり、特定の列に対する大量の更新など、高負荷の潜在的な原因を特定したりできます。トランザクションの統計情報を使用してデータベース内の競合を調査する方法について、以下の手順で説明します。

トランザクション数と commit 数を把握する

このようなコンテキストの例として、Spanner のトランザクションは commit するまで何回か再試行しなくてはならない場合があります。これは、2 つのトランザクションが同じデータを同時に処理しようとするときに最も発生しやすく、トランザクションのうちの1つは分離プロパティを保持するために中止する必要があります。トランザクションの中止を引き起こす可能性のあるその他の一時的イベントは次のとおりです。

  • ネットワークに関する一時的な問題

  • トランザクションの commit 処理中に適用されるデータベース スキーマの変更。

  • Spanner インスタンスに、受信したすべてのリクエストを処理するための容量がない。

このようなシナリオでは、クライアントは、正常に commit されるかタイムアウトするまで、中止されたトランザクションを再試行する必要があります。Spanner の公式クライアント ライブラリを使用している場合、各ライブラリには自動再試行メカニズムが実装されています。カスタム バージョンのクライアント コードを使用している場合、トランザクション コミットを再試行ループにラップします。

また、Spanner のトランザクションは、トランザクションのタイムアウト、権限の問題、または無効なテーブル/列名などの再試行できないエラーのために中止される場合があります。このようなトランザクションを再試行する必要はありません。Spanner クライアント ライブラリはすぐにエラーを返します。

次の表に、異なるシナリオでCOMMIT_ATTEMPT_COUNT、COMMIT_ABORT_COUNT、COMMIT_RETRY_COUNT がログに記録される例を記載します。

シナリオ COMMIT_ATTEMPT_COUNT COMMIT_ABORT_COUNT COMMIT_RETRY_COUNT
最初の試行でコミットに成功しました。 1 0 0
タイムアウト エラーによりトランザクションが中止されました。 1 1 0
一時的なネットワークの問題によりトランザクションが中止され、1 回の再試行後に正常に commit されました。 2 1 1
同じ FPRINT を持つ 5 つのトランザクションが 10 分以内に実行されました。最初の 3 回の commit はトランザクションの commit が正常に行われましたが、2 回目のトランザクションは中止され、最初の再試行で正常に commit されました。 7 2 2

transactions-stats テーブルのデータは、一定期間の集計データです。特定の間隔で、トランザクションの中止と再試行が境界を越えて別のバケットに入る場合もあります。その結果、特定の時間が経過すると中止や再試行が等しくならないことがあります。

これらの統計情報は、トラブルシューティングとイントロスペクションを目的としており、100% 正確であるとは限りません。統計情報は、Spanner テーブルに保存される前にメモリ内で集計されます。アップグレードやその他のメンテナンス アクティビティ中に Spanner サーバーが再起動するため、数値の精度に影響します。

トランザクションの統計情報を使用したデータベース競合のトラブルシューティング

SQL コードか、Transaction Insights ダッシュボードを使用して、ロック競合のために高いレイテンシを引き起こす可能性のあるデータベース内のトランザクションを表示できます。

以下のトピックでは、SQL コードを使用してそのようなトランザクションを調査する方法を説明します。

調査する期間を選択する

競合の問題は、Spanner を使用しているアプリケーションで発見されることがあります。

この演習では、この問題が 2020 年 5 月 17 日の午後 5 時 20 分頃に始まったとします。

トランザクション タグを使用してトランザクションの発生元を特定し、トランザクション統計テーブルとロック統計情報テーブルを相関させてロック競合を効果的にトラブルシューティングできます。詳細については、トランザクション タグによるトラブルシューティングをご覧ください。

選択した期間のトランザクション統計情報を収集する

調査を開始するには、問題の発生箇所あたりを TXN_STATS_TOTAL_10MINUTE テーブルにクエリします。このクエリの結果は、その期間にレイテンシやその他のトランザクションの統計情報がどのように変化したかを示します。

たとえば、次のクエリは 4:30 pm から 7:40 pm までの集計トランザクション統計を返します。

SELECT
  interval_end,
  ROUND(avg_total_latency_seconds,4) as avg_total_latency_seconds,
  commit_attempt_count,
  commit_abort_count
FROM SPANNER_SYS.TXN_STATS_TOTAL_10MINUTE
WHERE
  interval_end >= "2020-05-17T16:40:00"
  AND interval_end <= "2020-05-17T19:40:00"
ORDER BY interval_end;

次の表は、クエリから返されたデータの例を示したものです。

interval_end avg_total_latency_seconds commit_attempt_count commit_abort_count
2020-05-17 16:40:00-07:00 0.0284 315691 5170
2020-05-17 16:50:00-07:00 0.0250 302124 3828
2020-05-17 17:00:00-07:00 0.0460 346087 11382
2020-05-17 17:10:00-07:00 0.0864 379964 33826
2020-05-17 17:20:00-07:00 0.1291 390343 52549
2020-05-17 17:30:00-07:00 0.1314 456455 76392
2020-05-17 17:40:00-07:00 0.1598 507774 121458
2020-05-17 17:50:00-07:00 0.1641 516587 115875
2020-05-17 18:00:00-07:00 0.1578 552711 122626
2020-05-17 18:10:00-07:00 0.1750 569460 154205
2020-05-17 18:20:00-07:00 0.1727 613571 160772
2020-05-17 18:30:00-07:00 0.1588 601994 143044
2020-05-17 18:40:00-07:00 0.2025 604211 170019
2020-05-17 18:50:00-07:00 0.1615 601622 135601
2020-05-17 19:00:00-07:00 0.1653 596804 129511
2020-05-17 19:10:00-07:00 0.1414 560023 112247
2020-05-17 19:20:00-07:00 0.1367 570864 100596
2020-05-17 19:30:00-07:00 0.0894 539729 65316
2020-05-17 19:40:00-07:00 0.0820 479151 40398

集計されたレイテンシと中断の数が、ハイライト表示された期間で、他の期間と比べて高くなっていることがわかります。集計されたレイテンシや中断の数が多い 10 分の間隔をどれでも選択できます。次の手順では、末尾が 2020-05-17T18:40:00 の間隔を選択し、高レイテンシや中断の数が多い原因となっているトランザクションを特定するのに使用します。

レイテンシが高いトランザクションを特定する

前の手順で選択した間隔について TXN_STATS_TOP_10MINUTE テーブルに対してクエリを実行します。このデータを使用すると、レイテンシが高い、または中断数が多い、もしくはその両方のトランザクションを特定できます。

次のクエリを実行して、上記の例で 2020-05-17T18:40:00 で終わる間隔の合計レイテンシの降順で、パフォーマンスに影響を与える上位のトランザクションを取得します。

SELECT
  interval_end,
  fprint,
  ROUND(avg_total_latency_seconds,4) as avg_total_latency_seconds,
  ROUND(avg_commit_latency_seconds,4) as avg_commit_latency_seconds,
  commit_attempt_count,
  commit_abort_count,
  commit_retry_count
FROM SPANNER_SYS.TXN_STATS_TOP_10MINUTE
WHERE
  interval_end = "2020-05-17T18:40:00"
ORDER BY avg_total_latency_seconds DESC;
interval_end fprint avg_total_latency_seconds avg_commit_latency_seconds commit_attempt_count commit_abort_count commit_retry_count
2020-05-17 18:40:00-07:00 15185072816865185658 0.3508 0.0139 278802 142205 129884
2020-05-17 18:40:00-07:00 15435530087434255496 0.1633 0.0142 129012 27177 24559
2020-05-17 18:40:00-07:00 14175643543447671202 0.1423 0.0133 5357 636 433
2020-05-17 18:40:00-07:00 898069986622520747 0.0198 0.0158 6 0 0
2020-05-17 18:40:00-07:00 10510121182038036893 0.0168 0.0125 7 0 0
2020-05-17 18:40:00-07:00 9287748709638024175 0.0159 0.0118 4269 1 0
2020-05-17 18:40:00-07:00 7129109266372596045 0.0142 0.0102 182227 0 0
2020-05-17 18:40:00-07:00 15630228555662391800 0.0120 0.0107 58 0 0
2020-05-17 18:40:00-07:00 7907238229716746451 0.0108 0.0097 65 0 0
2020-05-17 18:40:00-07:00 10158167220149989178 0.0095 0.0047 3454 0 0
2020-05-17 18:40:00-07:00 9353100217060788102 0.0093 0.0045 725 0 0
2020-05-17 18:40:00-07:00 9521689070912159706 0.0093 0.0045 164 0 0
2020-05-17 18:40:00-07:00 11079878968512225881 0.0064 0.0019 65 0 0

上記の表の最初の行（ハイライト表示された行）は、commit の中断数が多いためにレイテンシが高いトランザクションであることがはっきりと確認できます。また、多数の commit の再試行も示されています。これは、中止された commit が再試行されたことを示します。次のステップでは、この問題の原因を詳しく調査します。

レイテンシが高いトランザクションに関係する列を特定する

この手順では、中断数が多いトランザクションで read_columns、write_constructive_columns、write_delete_tables のデータを取得し、高レイテンシのトランザクションが同じ列のセットで動作しているかどうかを確認します。FPRINT の値は、次の手順でも役立ちます。

SELECT
  fprint,
  read_columns,
  write_constructive_columns,
  write_delete_tables
FROM SPANNER_SYS.TXN_STATS_TOP_10MINUTE
WHERE
  interval_end = "2020-05-17T18:40:00"
ORDER BY avg_total_latency_seconds DESC LIMIT 3;
fprint read_columns write_constructive_columns write_delete_tables
15185072816865185658 [TestHigherLatency._exists,TestHigherLatency.lang_status,TestHigherLatency.score,globalTagAffinity.shares] [TestHigherLatency._exists,TestHigherLatency.shares,TestHigherLatency_lang_status_score_index.shares] []
15435530087434255496 [TestHigherLatency._exists,TestHigherLatency.lang_status,TestHigherLatency.likes,globalTagAffinity.score] [TestHigherLatency._exists,TestHigherLatency.likes,TestHigherLatency_lang_status_score_index.likes] []
14175643543447671202 [TestHigherLatency._exists,TestHigherLatency.lang_status,TestHigherLatency.score,globalTagAffinity.ugcCount] [TestHigherLatency._exists,TestHigherLatency.ugcCount,TestHigherLatency_lang_status_score_index.ugcCount] []

上記の表の出力が示すように、平均合計レイテンシが最も高いトランザクションが、同じ列を読み取っています。また、このトランザクションが同じ列（TestHigherLatency._exists）に書き込んでいるため、書き込み競合も見られます。

時間の経過に伴うトランザクションのパフォーマンスの変化を見極める

このトランザクションの状態に関連付けられた統計情報が、一定期間にわたってどのように変化したかを確認できます。次のクエリを使用します。$FPRINT は、前のステップで取得した、レンテンシが高いトランザクションのフィンガープリントです。

SELECT
  interval_end,
  ROUND(avg_total_latency_seconds, 3) AS latency,
  ROUND(avg_commit_latency_seconds, 3) AS commit_latency,
  commit_attempt_count,
  commit_abort_count,
  commit_retry_count,
  commit_failed_precondition_count,
  avg_bytes
FROM SPANNER_SYS.TXN_STATS_TOP_10MINUTE
WHERE
  interval_end >= "2020-05-17T16:40:00"
  AND interval_end <= "2020-05-17T19:40:00"
  AND fprint = $FPRINT
ORDER BY interval_end;
interval_end latency commit_latency commit_attempt_count commit_abort_count commit_retry_count commit_failed_precondition_count avg_bytes
2020-05-17 16:40:00-07:00 0.095 0.010 53230 4752 4330 0 91
2020-05-17 16:50:00-07:00 0.069 0.009 61264 3589 3364 0 91
2020-05-17 17:00:00-07:00 0.150 0.010 75868 10557 9322 0 91
2020-05-17 17:10:00-07:00 0.248 0.013 103151 30220 28483 0 91
2020-05-17 17:20:00-07:00 0.310 0.012 130078 45655 41966 0 91
2020-05-17 17:30:00-07:00 0.294 0.012 160064 64930 59933 0 91
2020-05-17 17:40:00-07:00 0.315 0.013 209614 104949 96770 0 91
2020-05-17 17:50:00-07:00 0.322 0.012 215682 100408 95867 0 90
2020-05-17 18:00:00-07:00 0.310 0.012 230932 106728 99462 0 91
2020-05-17 18:10:00-07:00 0.309 0.012 259645 131049 125889 0 91
2020-05-17 18:20:00-07:00 0.315 0.013 272171 137910 129411 0 90
2020-05-17 18:30:00-07:00 0.292 0.013 258944 121475 115844 0 91
2020-05-17 18:40:00-07:00 0.350 0.013 278802 142205 134229 0 91
2020-05-17 18:50:00-07:00 0.302 0.013 256259 115626 109756 0 91
2020-05-17 19:00:00-07:00 0.315 0.014 250560 110662 100322 0 91
2020-05-17 19:10:00-07:00 0.271 0.014 238384 99025 90187 0 91
2020-05-17 19:20:00-07:00 0.273 0.014 219687 84019 79874 0 91
2020-05-17 19:30:00-07:00 0.198 0.013 195357 59370 55909 0 91
2020-05-17 19:40:00-07:00 0.181 0.013 167514 35705 32885 0 91

上記の出力では、ハイライト表示された期間の合計レイテンシが高くなっていることがわかります。また、commit レイテンシ（commit_latency）があまり変化していない場合でも、合計レイテンシが高い場合は commit_attempt_count、commit_abort_count、commit_retry_count も高くなっています。トランザクションの commit がより頻繁に中断されるため、commit の再試行による commit の試行回数も多くなっています。

まとめ

この例では、commit の中断数が多いことが高レイテンシの原因であることがわかりました。次のステップでは、アプリケーションが受信した commit 中断のエラー メッセージを確認して中断の原因を把握します。アプリケーションのログを調べると、この期間にアプリケーションによって、ワークロードが実際に変更されたことがわかります。たとえば、attempts_per_second が高く表示された一部の別のトランザクションの状態と、別のトランザクション（おそらく夜間のクリーンアップ ジョブなど）が追加のロックの競合の原因になっていました。

正しく再試行されなかったトランザクションを識別する

次のクエリは、過去 10 分間にサンプリングされた、commit を中断した数は多いが、再試行がないトランザクションを返します。

SELECT
  *
FROM (
  SELECT
    fprint,
    SUM(commit_attempt_count) AS total_commit_attempt_count,
    SUM(commit_abort_count) AS total_commit_abort_count,
    SUM(commit_retry_count) AS total_commit_retry_count
  FROM
    SPANNER_SYS.TXN_STATS_TOP_10MINUTE
  GROUP BY
    fprint )
WHERE
  total_commit_retry_count = 0
  AND total_commit_abort_count > 0
ORDER BY
  total_commit_abort_count DESC;
fprint total_commit_attempt_count total_commit_abort_count total_commit_retry_count
1557557373282541312 3367894 44232 0
5776062322886969344 13566 14 0

fprint 1557557373282541312 のトランザクションは 44232 回の中止をしましたが、再試行はされていません。中止の回数が多く、すべての中止が再試行不可能なエラーによって引き起こされたという可能性は低いため、これは疑わしように見えます。一方、fprint 5776062322886969344 のトランザクションの場合、中止の回数の合計はそれほど高くないため、あまり危険ではないように見えます。

次のクエリは、read_columns、write_constructive_columns、write_delete_tables など、fprint 1557557373282541312 のトランザクションに関して、より詳細な情報を返します。この情報は、クライアント コードでトランザクションを識別するのに役立ち、このシナリオでの再試行のロジックを確認できます。

SELECT
  interval_end,
  fprint,
  read_columns,
  write_constructive_columns,
  write_delete_tables,
  commit_attempt_count,
  commit_abort_count,
  commit_retry_count
FROM
  SPANNER_SYS.TXN_STATS_TOP_10MINUTE
WHERE
  fprint = 1557557373282541312
ORDER BY
  interval_end DESC;
interval_end fprint read_columns write_constructive_columns write_delete_tables commit_attempt_count commit_abort_count commit_retry_count
2021-01-27T18:30:00Z 1557557373282541312 ['Singers._exists'] ['Singers.FirstName', 'Singers.LastName', 'Singers._exists'] [] 805228 1839 0
2021-01-27T18:20:00Z 1557557373282541312 ['Singers._exists'] ['Singers.FirstName', 'Singers.LastName', 'Singers._exists'] [] 1034429 38779 0
2021-01-27T18:10:00Z 1557557373282541312 ['Singers._exists'] ['Singers.FirstName', 'Singers.LastName', 'Singers._exists'] [] 833677 2266 0
2021-01-27T18:00:00Z 1557557373282541312 ['Singers._exists'] ['Singers.FirstName', 'Singers.LastName', 'Singers._exists'] [] 694560 1348 0

トランザクションで、Singers._exists 非表示列の読み取りを行い、行の存在を確認していることがわかります。トランザクションは、Singers.FirstName 列と Singer.LastName 列にも書き込みを行っています。この情報は、カスタム クライアント ライブラリで実装されたトランザクションの再試行メカニズムが、期待どおりに機能しているかどうかの判別に役立ちます。

次のステップ