クエリの統計情報

Cloud Spanner では、CPU を最も多く使用したクエリおよびすべてのクエリの総計について、多数の統計情報を保持する組み込みテーブルが提供されています。Google Cloud Platform Console はこれらの SPANNER_SYS.QUERY_STATS* テーブル内のデータを使用してクエリ統計ビューを生成しますが、SQL ステートメントを使用してテーブルから統計を取得することもできます。

使用量

SPANNER_SYS データは SQL インターフェース(executeQuerygcloud spanner databases execute-sql など)を介してのみ利用できます。Cloud Spanner が提供する他の単一読み取りメソッドは SPANNER_SYS をサポートしていません。

クエリごとにグループ化された CPU 使用率

次のテーブルでは、特定の期間中に CPU 使用率が最も高いクエリが追跡されます。

  • SPANNER_SYS.QUERY_STATS_TOP_MINUTE: 1 分間のクエリ
  • SPANNER_SYS.QUERY_STATS_TOP_10MINUTE: 10 分間のクエリ
  • SPANNER_SYS.QUERY_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 は統計を SQL クエリのテキストごとにグループ化します。クエリでクエリ パラメータを使用する場合、Cloud Spanner はそのクエリのすべての実行を 1 行にグループ化します。クエリで文字列リテラルを使用する場合、Cloud Spanner はクエリテキスト全体が同一の場合のみ統計をグループ化し、いずれかのテキストが異なっていれば、各クエリは別々の行として表示されます。

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

  • 期間中に実行されたすべてのクエリを Cloud Spanner が保存できない場合、指定された期間中の CPU 使用率が最も高いクエリが優先されます。

  • 追跡されるクエリには、ユーザーが完了、失敗、キャンセルされたクエリが含まれます。

  • 実行したものの、完了していないクエリに固有の統計情報のサブセット:

    • 完了しなかったクエリの実行数と平均レイテンシ(秒単位)。

    • タイムアウトしたクエリの実行数。

    • ユーザーがキャンセルしたか、ネットワーク接続の問題が原因で失敗したクエリの実行数。

テーブル スキーマ

列名 説明
INTERVAL_END TIMESTAMP その時間間隔に含まれているクエリが実行された時間間隔の終わり。
TEXT STRING SQL クエリテキスト。約 64 KB に切り捨てられます。
TEXT_TRUNCATED BOOL クエリテキストが切り捨てられたかどうか。
TEXT_FINGERPRINT INT64 クエリテキストのハッシュ。
EXECUTION_COUNT INT64 Cloud Spanner が一定期間内にクエリを検出した回数。
AVG_LATENCY_SECONDS FLOAT64 データベース内での各クエリ実行の平均時間(秒単位)。この平均からは、オーバーヘッドだけでなく、結果セットのエンコードおよび伝送時間も除外されます。
AVG_ROWS FLOAT64 クエリから返された平均行数。
AVG_BYTES FLOAT64 送信エンコードのオーバーヘッドを除いた、クエリから返されたデータの平均バイト数。
AVG_ROWS_SCANNED FLOAT64 クエリでスキャンされた平均行数(削除された値を除く)。
AVG_CPU_SECONDS FLOAT64 Cloud Spanner がクエリを実行するためにすべての操作に費やした CPU 時間の平均秒数。
ALL_FAILED_EXECUTION_COUNT INT64 クエリが一定期間内に失敗した回数。
ALL_FAILED_AVG_LATENCY_SECONDS FLOAT64 データベース内で失敗した各クエリ実行の平均時間(秒単位)。この平均からは、オーバーヘッドだけでなく、結果セットのエンコードおよび伝送時間も除外されます。
CANCELLED_OR_DISCONNECTED_EXECUTION_COUNT INT64 ユーザーがキャンセルしたか、一定期間内にネットワーク接続の問題が原因で失敗したクエリの回数。
TIMED_OUT_EXECUTION_COUNT INT64 クエリが一定期間内にタイムアウトした回数。

失敗したクエリに対する EXECUTION_COUNTAVG_LATENCY_SECONDS には、構文が正しくないか、一時的なエラーが発生したものの、再試行が成功したクエリが含まれます。

集計した統計のテーブル

