Hologres:スロークエリログの取得と分析

バージョンガイド

この機能を使用するには、Hologres V0.10 以降が必要です。インスタンスバージョンを確認するには、Hologres コンソールのインスタンスの詳細ページに移動します。以前のインスタンスをアップグレードするには、「Common upgrade preparation errors」を参照するか、Hologres サポートにお問い合わせください。詳細については、「How do I get more online support?」をご参照ください。

制限

• スロークエリログは、デフォルトで 1 か月 間保持されます。

• 1 回のクエリで返されるスロークエリ ログ エントリは最大 10,000 件です。一部のフィールドには長さの制限があります。フィールドの説明については、hg_query_log テーブルのセクションを参照してください。

• スロークエリログは Hologres メタデータウェアハウスの一部です。スロークエリログの検索が失敗してもビジネスクエリに影響はなく、ログの可用性は Hologres のサービスレベルアグリーメント (SLA) の対象外です。

仕組み

Hologres は、スロークエリログを hologres.hg_query_log システムテーブルに保存します。このテーブルには、完了した SQL ステートメントのみが記録され、まだ実行中のクエリはテーブルに書き込まれません。この動作は、V2、V3、およびそれ以降のバージョンで一貫しています。

記録される内容：

• V0.10 へのアップグレード後：実行時間が 100 ms を超える DML クエリ、およびすべての DDL 操作。

• V3.0.2 以降：100 ms を超えるクエリの詳細なレコードに加えて、100 ms 未満で完了する DQL および DML クエリの集計レコードも書き込まれます。

集計の仕組み (V3.0.2 以降)：

高速なクエリ (100 ms 未満) の場合、システムは同じ SQL フィンガープリント (digest) を共有する、成功した DQL および DML クエリをグループ化します。集計キーは、server_addr、usename、datname、warehouse_id、application_name、およびdigest です。各接続は、1 分あたり 1 つの集計レコードをフラッシュします。

前提条件

スロークエリログを表示するには、次のいずれかの権限が必要です。

[インスタンス内のすべてのデータベースのログを表示する場合：]

• スーパーユーザー： 次のコマンドを実行します。 Alibaba Cloud account ID を実際のユーザー名に置き換えてください。 RAM ユーザーの場合は、 p4_AccountID (RAM ユーザー名ではなく、アカウント ID) を使用してください。

  ALTER USER "Alibaba Cloud account ID" SUPERUSER;

• pg_read_all_stats グループ (スーパーユーザー以外の場合)： スーパーユーザーに連絡し、このグループへの追加を依頼してください。

  -- 標準 PostgreSQL 権限付与
  GRANT pg_read_all_stats TO "Alibaba Cloud account ID";
  
  -- 簡易権限モデル (SPM)
  CALL spm_grant('pg_read_all_stats', 'Alibaba Cloud account ID');
  
  -- スキーマレベル権限モデル (SLPM)
  CALL slpm_grant('pg_read_all_stats', 'Alibaba Cloud account ID');

[現在のデータベースのログのみを表示する場合：]

SPM または SLPM を有効にし、ユーザーを db_admin ロールに追加します。

-- SPM
CALL spm_grant('<db_name>_admin', 'Alibaba Cloud account ID');

-- SLPM
CALL slpm_grant('<db_name>.admin', 'Alibaba Cloud account ID');

一般ユーザー は、追加の設定なしで、現在のデータベース内の自分自身のクエリのみを表示できます。

スロークエリログの表示

Hologres では、スロークエリログを表示する方法が 2 つあります。視覚的な探索には HoloWeb を使用し、カスタムフィルター、時間範囲、エクスポートには SQL を使用します。

SQL フィンガープリント

V2.2 以降、hg_query_log の digest 列には、各クエリの SQL フィンガープリントが保存されます。SELECT、INSERT、DELETE、UPDATE 文では、Hologres が MD5 ハッシュをフィンガープリントとして計算します。

digest と query_id の使い分け：

