クエリの統計情報

Spanner では、CPU を最も多く使用したクエリや DML ステートメント、およびすべてのクエリ(変更ストリーム クエリを含む)の集計について、多数の統計情報を保持する組み込みテーブルが用意されています。

提供状況

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

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:00~11:58:59
    • 10 分: 午前 11:40:00~11:49:59
    • 1 時間: 午前 10:00:00~10:59:59
  • Spanner は、統計情報を SQL クエリのテキストごとにグループ化します。クエリでクエリ パラメータを使用する場合、Spanner は、そのクエリのすべての実行を 1 行にグループ化します。クエリで文字列リテラルを使用する場合、Spanner は、クエリテキスト全体が同一の場合のみ統計情報をグループ化し、いずれかのテキストが異なっていれば、各クエリは別々の行として表示されます。バッチ DML の場合、Spanner は、フィンガープリントを生成する前に、連続する同一のステートメントを重複除去することによってバッチを正規化します。

  • リクエストタグが存在する場合は、FPRINT がリクエストタグのハッシュです。存在しない場合は、TEXT 値のハッシュです。

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

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

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

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

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

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

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

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

テーブル スキーマ

列名 タイプ 説明
INTERVAL_END TIMESTAMP その時間間隔に含まれているクエリが実行された時間間隔の終わり。
REQUEST_TAG STRING このクエリ オペレーションの省略可能なリクエストタグ。タグの使用の詳細については、リクエストタグによるトラブルシューティングをご覧ください
QUERY_TYPE STRING クエリが PARTITIONED_QUERYQUERY かを指定します。PARTITIONED_QUERY は、PartitionQuery API から取得した partitionToken を使用したクエリです。他のすべてのクエリと DML ステートメントは、QUERY クエリタイプで示されます。 パーティション化された DML のクエリ統計情報はサポートされていません。
TEXT STRING SQL クエリテキスト。約 64 KB に切り捨てられます。

同じタグ文字列を持つ複数のクエリの統計情報は、REQUEST_TAG に一致するタグ文字列とともに 1 行にグループ化されます。このフィールドには、そうしたクエリのいずれかのテキストのみが表示され、約 64 KB に切り捨てられます。 バッチ DML の場合、SQL ステートメントは、区切り文字のセミコロンを使用して 1 行に連結されます。連続する同一の SQL テキストは、切り詰める前に重複が除去されます。
TEXT_TRUNCATED BOOL クエリテキストが切り捨てられたかどうか。
TEXT_FINGERPRINT INT64 REQUEST_TAG 値のハッシュ(存在する場合)。存在しない場合は、TEXT 値のハッシュ。 監査ログの query_fingerprint フィールドに対応
EXECUTION_COUNT INT64 Spanner が一定期間内にクエリを検出した回数。
AVG_LATENCY_SECONDS FLOAT64 データベース内での各クエリ実行の平均時間(秒単位)。この平均からは、オーバーヘッドだけでなく、結果セットのエンコードおよび伝送時間も除外されます。
AVG_ROWS FLOAT64 クエリから返された平均行数。
AVG_BYTES FLOAT64 送信エンコードのオーバーヘッドを除いた、クエリから返されたデータの平均バイト数。
AVG_ROWS_SCANNED FLOAT64 クエリでスキャンされた平均行数(削除された値を除く)。
AVG_CPU_SECONDS FLOAT64 Spanner がクエリを実行するためにすべての操作に費やした CPU 時間の平均秒数。
ALL_FAILED_EXECUTION_COUNT INT64 クエリが一定期間内に失敗した回数。
ALL_FAILED_AVG_LATENCY_SECONDS FLOAT64 データベース内で失敗した各クエリ実行の平均時間(秒単位)。この平均からは、オーバーヘッドだけでなく、結果セットのエンコードおよび伝送時間も除外されます。
CANCELLED_OR_DISCONNECTED_EXECUTION_COUNT INT64 ユーザーがキャンセルしたか、一定期間内にネットワーク接続の問題が原因で失敗したクエリの回数。
TIMED_OUT_EXECUTION_COUNT INT64 クエリが一定期間内にタイムアウトした回数。
AVG_BYTES_WRITTEN FLOAT64 ステートメントが書き込んだ平均バイト数。
AVG_ROWS_WRITTEN FLOAT64 ステートメントによって変更された平均行数。
STATEMENT_COUNT INT64 このエントリに集約されたステートメントの合計。通常のクエリと DML の場合、これは実行回数と同じです。バッチ DML の場合、Spanner はバッチ内のステートメントの数をキャプチャします。
RUN_IN_RW_TRANSACTION_EXECUTION_COUNT INT64 クエリが読み取り / 書き込みトランザクションの一部として実行された回数。この列は、クエリを読み取り専用トランザクションに移動することで、ロック競合を回避できるかどうかの判別に役立ちます。
LATENCY_DISTRIBUTION ARRAY<STRUCT>