Cloud Spanner が特定の期間に統計情報をキャプチャした、すべてのクエリの集計データを追跡するテーブルもあります。

  • SPANNER_SYS.QUERY_STATS_TOTAL_MINUTE: 1 分間のクエリ
  • SPANNER_SYS.QUERY_STATS_TOTAL_10MINUTE: 10 分間のクエリ
  • SPANNER_SYS.QUERY_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 行のみが返され、完了したクエリ、失敗したクエリ、ユーザーがキャンセルしたクエリが含まれます。

  • TOTAL テーブルにキャプチャされた統計には、Cloud Spanner が TOP テーブルでキャプチャしなかったクエリが含まれる場合があります。

テーブル スキーマ

列名 説明
INTERVAL_END TIMESTAMP その時間間隔に含まれているクエリが実行された時間間隔の終わり。
EXECUTION_COUNT INT64 Cloud Spanner が一定期間内にクエリを検出した回数。
AVG_LATENCY_SECONDS FLOAT64 データベース内での各クエリ実行の平均時間(秒単位)。この平均からは、オーバーヘッドだけでなく、結果セットのエンコードおよび伝送時間も除外されます。
AVG_ROWS FLOAT64 クエリから返された平均行数。
AVG_BYTES FLOAT64 送信エンコードのオーバーヘッドを除いた、クエリから返されたデータの平均バイト数。
AVG_ROWS_SCANNED FLOAT64 クエリでスキャンされた平均行数(削除された値を除く)。
AVG_CPU_SECONDS FLOAT64 Cloud Spanner がクエリを実行するためにすべての操作に費やした CPU 時間の平均秒数。
ALL_FAILED_EXECUTION_COUNT INT64 クエリが一定期間内に失敗した回数。
ALL_FAILED_AVG_LATENCY_SECONDS FLOAT64 データベース内で失敗した各クエリ実行の平均時間(秒単位)。この平均からは、オーバーヘッドだけでなく、結果セットのエンコードおよび伝送時間も除外されます。
CANCELLED_OR_DISCONNECTED_EXECUTION_COUNT INT64 ユーザーがキャンセルしたか、一定期間内にネットワーク接続の問題が原因で失敗したクエリの回数。
TIMED_OUT_EXECUTION_COUNT INT64 クエリが一定期間内にタイムアウトした回数。

データの保持

Cloud Spanner は最低でも、次の期間中に各テーブルのデータを保持します。

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

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

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

クエリの例

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

特定の期間における各クエリの基本的な統計を一覧表示する

次のクエリは、直前の 1 分間における上位のクエリの生データを返します。

SELECT text,
       interval_end,
       execution_count,
       avg_latency_seconds,
       avg_rows,
       avg_bytes,
       avg_rows_scanned,
       avg_cpu_seconds
FROM spanner_sys.query_stats_top_minute
ORDER BY interval_end DESC;

CPU 使用率が最も高いクエリを一覧表示する

次のクエリは、直前の 1 時間における CPU 使用率が最も高いクエリを返します。

SELECT text,
       execution_count AS count,
       avg_latency_seconds AS latency,
       avg_cpu_seconds AS cpu,
       execution_count * avg_cpu_seconds AS total_cpu
FROM spanner_sys.query_stats_top_hour
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.query_stats_top_hour)
ORDER BY total_cpu DESC;

特定の期間における総実行数を調べる

次のクエリは、直近の 1 分間に実行されたクエリの総数を返します。

SELECT interval_end,
       execution_count
FROM spanner_sys.query_stats_total_minute
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.query_stats_top_minute);

クエリの平均レイテンシを求める

次のクエリは、特定のクエリの平均レイテンシ情報を返します。

SELECT avg_latency_seconds
FROM spanner_sys.query_stats_top_hour
WHERE text LIKE "SELECT x FROM table WHERE x=@foo;";

最も多くのデータをスキャンするクエリを見つける

クエリがスキャンしたデータ量の尺度として、クエリによってスキャンされた行数を使用できます。次のクエリは、直前の 1 時間に実行されたクエリによってスキャンされた行数を返します。

SELECT text,
       execution_count,
       avg_rows_scanned
FROM spanner_sys.query_stats_top_hour
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.query_stats_top_hour)
ORDER BY avg_rows_scanned DESC;

すべてのクエリでの CPU 使用率の合計

次のクエリは、直前の 1 時間に使用された CPU 時間数を返します。

SELECT (avg_cpu_seconds * execution_count / 60 / 60)
  AS total_cpu_hours
FROM spanner_sys.query_stats_total_hour
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.query_stats_total_hour);