• 同じタイプのクエリをグループ化して分析する場合は、digest を使用します。たとえば、平均で最も CPU を消費するクエリパターンを特定できます。

• 特定のクエリの実行を追跡する場合は、query_id を使用します。たとえば、特定の失敗したクエリの詳細をすべて取得できます。

フィンガープリントの計算方法：

• フィンガープリントは、SELECT、INSERT、DELETE、UPDATE 文に対してのみ収集されます。

• 空白 (スペース、改行、タブ) は無視されます。

• 定数値は無視されます。SELECT * FROM t WHERE a > 1 と SELECT * FROM t WHERE a > 2 は同じフィンガープリントになります。

• 配列の要素数は無視されます。WHERE a IN (1, 2) と WHERE a IN (3, 4, 5) は同じフィンガープリントになります。

• 定数データを含む INSERT 文の場合、フィンガープリントは挿入される行数の影響を受けません。

• 大文字と小文字は Hologres のクエリルールに従います。

• フィンガープリントにはデータベース名と完全修飾スキーマが含まれます。そのため、SELECT * FROM t と SELECT * FROM public.t が同じフィンガープリントになるのは、t が public スキーマにあり、かつ両方のクエリが同じテーブルを参照している場合のみです。

クエリの診断

以下の SQL の例は、最も一般的な診断シナリオを対象としています。すべてのクエリは hologres.hg_query_log を対象とします。

ログ内のスロークエリをカウント (デフォルト：先月)：

SELECT count(*) FROM hologres.hg_query_log;

出力例 — 先月 44 件のスロークエリ：

 count
-------
    44
(1 row)

ユーザーごとのスロークエリ数をカウント：

SELECT usename AS "User",
       count(1) AS "Query count"
FROM hologres.hg_query_log
GROUP BY usename
ORDER BY count(1) DESC;

出力例：

        User         | Query count
---------------------+-------------
 1111111111111111    |          27
 2222222222222222    |          11
 3333333333333333    |           4
 4444444444444444    |           2
(4 rows)

ID で特定のクエリを検索：

SELECT * FROM hologres.hg_query_log WHERE query_id = '13001450118416xxxx';

返されるフィールドの説明については、「hg_query_log テーブル」をご参照ください。

過去 10 分間のリソース集約型クエリを検索：

対象の時間範囲に合わせて間隔を調整してください。

SELECT status           AS "Status",
       duration         AS "Duration (ms)",
       query_start      AS "Start time",
       (read_bytes / 1048576)::text || ' MB'  AS "Data read",
       (memory_bytes / 1048576)::text || ' MB' AS "Memory",
       (shuffle_bytes / 1048576)::text || ' MB' AS "Shuffle",
       (cpu_time_ms / 1000)::text || ' s'    AS "CPU time",
       physical_reads   AS "Disk reads",
       query_id         AS "Query ID",
       query::char(30)
FROM hologres.hg_query_log
WHERE query_start >= now() - interval '10 min'
ORDER BY duration DESC,
         read_bytes DESC,
         shuffle_bytes DESC,
         memory_bytes DESC,
         cpu_time_ms DESC,
         physical_reads DESC
LIMIT 100;

出力例：

 Status  | Duration (ms) |       Start time       | Data read | Memory | Shuffle | CPU time | Disk reads |       Query ID     |         query
---------+---------------+------------------------+-----------+--------+---------+----------+------------+--------------------+--------------------------------
 SUCCESS |           149 | 2021-03-30 23:45:01+08 | 0 MB      | 25 MB  | 454 MB  | 321 s    |          0 | 13001450118416xxxx | explain analyze SELECT  * FROM
 SUCCESS |           137 | 2021-03-30 23:49:18+08 | 247 MB    | 21 MB  | 213 MB  | 803 s    |       7771 | 13001491818416xxxx | explain analyze SELECT  * FROM
 FAILED  |            53 | 2021-03-30 23:48:43+08 | 0 MB      | 0 MB   | 0 MB    | 0 s      |          0 | 13001484318416xxxx | SELECT ds::bigint / 0 FROM pub