クエリ実行時間のヒストグラム。値は秒単位で測定されます。

この配列には単一の要素が含まれ、次のタイプがあります。
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 パーセンタイル レイテンシを確認するをご覧ください。

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

AVG_MEMORY_PEAK_USAGE_BYTES FLOAT64

分散クエリの実行中の平均ピークメモリ使用量(バイト単位)。

この統計情報を使用して、メモリ上限に達する可能性が高いクエリまたはテーブルデータのサイズを特定します。

AVG_MEMORY_USAGE_PERCENTAGE FLOAT64

分散クエリの実行中に必要な平均メモリ使用量(このクエリで許可されているメモリ上限の割合)。

この統計情報は、クエリの実行に必要なメモリのみを追跡します。一部のオペレーターは、パフォーマンスを向上させるために追加のバッファリング メモリを使用します。使用される追加のバッファリング メモリはクエリプランに表示されますが、バッファリング メモリは最適化に使用され、必須ではないため、AVG_MEMORY_USAGE_PERCENTAGE の計算には使用されません。

この統計情報を使用して、メモリ使用量の上限に近づいており、データサイズの増加により失敗するリスクがあるクエリを特定します。クエリが失敗するリスクを軽減するには、SQL のベスト プラクティスを参照してこれらのクエリを最適化するか、クエリを分割して読み取るデータを減らします。

AVG_QUERY_PLAN_CREATION_TIME_SECS FLOAT64

クエリの実行時の作成を含む、クエリのコンパイルに費やされた平均 CPU 時間(秒単位)。

この列の値が高い場合は、パラメータ化されたクエリを使用します。

AVG_FILESYSTEM_DELAY_SECS FLOAT64

クエリがファイル システムからの読み取りに費やした時間、または入出力(I/O)でブロックされた時間の平均。

この統計情報を使用して、ファイル システム I/O によって発生する可能性のある高レイテンシを特定します。軽減するには、インデックスを追加するか、既存のインデックスに STORING(GoogleSQL)または INCLUDE(PostgreSQL)句を追加します。

AVG_REMOTE_SERVER_CALLS FLOAT64

クエリによって完了したリモート サーバー コール(RPC)の平均数。

この統計情報は、同じ数の行をスキャンする異なるクエリで RPC 数が大きく異なるかどうかを特定するために使用します。RPC 値が高いクエリでは、インデックスを追加するか、既存のインデックスに STORING(GoogleSQL)または INCLUDE(PostgreSQL)句を追加すると効果的です。

AVG_ROWS_SPOOLED FLOAT64

クエリ ステートメントによって一時ディスク(インメモリではない)に書き込まれた行数の平均。

この統計情報を使用して、メモリ使用量が多く、インメモリで実行できない可能性のあるレイテンシの高いクエリを特定します。緩和するには、JOIN の順序を変更するか、必要な SORT を提供するインデックスを追加します。

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

統計情報の集計

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:00~11:58:59
    • 10 分: 午前 11:40:00~11:49:59
    • 1 時間: 午前 10:00:00~10:59:59
  • 各行には、指定した期間中にデータベースに対して実行されたすべてのクエリの統計がまとめて含まれています。時間間隔ごとに 1 行のみが返され、完了したクエリ、失敗したクエリ、ユーザーがキャンセルしたクエリが含まれます。

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

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

    • クエリ実行回数
    • クエリの失敗数
    • クエリのレイテンシ
    • 返された行数
    • スキャンされた行数
    • 返されたバイト数
    • クエリの CPU 時間

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

テーブル スキーマ