特定の期間内に失敗したクエリを一覧表示する

次のクエリは、過去 1 分間における上位クエリに対する失敗したクエリの実行回数と平均レイテンシなどの元データを返します。

SELECT text,
       interval_end,
       execution_count,
       all_failed_execution_count,
       all_failed_avg_latency_seconds,
       avg_latency_seconds,
       avg_rows,
       avg_bytes,
       avg_rows_scanned,
       avg_cpu_seconds
FROM spanner_sys.query_stats_top_minute
WHERE all_failed_execution_count > 0
ORDER BY interval_end;

特定の期間における合計エラー数を調べる

次のクエリは、直近の 1 分間に実行に失敗したクエリの合計数を返します。

SELECT interval_end,
       all_failed_execution_count
FROM spanner_sys.query_stats_total_minute
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.query_stats_top_minute)
ORDER BY interval_end;

タイムアウトが最も多かったクエリを一覧表示する

次のクエリは、直前の 1 時間におけるタイムアウト数が最も多かったがクエリを返します。

SELECT text,
       execution_count AS count,
       timed_out_execution_count AS timeout_count,
       avg_latency_seconds AS latency,
       avg_cpu_seconds AS cpu,
       execution_count * avg_cpu_seconds AS total_cpu
FROM spanner_sys.query_stats_top_hour
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.query_stats_top_hour)
ORDER BY timed_out_execution_count DESC;

クエリ実行の成功と失敗の平均レイテンシを求める

次のクエリは、特定のクエリにおける合計平均レイテンシ、成功した実行の平均レイテンシ、失敗した実行の平均レイテンシを返します。

SELECT avg_latency_seconds AS combined_avg_latency,
       all_failed_avg_latency_seconds AS failed_execution_latency,
       ( avg_latency_seconds * execution_count -
         all_failed_avg_latency_seconds * all_failed_execution_count
       ) / (
       execution_count - all_failed_execution_count ) AS success_execution_latency
FROM   spanner_sys.query_stats_top_hour
WHERE  text LIKE "select x from table where x=@foo;";

クエリ統計情報を使用した CPU 使用率が高いクエリ、またはレイテンシが長いクエリについてのトラブルシューティング

クエリ統計情報は、Cloud Spanner データベースの高 CPU 使用率を調査する必要がある場合や、データベースで CPU の負荷がかかるクエリを把握する場合に有用です。大量のデータベース リソースを使用するクエリを調査することで、Cloud Spanner ユーザーは運用コストを削減し、場合によっては一般的なシステムのレイテンシを短縮できます。次の手順では、クエリ統計情報を使用してデータベースにおける高 CPU 使用率について調査する方法を説明します。

下記の例では CPU 使用率に重点を置いていますが、同様の手順で、クエリのレイテンシの増加をトラブルシューティングし、レイテンシが最大のクエリを特定できます。CPU 使用率ではなく、レイテンシで期間とクエリを選択するだけです。

調査する期間を選択する

まず、アプリケーションでの CPU 使用率が高くなり始めた時間を探すことから調査を開始します。たとえば、2020 年 7 月 24 日午後 5 時(UTC)頃に問題が発生するとします。

選択した期間のクエリ統計情報を収集する

調査を開始する期間を選択していただいている場合は、その時刻前後に QUERY_STATS_TOTAL_10MINUTE テーブルで収集された統計情報を確認いたします。このクエリの結果は、一定期間に CPU と他のクエリ統計がどのように変化したかを示します。

次のクエリは、午後 4 時 30 分から午後 5 時 30 分(UTC)までの集計されたクエリ統計情報を返します。クエリでは、表示目的で ROUND を使用して小数点以下の桁数を制限します。

SELECT interval_end,
       execution_count AS count,
       ROUND(avg_total_latency_seconds,2) AS latency,
       ROUND(avg_rows,2) AS rows_returned,
       ROUND(avg_bytes,2) AS bytes,
       ROUND(avg_rows_scanned,2) AS rows_scanned,
       ROUND(avg_cpu_seconds,3) AS avg_cpu
FROM spanner_sys.query_stats_total_10minute
WHERE
  interval_end >= "2020-07-24T16:30:00Z"
  AND interval_end <= "2020-07-20T17:30:00Z"
ORDER BY interval_end;

このクエリを実行すると、次のような結果が生成されます。