(3 rows)

シナリオ：インスタンスバージョンのアップグレード後に CPU またはメモリ使用率が高い場合の診断

このクエリは、Hologres インスタンスバージョンのアップグレード後に CPU またはメモリ使用率が急上昇した場合に特に役立ちます。リソース消費が高い原因となっているクエリを特定するには：

1. CPU またはメモリの使用量が異常に高かった期間が含まれるように、WHERE 句の時間範囲を調整します。 たとえば、interval '10 min' を、スパイクが発生した時間ウィンドウに一致する範囲に置き換えます。

2. CPU 負荷の高いクエリを検索するには ORDER BY cpu_time_ms DESC を、メモリを大量に消費するクエリを検索するには ORDER BY memory_bytes DESC を追加します。

3. 結果の query_id、usename、および query 列を確認して特定のクエリとその所有者を特定し、それらのクエリを適宜分析および最適化します。

ステージごとの所要時間の内訳：

これにより、どのステージ (optimization_cost、start_query_cost、または get_next_cost) が遅延の大部分を占めているかを特定できます。各ステージの詳細については、hg_query_log テーブルセクションの期間の内訳テーブルをご参照ください。

SELECT status              AS "Status",
       duration            AS "Duration (ms)",
       optimization_cost   AS "Optimization cost (ms)",
       start_query_cost    AS "Startup cost (ms)",
       get_next_cost       AS "Execution cost (ms)",
       duration - optimization_cost - start_query_cost - get_next_cost AS "Other cost (ms)",
       query_id            AS "Query ID",
       query::char(30)
FROM hologres.hg_query_log
WHERE query_start >= now() - interval '10 min'
ORDER BY duration DESC,
         start_query_cost DESC,
         optimization_cost,
         get_next_cost DESC,
         duration - optimization_cost - start_query_cost - get_next_cost DESC
LIMIT 100;

出力例：

 Status  | Duration (ms) | Optimization cost (ms) | Startup cost (ms) | Execution cost (ms) | Other cost (ms) |       Query ID     |         query