列名 タイプ 説明
INTERVAL_END TIMESTAMP その時間間隔に含まれているクエリが実行された時間間隔の終わり。
EXECUTION_COUNT INT64 Spanner が一定期間内にクエリを検出した回数。
AVG_LATENCY_SECONDS FLOAT64 データベース内での各クエリ実行の平均時間(秒単位)。この平均からは、オーバーヘッドだけでなく、結果セットのエンコードおよび伝送時間も除外されます。
AVG_ROWS FLOAT64 クエリから返された平均行数。
AVG_BYTES FLOAT64 送信エンコードのオーバーヘッドを除いた、クエリから返されたデータの平均バイト数。
AVG_ROWS_SCANNED FLOAT64 クエリでスキャンされた平均行数(削除された値を除く)。
AVG_CPU_SECONDS FLOAT64 Spanner がクエリを実行するためにすべての操作に費やした CPU 時間の平均秒数。
ALL_FAILED_EXECUTION_COUNT INT64 クエリが一定期間内に失敗した回数。
ALL_FAILED_AVG_LATENCY_SECONDS FLOAT64 データベース内で失敗した各クエリ実行の平均時間(秒単位)。この平均からは、オーバーヘッドだけでなく、結果セットのエンコードおよび伝送時間も除外されます。
CANCELLED_OR_DISCONNECTED_EXECUTION_COUNT INT64 ユーザーがキャンセルしたか、一定期間内にネットワーク接続の問題が原因で失敗したクエリの回数。
TIMED_OUT_EXECUTION_COUNT INT64 クエリが一定期間内にタイムアウトした回数。
AVG_BYTES_WRITTEN FLOAT64 ステートメントが書き込んだ平均バイト数。
AVG_ROWS_WRITTEN FLOAT64 ステートメントによって変更された平均行数。
RUN_IN_RW_TRANSACTION_EXECUTION_COUNT INT64 クエリが読み取り / 書き込みトランザクションの一部として実行された回数。この列は、一部のクエリを読み取り専用トランザクションに移動することで、ロック競合を回避できるかどうかの判断に役立ちます。
LATENCY_DISTRIBUTION ARRAY<STRUCT>

クエリ全体にわたる実行時間のヒストグラム。値は秒単位です。

配列を次のように指定します。
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 パーセンタイル レイテンシを確認するをご覧ください。

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

データの保持

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 ステートメントは、クライアント ライブラリGoogle Cloud CLI、または Google Cloud Console を使用して実行できます。

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

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

SELECT text,
       request_tag,
       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,
       request_tag,
       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;";

クエリの 99 パーセンタイル レイテンシを確認する

次のクエリは、過去 10 分間に実行されたクエリ全体にわたる実行時間の 99 パーセンタイルを返します。

SELECT interval_end, avg_latency_seconds, SPANNER_SYS.DISTRIBUTION_PERCENTILE(latency_distribution[OFFSET(0)], 99.0)
  AS percentile_latency
FROM spanner_sys.query_stats_total_10minute
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.query_stats_total_10minute)
ORDER BY interval_end;

平均レイテンシと 99 パーセンタイルのレイテンシを比較すると、実行時間が長い可能性のある外れ値クエリを特定できます。

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

クエリがスキャンしたデータ量の尺度として、クエリによってスキャンされた行数を使用できます。次のクエリは、直前の 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;

最も多くのデータを書き込んだステートメントを見つける

クエリによって変更されたデータ量の尺度として、DML によって書き込まれた行数(または書き込みバイト数)を使用できます。次のクエリは、直前の 1 時間に実行された DML ステートメントによって書き込まれた行数を返します。

SELECT text,
       execution_count,
       avg_rows_written
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_written 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,
       request_tag,
       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 使用率が高いクエリ、またはレイテンシが長いクエリについてのトラブルシューティング

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

SQL コードまたは Query Insights ダッシュボードを使用して、データベース内の問題のあるクエリを調査できます。以下のトピックでは、SQL コードを使用してそのようなクエリを調査する方法を説明します。

下記の例では 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_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-24T17:30:00Z"
ORDER BY interval_end;

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

interval_end count 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-24T17:00:00Z"
ORDER BY total_cpu DESC;

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

fingerprint count 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 の注文から * を選択; false

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

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

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

正常に完了していないクエリは、タイムアウト、キャンセル、またはその他の理由で失敗する前にリソースを消費し続けます。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 のベスト プラクティスを使用して最適化を試みます。

次のステップ