interval_end latency rows_returned バイト rows_scanned avg_cpu
2020-07-24T16:30:00Z 6 0.06 5.00 536.00 16.67 0.035
2020-07-24T16:40:00Z 55 0.02 0.22 25.29 0.22 0.004
2020-07-24T16:50:00Z 102 0.02 0.30 33.35 0.30 0.004
2020-07-24T17:00:00Z 154 1.06 4.42 486.33 7792208.12 4.633
2020-07-24T17:10:00Z 94 0.02 1.68 106.84 1.68 0.006
2020-07-24T17:20:00Z 110 0.02 0.38 34.60 0.38 0.005
2020-07-24T17:30:00Z 47 0.02 0.23 24.96 0.23 0.004

上の結果テーブルでは、avg_cpu 列の平均 CPU 時間は、午後 5 時までの期間(ハイライト表示)に最大であることがわかります。また、スキャンされる平均行数も増大しています。これは、よりコストの高いクエリが午後 4 時 50 分から午後 5 時の範囲で実行されたことを示します。次は、この期間を選択して以降のステップで詳しく調査しましょう。

CPU 使用率の高いクエリを特定する

調査する時間間隔を指定して、QUERY_STATS_TOP_10MINUTE テーブルに対してクエリを実行します。このクエリの結果は、CPU 使用率が高いクエリを特定するうえで有用です。

SELECT text_fingerprint AS fingerprint,
       execution_count AS count,
       ROUND(avg_latency_seconds,2) AS latency,
       ROUND(avg_cpu_seconds,3) AS cpu,
       ROUND(execution_count * avg_cpu_seconds,3) AS total_cpu
FROM spanner_sys.query_stats_top_10MINUTE
WHERE
  interval_end = "2020-07-20T17:00:00Z"
ORDER BY total_cpu DESC;

このクエリを実行すると、次のような結果が得られます。

Fingerprint latency CPU total_cpu
5505124206529314852 30 3.88 17.635 529.039
1697951036096498470 10 4.49 18.388 183.882
2295109096748351518 1 0.33 0.048 0.048
11618299167612903606 1 0.25 0.021 0.021
10302798842433860499 1 0.04 0.006 0.006
123771704548746223 1 0.04 0.006 0.006
4216063638051261350 1 0.04 0.006 0.006
3654744714919476398 1 0.04 0.006 0.006
2999453161628434990 1 0.04 0.006 0.006
823179738756093706 1 0.02 0.005 0.0056

結果テーブルでハイライト表示されている上位 2 つのクエリは、平均 CPU とレイテンシ、実行回数、合計 CPU 数といった点で外れ値です。これらの結果で挙げられた最初のクエリを調査しましょう。

クエリの実行の推移を比較する

調査を絞り込むと、QUERY_STATS_TOP_MINUTE テーブルに注目できます。特定のクエリに関する実行時間の推移を比較すると、返される行数またはバイト数、またはスキャンされた行数と CPU やレイテンシの高くなった行数との相関関係を確認できます。偏差は、データにおける不均一性を示す場合があります。スキャン対象の行数が一貫して多い場合、適切なインデックスが存在しないか、最適な結合順序がない可能性があります。

クエリの text_fingerprint をフィルタリングする次のステートメントを実行して、平均 CPU 使用率とレイテンシが最も高いクエリを調査してみましょう。

SELECT interval_end,
       ROUND(avg_latency_seconds,2) AS latency,
       avg_rows AS rows_returned,
       avg_bytes AS bytes_returned,
       avg_rows_scanned AS rows_scanned,
       ROUND(avg_cpu_seconds,3) AS cpu,
FROM spanner_sys.query_stats_top_minute
WHERE text_fingerprint = 5505124206529314852
ORDER BY interval_end DESC;

このクエリを実行すると、次のような結果が返されます。

interval_end latency rows_returned bytes_returned rows_scanned CPU
2020-07-24T17:00:00Z 4.55 21 2365 30000000 19.255
2020-07-24T16:00:00Z 3.62 21 2365 30000000 17.255
2020-07-24T15:00:00Z 4.37 21 2365 30000000 18.350
2020-07-24T14:00:00Z 4.02 21 2365 30000000 17.748
2020-07-24T13:00:00Z 3.12 21 2365 30000000 16.380
2020-07-24T12:00:00Z 3.45 21 2365 30000000 15.476
2020-07-24T11:00:00Z 4.94 21 2365 30000000 22.611
2020-07-24T10:00:00Z 6.48 21 2365 30000000 21.265
2020-07-24T09:00:00Z 0.23 21 2365 5 0.040
2020-07-24T08:00:00Z 0.04 21 2365 5 0.021
2020-07-24T07:00:00Z 0.09 21 2365 5 0.030

