Hologres：慢Query日誌查看與分析

在Hologres中查詢慢Query日誌，具體限制如下：

• 慢Query日誌預設保留一個月的資料，但是HoloWeb僅支援查最近7天的資料，如果需要查詢一個月內的資料請使用SQL進行查詢。

• 為了保證系統穩定性，避免流量超載，單次查詢最多返回10000條慢Query日誌。慢Query日誌中的部分欄位有長度限制，詳情請參見query_log表欄位說明。

• 慢Query日誌屬於Hologres的元倉系統，慢Query日誌查詢失敗不會影響執行個體中的業務Query運行，故慢Query日誌的穩定性不在產品的SLA保護範圍內。

Hologres的慢Query查詢日誌儲存於hologres.hg_query_log系統資料表中，其中：

• 在執行個體升級至V0.10版本後，將會預設採集執行時間大於100 ms的慢DML Query以及所有的DDL操作。

• 自V3.0.2版本開始，支援在原有的hologres.hg_query_log中，使用彙總方式記錄執行時間小於100 ms的DML和查詢的記錄。

  • 系統會將執行時間小於100 ms，成功且有指紋的Query（DQL和DML）操作進行彙總記錄。

  • 彙總的主要列為：server_addr、usename、datname、warehouse_id、application_name、digest。

  • 每個串連每分鐘會匯總一次後上報。

hologres.hg_query_log系統資料表，包含的欄位資訊介紹如下。

您可以通過HoloWeb可視化查看慢Query日誌。

您可以通過查詢hologres.hg_query_log表，擷取慢Query日誌。如下將為您介紹進行Query日誌診斷常用的固定SQL語句。主要包括：

• 查詢query_log總查詢數

• 查詢每個使用者的慢Query情況

• 查詢某個慢Query的具體資訊

• 查詢最近10分鐘消耗比較高的Query

• 查看最近3小時內每小時的Query訪問量和資料讀取總量

• 查看與昨天同一時間對比過去3小時的資料訪問量情況

• 查詢最近10分鐘Query各階段耗時比較高的Query

• 查詢最先失敗的Query

• 查詢query_log總查詢數（預設為近1個月內的資料）。

  SELECT count(*) FROM hologres.hg_query_log;

  執行結果如下，表示近1個月內總共執行了44個耗時大於指定閾值的Query。

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

• 查詢每個使用者的慢Query個數。

  SELECT usename AS "使用者",
         count(1) as "Query個數"
  FROM hologres.hg_query_log
  GROUP BY usename
  order by count(1) desc;

  執行結果如下，其中count(1)的單位是個數。

  使用者                   | Query個數
  -----------------------+-----
   1111111111111111      |  27
   2222222222222222      |  11
   3333333333333333      |   4
   4444444444444444      |   2
  (4 rows)

• 查詢某個慢Query的具體資訊。

  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分鐘）消耗比較高的Query。您也可以根據業務需求修改具體時間，查詢目標時間段消耗比較高的Query。

  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 "Shuffle",
         (cpu_time_ms/1000)::text || ' s' AS "CPU時間",
         physical_reads as "讀盤",
         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;

  執行結果如下：

  狀態     |耗時(ms) |    開始時間            | 讀取量 | 記憶體  | Shuffle | CPU時間 | 讀盤 |      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)

• 查看昨日新增的Query數量。

  • 統計昨日新增的Query總量。

    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;

    執行結果如下，表示昨日新增Query總量為10個。

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

  • 按照查詢的類型（command_tag）分組統計昨日新增的Query數量。

    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類型的Query。

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

• 查看昨日新增的Query明細。

  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)

• 查看昨日新增的Query趨勢（按小時展示）。

  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時、13時、21時分別新增了1個SELECT、1個SELECT、8個INSERT類型的Query。

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

• 歸類慢Query的次數。

  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平均耗時前十的Query。

  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;

• 查看過去一周記憶體（memory_bytes）平均消耗量前十的Query。

  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小時內每小時的Query訪問量和資料讀取總量，用於對比判斷每個小時是否有資料量變化。

  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分鐘）Query各階段耗時比較高的Query。您也可以根據業務需求修改具體時間，查詢目標時間段Query各階段耗時比較高的Query。

  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 "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;

  執行結果如下：

  狀態     | 耗時(ms) | 最佳化耗時(ms) | 啟動耗時(ms) | 執行耗時(ms) | 其他耗時(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)

• 查詢最先失敗的Query。

  SELECT
      status AS "狀態",
      regexp_replace(message, '\n', ' ')::char(150) AS "報錯資訊",
      duration AS "耗時(ms)",
      query_start AS "開始時間",
      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;

  執行結果如下：

  狀態    |                                                                     報錯資訊                                                                           | 耗時(ms)  |        開始時間        |     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)