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

Hologres でスロークエリのログをクエリする場合は、次の項目に注意してください。

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

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

• スロークエリのログは、Hologres のメタデータ ウェアハウス システムに属します。 スロークエリのログのクエリに失敗しても、インスタンスでのクエリに悪影響はありません。 したがって、スロークエリのログの安定性は、Hologres のサービスレベル契約（SLA）では規定されていません。

Hologres のスロークエリのログは、hologres.hg_query_log システム テーブルに保存されます。

• Hologres V0.10 以降では、Hologres は実行時間が 100 ミリ秒を超えるデータ操作言語（DML）クエリのログと、すべての DDL 文のログを収集します。

• Hologres V3.0.2 以降では、Hologres は 100 ミリ秒未満を消費する DML およびデータクエリ言語（DQL）クエリのログも収集および集計します。

  • Hologres は、SQL フィンガープリントを持ち、100 ミリ秒未満を消費する、正常に実行された DQL および DML クエリのログを収集および集計します。

  • ほとんどの場合、Hologres は server_addr、usename、datname、warehouse_id、application_name、および digest フィールドの値を集計します。

  • Hologres は、接続ごとに 1 分ごとにフィールド値を集計して報告します。

次の表に、hologres.hg_query_log システム テーブルに含まれるフィールドを示します。

HoloWeb コンソールでスロークエリのログを視覚的にクエリできます。

hologres.hg_query_log テーブルをクエリすることで、スロークエリのログを取得できます。 このセクションでは、スロークエリのログを分析するためによく使用される SQL 文について説明します。 次の操作を実行できます。

• スロークエリの総数をクエリする。

• 各ユーザーが開始したスロークエリの数をクエリする。

• 指定されたスロークエリの詳細をクエリする。

• 過去 10 分間で最も時間がかかったスロークエリをクエリする。

• 過去 3 時間のそれぞれで開始されたスロークエリのアクセス量とデータ読み取り量をクエリする。

• 過去 3 時間のデータアクセス量と比較のために前日の同じ期間のデータアクセス量をクエリする。

• 過去 10 分間で異なるクエリ ステージで最も時間がかかったスロークエリをクエリする。

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

• 次の文を実行して、スロークエリの総数をクエリします。 デフォルトでは、前月のスロークエリの数が返されます。

  SELECT count(*) FROM hologres.hg_query_log;

  次の結果が返されます。 結果は、実行時間が指定されたしきい値を超えた 44 件のクエリが前月に開始されたことを示しています。

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

• 次の文を実行して、各ユーザーが開始したスロークエリの数をクエリします。

  SELECT usename AS "ユーザー",
         count(1) as "スロークエリの件数"
  FROM hologres.hg_query_log
  GROUP BY usename
  order by count(1) desc;

  次の結果が返されます。 count(1) 関数によって返される値は、各ユーザーが開始したスロークエリの数を示します。

  ユーザー                   | スロークエリの件数
  -----------------------+-----
   1111111111111111      |  27
   2222222222222222      |  11
   3333333333333333      |   4
   4444444444444444      |   2
  (4 rows)

• 次の文を実行して、指定されたスロークエリの詳細をクエリします。

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

  次の結果が返されます。 フィールドの詳細については、このトピックの hologres.hg_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 "ステータス",
         duration AS "消費時間（ms）",
         query_start AS "開始時刻",
         (read_bytes/1048576)::text || ' MB' AS "読み取りバイト数",
         (memory_bytes/1048576)::text || ' MB' AS "メモリ",
         (shuffle_bytes/1048576)::text || ' MB' AS "シャッフル",
         (cpu_time_ms/1000)::text || ' s' AS "CPU 時間",
         physical_reads as "物理読み取り",
         query_id as "クエリ 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;

  次の結果が返されます。

  ステータス     |消費時間（ms） |    開始時刻            | 読み取りバイト数 | メモリ  | シャッフル | CPU 時間 | 物理読み取り |      クエリ ID       |             クエリ
  ---------+---------+------------------------+--------+-------+---------+---------+------+--------------------+--------------------------------
   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 時間目に 1 件の SELECT クエリが開始され、13 時間目に別の SELECT クエリが開始され、21 時間目に 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;

• 次の文を実行して、前日に最大の 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;

• 次の文を実行して、前週で最大のメモリ リソースを占有した上位 10 件のクエリをクエリします。 メモリは memory_bytes によって指定されます。

  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 時間のそれぞれで開始されたスロークエリのアクセス量とデータ読み取り量をクエリします。 これにより、各時間のデータ量の変更を判断できます。

  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 "ステータス",
      duration AS "消費時間（ms）",
      optimization_cost AS "最適化時間（ms）",
      start_query_cost AS "起動時間（ms）",
      get_next_cost AS "実行時間（ms）",
      duration - optimization_cost - start_query_cost - get_next_cost AS "その他（ms）",
      query_id AS "クエリ 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;

  次の結果が返されます。

  ステータス     | 消費時間（ms） | 最適化時間（ms） | 起動時間（ms） | 実行時間（ms） | その他（ms） |      クエリ ID       |             クエリ
  ---------+----------+--------------+--------------+--------------+--------------+--------------------+--------------------------------
   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 "ステータス",
      regexp_replace(message, '\n', ' ')::char(150) AS "エラーメッセージ",
      duration AS "消費時間（ms）",
      query_start AS "開始時刻",
      query_id AS "クエリ ID",
      query::char(100) AS "クエリ"
  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;

  次の結果が返されます。

  ステータス    |                                                                     エラーメッセージ                                                                           | 消費時間（ms）  |        開始時刻        |     クエリ ID       | クエリ
  --------+--------------------------------------------------------------------------------------------------------------------------------------------------------+-------+------------------------+-------------------+-------
   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)