前の結果を確認すると、スキャンされた行数、使用された CPU 数、レイテンシがすべて午前 9 時頃に大幅に変わったことがわかりました。この数値が大幅に増加した理由を把握するため、クエリテキストを調べて、スキーマの変更がクエリに影響を及ぼしたかどうかを確認します。

次のクエリを使用して、調査するクエリのクエリテキストを取得します。

SELECT text,
       text_truncated
FROM spanner_sys.query_stats_top_hour
WHERE text_fingerprint = 5505124206529314852
LIMIT 1;

次のような結果が返されます。

テキスト text_truncated
o_custkey = 36901 の注文から * を選択; いいえ

返されたクエリテキストを調べると、クエリが o_custkey というフィールドでフィルタリングされていることがわかりました。これは、orders テーブルの非キー列です。以前は、その列には午前 9 時にドロップされるインデックスがありました。このことから、このクエリの費用が変化した理由がわかります。インデックスは再度追加できます。また、クエリが頻繁に実行されていない場合は、インデックスが保持されないので読み取りコストが高くなります。

これまでの調査では、正常に完了したクエリに焦点を合わせ、データベースのパフォーマンスが低下した原因を 1 つ求めていました。次のステップでは、失敗したクエリまたはキャンセルされたクエリに焦点を絞り、そのデータを詳しく調べて分析情報を得る方法について説明します。

失敗したクエリを調査する

正常に完了していないクエリは、タイムアウト、キャンセル、またはその他の理由で失敗する前にリソースを消費し続けます。Cloud Spanner は、完了したクエリと失敗したクエリの実行数と消費されたリソースを追跡します。

失敗したクエリがシステム使用率に大きく寄与しているかどうかを確認するには、まず、特定の期間内に失敗したクエリの数を確認します。

SELECT interval_end,
       all_failed_execution_count AS failed_count,
       all_failed_avg_latency_seconds AS latency
FROM spanner_sys.query_stats_total_minute
WHERE
  interval_end >= "2020-07-24T16:50:00Z"
  AND interval_end <= "2020-07-24T17:00:00Z"
ORDER BY interval_end;
interval_end failed_count latency
2020-07-24T16:52:00Z 1 15.211391
2020-07-24T16:53:00Z 3 58.312232

さらに詳しく調べると、次のクエリを使用して失敗した可能性が高いクエリを見つけることができます。

SELECT interval_end,
       text_fingerprint,
       execution_count,
       avg_latency_seconds AS avg_latency,
       all_failed_execution_count AS failed_count,
       all_failed_avg_latency_seconds AS failed_latency,
       cancelled_or_disconnected_execution_count AS cancel_count,
       timed_out_execution_count AS to_count
FROM spanner_sys.query_stats_top_minute
WHERE all_failed_execution_count > 0
ORDER BY interval_end;
interval_end text_fingerprint execution_count failed_count cancel_count to_count
2020-07-24T16:52:00Z 5505124206529314852 3 1 1 0
2020-07-24T16:53:00Z 1697951036096498470 2 1 1 0
2020-07-24T16:53:00Z 5505124206529314852 5 2 1 1

上のテーブルに示すように、フィンガープリント 5505124206529314852 を含むクエリは、異なる期間で何度も失敗しています。このような障害のパターンが発生した場合は、成功した実行と失敗した実行のレイテンシを比較することをおすすめします。

SELECT interval_end,
       avg_latency_seconds AS combined_avg_latency,
       all_failed_avg_latency_seconds AS failed_execution_latency,
       ( avg_latency_seconds * execution_count -
         all_failed_avg_latency_seconds * all_failed_execution_count
       ) / (
       execution_count - all_failed_execution_count ) AS success_execution_latency
FROM   spanner_sys.query_stats_top_hour
WHERE  text_fingerprint = 5505124206529314852;
interval_end combined_avg_latency failed_execution_latency success_execution_latency
2020-07-24T17:00:00Z 3.880420 13.830709 2.774832

ベスト プラクティスを適用する

最適化のための候補クエリを特定したら、次にクエリ プロファイルを確認し、SQL のベスト プラクティスを使用して最適化を試みます。

次のステップ