---------+---------------+------------------------+-------------------+---------------------+-----------------+--------------------+--------------------------------
 SUCCESS |          4572 |                    521 |               320 |                3726 |               5 | 6000260625679xxxx  | -- /* user: wang ip: xxx.xx.x
 SUCCESS |          1490 |                    538 |                98 |                 846 |               8 | 12000250867886xxxx | -- /* user: lisa ip: xxx.xx.x
 SUCCESS |          1230 |                    502 |                95 |                 625 |               8 | 26000512070295xxxx | -- /* user: zhang ip: xxx.xx.
(3 rows)

1 時間あたりのクエリ量とデータ読み取り量を表示 (過去 3 時間)：

SELECT date_trunc('hour', query_start) AS query_start,
       count(1)           AS query_count,
       sum(read_bytes)    AS read_bytes,
       sum(cpu_time_ms)   AS cpu_time_ms
FROM hologres.hg_query_log
WHERE query_start >= now() - interval '3 h'
GROUP BY 1;

昨日の同じ時間帯のトラフィックと比較：

SELECT query_date,
       count(1)           AS query_count,
       sum(read_bytes)    AS read_bytes,
       sum(cpu_time_ms)   AS cpu_time_ms
FROM hologres.hg_query_log
WHERE query_start >= now() - interval '3 h'
GROUP BY query_date
UNION ALL
SELECT query_date,
       count(1)           AS query_count,
       sum(read_bytes)    AS read_bytes,
       sum(cpu_time_ms)   AS cpu_time_ms
FROM hologres.hg_query_log
WHERE query_start >= now() - interval '1d 3h'
  AND query_start <= now() - interval '1d'
GROUP BY query_date;

時間範囲内で最初に失敗したクエリを検索：

SELECT status              AS "Status",
       regexp_replace(message, '\n', ' ')::char(150) AS "Error message",
       duration            AS "Duration (ms)",
       query_start         AS "Start time",
       query_id            AS "Query ID",
       query::char(100)    AS "Query"
FROM hologres.hg_query_log
WHERE query_start BETWEEN '2021-03-25 17:00:00'::timestamptz
                      AND '2021-03-25 17:42:00'::timestamptz + interval '2 min'
  AND status = 'FAILED'
ORDER BY query_start ASC
LIMIT 100;

出力例：

 Status |                        Error message                        | Duration (ms) |       Start time       |      Query ID      | Query
--------+--------------------------------------------------------------+---------------+------------------------+--------------------+-------
 FAILED | Query:[1070285448673xxxx] code: kActorInvokeError msg: "..." |          1460 | 2021-03-25 17:28:54+08 | 1070285448673xxxx  | S...
 FAILED | Query:[1016285560553xxxx] code: kActorInvokeError msg: "..." |           131 | 2021-03-25 17:28:55+08 | 1016285560553xxxx  | S...
(2 rows)

昨日の新しいクエリパターンを検索 (総数)：

一昨日と比較して初めて出現したクエリを、ダイジェストでグループ化します。

SELECT COUNT(1)
FROM (
    SELECT DISTINCT t1.digest
    FROM hologres.hg_query_log t1
    WHERE t1.query_start >= CURRENT_DATE - INTERVAL '1 day'
      AND t1.query_start < CURRENT_DATE
      AND NOT EXISTS (
          SELECT 1
          FROM hologres.hg_query_log t2
          WHERE t2.digest = t1.digest
            AND t2.query_start < CURRENT_DATE - INTERVAL '1 day'
      )
      AND digest IS NOT NULL
) AS a;

出力例 — 昨日 10 件の新しいクエリパターン：

 count
-------
    10
(1 row)

昨日の新しいクエリパターンを検索 (タイプ別)：

SELECT a.command_tag,
       COUNT(1)
FROM (
    SELECT DISTINCT t1.digest, t1.command_tag
    FROM hologres.hg_query_log t1
    WHERE t1.query_start >= CURRENT_DATE - INTERVAL '1 day'
      AND t1.query_start < CURRENT_DATE
      AND NOT EXISTS (
          SELECT 1
          FROM hologres.hg_query_log t2
          WHERE t2.digest = t1.digest
            AND t2.query_start < CURRENT_DATE - INTERVAL '1 day'
      )
      AND t1.digest IS NOT NULL
) AS a
GROUP BY 1
ORDER BY 2 DESC;

出力例：

 command_tag | count
-------------+-------
 INSERT      |     8
 SELECT      |     2
(2 rows)

昨日の新しいクエリパターンを検索 (詳細付き)：

SELECT a.usename, a.status, a.query_id, a.digest,
       a.datname, a.command_tag, a.query, a.cpu_time_ms, a.memory_bytes
FROM (
    SELECT DISTINCT
        t1.usename, t1.status, t1.query_id, t1.digest,
        t1.datname, t1.command_tag, t1.query, t1.cpu_time_ms, t1.memory_bytes
    FROM hologres.hg_query_log t1
    WHERE t1.query_start >= CURRENT_DATE - INTERVAL '1 day'
      AND t1.query_start < CURRENT_DATE
      AND NOT EXISTS (
          SELECT 1
          FROM hologres.hg_query_log t2
          WHERE t2.digest = t1.digest
            AND t2.query_start < CURRENT_DATE - INTERVAL '1 day'
      )
      AND t1.digest IS NOT NULL
) AS a;

昨日の新しいクエリパターンを検索 (時間別)：

SELECT to_char(a.query_start, 'HH24') AS query_start_hour,
       a.command_tag,
       COUNT(1)
FROM (
    SELECT DISTINCT t1.query_start, t1.digest, t1.command_tag
    FROM hologres.hg_query_log t1
    WHERE t1.query_start >= CURRENT_DATE - INTERVAL '1 day'
      AND t1.query_start < CURRENT_DATE
      AND NOT EXISTS (
          SELECT 1
          FROM hologres.hg_query_log t2
          WHERE t2.digest = t1.digest
            AND t2.query_start < CURRENT_DATE - INTERVAL '1 day'
      )
      AND t1.digest IS NOT NULL
) AS a
GROUP BY 1, 2
ORDER BY 3 DESC;

出力例 — 昨日の 21:00 に 8 件の INSERT パターン、11:00 と 13:00 にそれぞれ 1 件の SELECT パターン：

 query_start_hour | command_tag | count
------------------+-------------+-------
               21 | INSERT      |     8
               11 | SELECT      |     1
               13 | SELECT      |     1
(3 rows)

ダイジェスト別にスロークエリをカウント (昨日)：

SELECT digest,
       command_tag,
       count(1)
FROM hologres.hg_query_log
WHERE query_start >= CURRENT_DATE - INTERVAL '1 day'
  AND query_start < CURRENT_DATE
GROUP BY 1, 2
ORDER BY 3 DESC;

平均 CPU 時間が最も高い上位 10 のクエリパターンを検索 (過去 1 日)：

SELECT digest,
       avg(cpu_time_ms)
FROM hologres.hg_query_log
WHERE query_start >= CURRENT_DATE - INTERVAL '1 day'
  AND query_start < CURRENT_DATE
  AND digest IS NOT NULL
  AND usename != 'system'
  AND cpu_time_ms IS NOT NULL
GROUP BY 1
ORDER BY 2 DESC
LIMIT 10;

平均メモリ使用率が最も高い上位 10 のクエリパターンを検索 (過去 1 週間)：

SELECT digest,
       avg(memory_bytes)
FROM hologres.hg_query_log
WHERE query_start >= CURRENT_DATE - INTERVAL '7 day'
  AND query_start < CURRENT_DATE
  AND digest IS NOT NULL
  AND memory_bytes IS NOT NULL
GROUP BY 1
ORDER BY 2 DESC
LIMIT 10;

設定パラメータ

これらの GUC パラメータを使用して、ログに記録する内容や取得する詳細レベルを制御します。

-- データベースレベル (スーパーユーザーのみ)
ALTER DATABASE dbname SET log_min_duration_statement = '250ms';

-- セッションレベル
SET log_min_duration_statement = '250ms';

-- データベースレベル (スーパーユーザーのみ)
ALTER DATABASE dbname SET log_min_duration_query_stats = '20s';

-- セッションレベル
SET log_min_duration_query_stats = '20s';

-- データベースレベル (スーパーユーザーのみ)
ALTER DATABASE dbname SET log_min_duration_query_plan = '10s';

-- セッションレベル
SET log_min_duration_query_plan = '10s';

ログ保持期間の変更

V3.0.27 以降では、データベースレベルでスロークエリログの保持期間を変更できます。

ALTER DATABASE <db_name> SET hg_query_log_retention_time_sec = 2592000;

スロークエリログのエクスポート

hg_query_log から Hologres の内部テーブル、MaxCompute の外部テーブル、または OSS にデータをエクスポートし、長期的な保存や分析に利用します。

エクスポート前の注意点：

• INSERT INTO ... SELECT ... FROM hologres.hg_query_log コマンドを実行するアカウントは、hg_query_log へのアクセス権を持つ必要があります。インスタンス全体をエクスポートするには、スーパーユーザーまたは pg_read_all_stats の権限が必要です。そうでない場合、エクスポートされたデータは不完全になります。

• query_start はインデックス列です。パフォーマンスを向上させ、リソース使用量を削減するために、常に WHERE 句に含めてください。

• WHERE 句で query_start に関数を適用しないでください。これにより、インデックスが使用されなくなります。

  -- 正解例：query_start に直接範囲条件を使用します
  WHERE query_start >= '2022-08-03' AND query_start < '2022-08-04'
  
  -- 不正解例：query_start を関数でラップすると、インデックスがバイパスされます
  WHERE to_char(query_start, 'yyyymmdd') = '20220101'

-- ステップ 1：ターゲットテーブルの作成
CREATE TABLE query_log_download (
    usename text,
    status text,
    query_id text,
    datname text,
    command_tag text,
    duration integer,
    message text,
    query_start timestamp with time zone,
    query_date text,
    query text,
    result_rows bigint,
    result_bytes bigint,
    read_rows bigint,
    read_bytes bigint,
    affected_rows bigint,
    affected_bytes bigint,
    memory_bytes bigint,
    shuffle_bytes bigint,
    cpu_time_ms bigint,
    physical_reads bigint,
    pid integer,
    application_name text,
    engine_type text[],
    client_addr text,
    table_write text,
    table_read text[],
    session_id text,
    session_start timestamp with time zone,
    trans_id text,
    command_id text,
    optimization_cost integer,
    start_query_cost integer,
    get_next_cost integer,
    extended_cost text,
    plan text,
    statistics text,
    visualization_info text,
    query_detail text,
    query_extinfo text[]
);

-- ステップ 2：特定の日付のログをエクスポート
INSERT INTO query_log_download
SELECT
    usename, status, query_id, datname, command_tag, duration, message,
    query_start, query_date, query, result_rows, result_bytes, read_rows,
    read_bytes, affected_rows, affected_bytes, memory_bytes, shuffle_bytes,
    cpu_time_ms, physical_reads, pid, application_name, engine_type,
    client_addr, table_write, table_read, session_id, session_start,
    trans_id, command_id, optimization_cost, start_query_cost, get_next_cost,
    extended_cost, plan, statistics, visualization_info, query_detail, query_extinfo
FROM hologres.hg_query_log
WHERE query_start >= '2022-08-03'
  AND query_start < '2022-08-04';

よくある質問

Hologres V1.1 で、返却行数と読み取り行数が表示されません。

これは、V1.1 の一部のバージョンでは、スロークエリログの収集が不完全なために発生します。V1.1.36～V1.1.49 では、次の GUC パラメーターを有効にして、完全な実行統計を収集してください。

-- データベースレベル (推奨：データベースごとに 1 回設定)
ALTER DATABASE <db_name> SET hg_experimental_force_sync_collect_execution_statistics = ON;

-- セッションレベル
SET hg_experimental_force_sync_collect_execution_statistics = ON;

<db_name> をお使いのデータベース名に置き換えてください。

インスタンスのバージョンが V1.1.36 より前の場合は、「Common upgrade preparation errors」を参照するか、Hologres サポートにお問い合わせください。詳細については、「How do I get more online support?」をご参照ください。

この動作は、V1.1.49 以降ではデフォルトで解消されています。

スロークエリログの期間にはフェッチ時間が含まれますか。

いいえ。Hologres のスロークエリログの duration フィールドは、サーバー側の実行時間のみを測定します。これは、プラン生成 (optimization_cost)、起動 (start_query_cost)、計算 (get_next_cost) で構成されます。クライアントが結果データをフェッチする時間 (フェッチフェーズ) は含まれません。

Quick BI などの BI ツールからのクエリが、同じ SQL ステートメントを HoloWeb またはコマンドラインで実行した場合よりも大幅に時間がかかる場合、一般的な原因は次のとおりです。

• BI ツールが複数のクエリを同時に送信するため、並列性が高くなり全体の応答時間が増加します。

• get_next_cost フィールドには、結果データをサーバーからクライアントに送信するためのネットワーク転送時間が含まれます。get_next_cost の値が大きい場合、サーバー側の計算が遅いのではなく、クライアント側のデータ取得レイテンシーを反映している可能性があります。

サーバー側とクライアント側の遅延を切り分けるには、EXPLAIN ANALYZE を使用してクエリを実行し、get_next_cost フィールドを確認してください。get_next_cost が高く、optimization_cost と start_query_cost が低い場合、通常はクエリ実行ではなくデータ転送に時間が費やされていることを示します。

次のステップ

インスタンス内のアクティブなクエリを監視および管理するには、「Manage queries」をご参照ください。