Hologres:スロークエリログの表示と分析

Hologres でスロークエリログをクエリする際には、次の制限が適用されます：

• スロークエリログはデフォルトで 1 か月間保持されます。その月内の任意の期間のデータをクエリできます。

• システムの安定性を確保し、トラフィックの過負荷を防ぐため、1 回のクエリで最大 10,000 件のスロークエリログを返すことができます。スロークエリログの一部のフィールドには長さの制限があります。詳細については、query_log テーブルのフィールド説明をご参照ください。

• スロークエリログは Hologres メタデータウェアハウスの一部です。スロークエリログの検索が失敗しても、インスタンス内のビジネスクエリには影響しません。したがって、スロークエリログの安定性は、製品のサービスレベルアグリーメント (SLA) の対象外です。

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

• インスタンスを V0.10 にアップグレードすると、Hologres はデフォルトで 100 ms を超えて実行される低速な DML クエリとすべての DDL 操作のログを収集します。

• V3.0.2 以降、Hologres は hologres.hg_query_log テーブルで 100 ms 未満で実行される DML およびクエリ操作の集計レコードをサポートします。

  • システムは、指紋を持ち、100 ms 未満で実行される成功した DQL および DML クエリのレコードを集計します。

  • 集計の主な列は、server_addr、usename、datname、warehouse_id、application_name、および digest です。

  • 各接続は、1 分に 1 回データを要約して報告します。

次の表は、hologres.hg_query_log システムテーブルのフィールドについて説明しています。

HoloWeb を使用してスロークエリログを表示できます。

hologres.hg_query_log テーブルをクエリして、スロークエリログを取得できます。以下のセクションでは、クエリログを診断するための一般的な SQL ステートメントを提供します：

• query_log 内のクエリの総数をクエリする

• 各ユーザーのスロークエリ数をクエリする

• 特定のスロークエリの詳細をクエリする

• 過去 10 分間の高消費クエリをクエリする

• 過去 3 時間の 1 時間あたりのクエリ量と合計データ読み取り量を表示する

• 過去 3 時間のデータアクセス量を昨日の同時刻と比較して表示する

• 過去10分間の各ステージで実行時間の長いクエリを照会する

• 最初に失敗したクエリをクエリする

• query_log 内のクエリの総数をクエリします (デフォルトは過去 1 か月間のデータ)。

  SELECT count(*) FROM hologres.hg_query_log;

  次の結果は、過去 1 か月間に指定されたしきい値を超える期間で 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;

  次の結果が返されます。count(1) の単位はクエリ数です。

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

• 特定のスロークエリの詳細をクエリします。

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

  次の結果が返されます。パラメーターの詳細については、「query_log テーブル」をご参照ください。

         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      | command_id | optimization_cost | start_query_cost | get_next_cost | extended_cost | plan | statistics | visualization_info | query_detail | query_extinfo
  -----------------------+---------+--------------------+---------+-------------+----------+---------+------------------------+------------+---------------------------------------------------------------------------------------------------------+-------------+--------------+-----------+------------+---------------+----------------+--------------+---------------+-------------+----------------+---------+------------------+-------------+---------------+-------------+------------+-----------------+------------------------+------------+-------------------+------------------+---------------+---------------+------+------------+--------------------+--------------+---------------
   p4_11111111111xxxx | SUCCESS | 13001450118416xxxx | dbname | SELECT      |      149 |         | 2021-03-30 23:45:01+08 | 20210330   | explain analyze SELECT  * FROM tablename WHERE user_id = '20210330010xxxx' limit 1000;             |        1000 |       417172 |         0 |         0 |            -1 |             -1 |     26731376 |     476603616 |      321626 |              0 | 1984913 | psql             | {HQE}      | 33.41.xxx.xxx |             |            | 6063475a.1e4991 | 2021-03-30 23:44:26+08 | 0          |                58 |               22 |            67 |               |      |            |                    |              |
  (1 row)

• 最近の期間 (たとえば過去 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 "QueryID",
         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 |      QueryID       |             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)

