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

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

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

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

対象

SPANNER_SYS データは SQL インターフェース(executeQuerygcloud spanner databases execute-sql など)を介してのみ利用できます。Cloud 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:01〜11:59:00
    • 10 分: 午前 11:40:01〜11:50:00
    • 1 時間: 午前 10:00:01~11:00:00
  • Cloud Spanner は、トランザクションの FPRINT(フィンガープリント)別に統計情報をグループ化します。FPRINT は、トランザクションに含まれるオペレーションに基づいて計算されるハッシュです。

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

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

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

テーブル スキーマ

列名 説明
INTERVAL_END TIMESTAMP 発生したトランザクションの実行を含む時間間隔の終了。
FPRINT INT64 フィンガープリントは、トランザクションに含まれるオペレーションに基づいて計算されるハッシュです。INTERVAL_ENDFPRINT は、これらのテーブルの一意のキーとして機能します。
READ_COLUMNS ARRAY<STRING> トランザクションが読み取った列のセット。
WRITE_CONSTRUCTIVE_COLUMNS ARRAY<STRING> トランザクションによって建設的に書き込まれた(つまり、新しい値に割り当てられた)列のセット。
WRITE_DELETE_TABLES ARRAY<STRING> トランザクションによって行が削除または置換されたテーブルのセット。
COMMIT_ATTEMPT_COUNT INT64 トランザクションに対する commit の合計回数。
COMMIT_FAILED_PRECONDITION_COUNT INT64 トランザクションの前提条件の失敗(FAILED_PRECONDITION)の合計数。
COMMIT_ABORT_COUNT INT64 トランザクションの commit が中止された回数。
AVG_PARTICIPANTS FLOAT64 各 commit 試行の平均参加者数。参加者の詳細については、Cloud Spanner の読み取りと書き込みのライフサイクルをご覧ください。
AVG_TOTAL_LATENCY_SECONDS FLOAT64 トランザクションの最初のオペレーションから commit の中断までにかかった平均秒数。
AVG_COMMIT_LATENCY_SECONDS FLOAT64 commit オペレーションの実行にかかった平均秒数。
AVG_BYTES FLOAT64 トランザクションが書き込んだ平均バイト数。

クエリの例

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

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

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

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_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 avg_bytes
40015598317 [] ["Routes"] ["Users"] 0.006578737 0.006547737 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"] ["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 には、Cloud 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:01〜11:59:00
    • 10 分: 午前 11:40:01〜11:50:00
    • 1 時間: 午前 10:00:01~11:00:00
  • 各行には、指定した期間中にデータベースに対して実行されたすべてのトランザクションの統計がまとめて含まれています。時間間隔ごとに 1 行のみとなります。

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

テーブル スキーマ

列名 説明
INTERVAL_END TIMESTAMP 統計情報が収集された時間間隔の終了。
COMMIT_ATTEMPT_COUNT INT64 トランザクションに対する commit の合計回数。
COMMIT_FAILED_PRECONDITION_COUNT INT64 トランザクションの前提条件の失敗(FAILED_PRECONDITION)の合計数。
COMMIT_ABORT_COUNT INT64 トランザクションの commit が中止された回数。
AVG_PARTICIPANTS FLOAT64 各 commit 試行の平均参加者数。参加者の詳細については、Cloud Spanner の読み取りと書き込みのライフサイクルをご覧ください。
AVG_TOTAL_LATENCY_SECONDS FLOAT64 トランザクションの最初のオペレーションから commit の中断までにかかった平均秒数。
AVG_COMMIT_LATENCY_SECONDS FLOAT64 commit 操作の実行にかかった平均秒数。
AVG_BYTES FLOAT64 トランザクションが書き込んだ平均バイト数。

クエリの例

このセクションには、トランザクションの統計を取得する SQL ステートメントの例がいくつか含まれています。これらの SQL ステートメントは、クライアント ライブラリgcloud コマンドライン ツール、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 行のみとなります。

データの保持

Cloud 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 日間を対象とする間隔。

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

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

調査する期間を選択する

競合の問題は、Cloud 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
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
2020-05-17 18:40:00-07:00 15185072816865185658 0.3508 0.0139 278802 142205
2020-05-17 18:40:00-07:00 15435530087434255496 0.1633 0.0142 129012 27177
2020-05-17 18:40:00-07:00 14175643543447671202 0.1423 0.0133 5357 636
2020-05-17 18:40:00-07:00 898069986622520747 0.0198 0.0158 6 0
2020-05-17 18:40:00-07:00 10510121182038036893 0.0168 0.0125 7 0
2020-05-17 18:40:00-07:00 9287748709638024175 0.0159 0.0118 4269 1
2020-05-17 18:40:00-07:00 7129109266372596045 0.0142 0.0102 182227 0
2020-05-17 18:40:00-07:00 15630228555662391800 0.0120 0.0107 58 0
2020-05-17 18:40:00-07:00 7907238229716746451 0.0108 0.0097 65 0
2020-05-17 18:40:00-07:00 10158167220149989178 0.0095 0.0047 3454 0
2020-05-17 18:40:00-07:00 9353100217060788102 0.0093 0.0045 725 0
2020-05-17 18:40:00-07:00 9521689070912159706 0.0093 0.0045 164 0
2020-05-17 18:40:00-07:00 11079878968512225881 0.0064 0.0019 65 0

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

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

この手順では、中断数が多いトランザクションで read_columnswrite_constructive_columnswrite_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
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_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 遅延 commit_latency commit_attempt_count commit_abort_count commit_failed_precondition_count avg_bytes
2020-05-17 16:40:00-07:00 0.095 0.010 53230 4752 0 91
2020-05-17 16:50:00-07:00 0.069 0.009 61264 3589 0 91
2020-05-17 17:00:00-07:00 0.150 0.010 75868 10557 0 91
2020-05-17 17:10:00-07:00 0.248 0.013 103151 30220 0 91
2020-05-17 17:20:00-07:00 0.310 0.012 130078 45655 0 91
2020-05-17 17:30:00-07:00 0.294 0.012 160064 64930 0 91
2020-05-17 17:40:00-07:00 0.315 0.013 209614 104949 0 91
2020-05-17 17:50:00-07:00 0.322 0.012 215682 100408 0 90
2020-05-17 18:00:00-07:00 0.310 0.012 230932 106728 0 91
2020-05-17 18:10:00-07:00 0.309 0.012 259645 131049 0 91
2020-05-17 18:20:00-07:00 0.315 0.013 272171 137910 0 90
2020-05-17 18:30:00-07:00 0.292 0.013 258944 121475 0 91
2020-05-17 18:40:00-07:00 0.350 0.013 278802 142205 0 91
2020-05-17 18:50:00-07:00 0.302 0.013 256259 115626 0 91
2020-05-17 19:00:00-07:00 0.315 0.014 250560 110662 0 91
2020-05-17 19:10:00-07:00 0.271 0.014 238384 99025 0 91
2020-05-17 19:20:00-07:00 0.273 0.014 219687 84019 0 91
2020-05-17 19:30:00-07:00 0.198 0.013 195357 59370 0 91
2020-05-17 19:40:00-07:00 0.181 0.013 167514 35705 0 91

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

まとめ

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

次のステップ