• 昨日の新規クエリ数を表示します。

  • 昨日の新規クエリの総数をカウントします。

    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)

  • クエリタイプ (command_tag) 別に昨日の新規クエリ数をグループ化してカウントします。

    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;

    次の結果は、昨日 8 件の新規 INSERT クエリと 2 件の新規 SELECT クエリが追加されたことを示します。

    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; 

  次の結果が返されます：

  usename	         |status  |query_id	           |digest	                            |datname|command_tag	|query	                            |cpu_time_ms   |memory_bytes
  -----------------+--------+--------------------+------------------------------------+-------+-------------+-----------------------------------+--------------+--------------
  111111111111xxxx |SUCCESS |100100425827776xxxx |md58cf93d91c36c6bc9998add971458ba1a |dbname	|INSERT	      |INSERT INTO xxx SELECT * FROM xxx  | 	   		 1748|	   898808596
  111111111111xxxx |SUCCESS |100100425827965xxxx |md5f7e87e2c9e0b3d9eddcd6b3bc7f04b3b |dbname	|INSERT       |INSERT INTO xxx SELECT * FROM xxx  | 	   		59891|	  6819529886
  111111111111xxxx |SUCCESS |100100425829654xxxx |md55612dc09d2d81074fd5deed1aa3eca9b |dbname	|INSERT	      |INSERT INTO xxx SELECT * FROM xxx  |   	   		  3|	     2100039
  111111111111xxxx |SUCCESS |100100425829664xxxx |md58d3bf67fbdf2247559bc916586d40011 |dbname	|INSERT	      |INSERT INTO xxx SELECT * FROM xxx  |     		10729|	  2052861937
  111111111111xxxx |SUCCESS |100100425830099xxxx |md503bd45d6b2d7701c2617d079b4d55a10 |dbname	|INSERT	      |INSERT INTO xxx SELECT * FROM xxx  |	   		   2196|     897948034
  111111111111xxxx |SUCCESS |100100425830186xxxx |md5c62169eaf3ea3a0c59bdc834a8141ac4 |dbname	|INSERT	      |INSERT INTO xxx SELECT * FROM xxx  |	   		   5268|    1734305972
  111111111111xxxx |SUCCESS |100100425830448xxxx |md59aa0c73b24c9c9eba0b34c8fdfc23bb0 |dbname	|INSERT	      |INSERT INTO xxx SELECT * FROM xxx  |	   		      2|       2098402
  111111111111xxxx |SUCCESS |100100425830459xxxx |md57d22c1d37b68984e9472f11a4c9fd04e |dbname	|INSERT	      |INSERT INTO xxx SELECT * FROM xxx  |	   		    113|      76201984
  111111111111xxxx |SUCCESS |100100525468694xxxx |md5ac7d6556fae123e9ea9527d8f1c94b1c |dbname	|SELECT	      |SELECT * FROM xxx limit 200	      |     		    6|	     1048576
  111111111111xxxx |SUCCESS |100101025538840xxxx |md547d09cdad4d5b5da74abaf08cba79ca0 |dbname	|SELECT	      |SELECT * FROM xxx limit 200	      |\N	           |\N        
  (10 rows)

• 昨日の新規クエリの傾向を表示します (時間別に表示)。

  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; 

  次の結果は、昨日の 11:00、13:00、21:00 にそれぞれ 1 件の SELECT、1 件の SELECT、8 件の INSERT クエリが追加されたことを示します。

  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;

• 過去 1 日間で平均 CPU 時間が最も高い上位 10 件のクエリをクエリします。

  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;

• 過去 1 週間で平均メモリ消費量 (memory_bytes) が最も高い上位 10 件のクエリを表示します。

  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;

• 過去 3 時間の 1 時間あたりのクエリ量と合計データ読み取り量を表示して、データ量の変化を確認します。

  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;

• 過去 3 時間のデータアクセス量を昨日の同時刻と比較して、データアクセス量の変化を確認します。

  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;

• 最近の期間 (たとえば過去 10 分間) の各ステージで実行時間が長いクエリをクエリします。必要に応じて、特定の期間の各ステージで実行時間が長いクエリをクエリするために期間を変更することもできます。

  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 "QueryID",
      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) |      QueryID       |             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)

• 最初に失敗したクエリをクエリします。

  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 "QueryID",
      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        |     QueryID       | Query
  --------+--------------------------------------------------------------------------------------------------------------------------------------------------------+-------+------------------------+-------------------+-------
   FAILED | Query:[1070285448673xxxx] code: kActorInvokeError msg: "[holo_query_executor.cc:330 operator()] HGERR_code XX000 HGERR_msge internal error: status { c |  1460 | 2021-03-25 17:28:54+08 | 1070285448673xxxx | S...
   FAILED | Query:[1016285560553xxxx] code: kActorInvokeError msg: "[holo_query_executor.cc:330 operator()] HGERR_code XX000 HGERR_msge internal error: status { c |   131 | 2021-03-25 17:28:55+08 | 1016285560553xxxx | S...
  (2 rows)