Hologres:Query and analyze slow query logs

Take note of the following items when you query slow query logs in Hologres:

• By default, the slow query logs of the last month are retained. However, HoloWeb allows you to query only the slow query logs of the last seven days. To query earlier slow query logs, execute SQL statements.

• To ensure system stability and prevent traffic overloads, a maximum of 10,000 slow query logs are returned from the server for each query. The length of some fields in slow query logs is limited. For more information, see field descriptions in the hologres.hg_query_log table.

• Slow query logs belong to the metadata warehouse system of Hologres. Failure in querying slow query logs does not negatively affect queries in instances. Therefore, the stability of slow query logs is not specified in the service-level agreement (SLA) of Hologres.

Slow query logs of Hologres are stored in the hologres.hg_query_log system table.

• In Hologres V0.10 and later, Hologres collects the logs of data manipulation language (DML) queries whose execution time is longer than 100 ms and the logs of all DDL statements.

• In Hologres V3.0.2 and later, Hologres also collects and aggregates the logs of DML and data query language (DQL) queries that consume less than 100 ms.

  • Hologres collects and aggregates the logs of successfully executed DQL and DML queries that have SQL fingerprints and consume less than 100 ms.

  • In most cases, Hologres aggregates values of the following fields: server_addr, usename, datname, warehouse_id, application_name, and digest.

  • Hologres aggregates and reports field values every minute for each connection.

The following table describes the fields that are contained in the hologres.hg_query_log system table.

You can query slow query logs in the HoloWeb console in a visualized manner.

You can obtain slow query logs by querying the hologres.hg_query_log table. This section describes the SQL statements that are commonly used to analyze slow query logs. You can perform the following operations:

• Query the total number of slow queries

• Query the number of slow queries initiated by each user.

• Query the details of a specified slow query.

• Query the slow queries that are most time-consuming in the last 10 minutes.

• Query the access amount and data read amount of slow queries initiated in each of the last 3 hours.

• Query the data access amount of slow queries in the past 3 hours and that in the same period on the previous day for comparison.

• Query the slow queries that are most time-consuming at different query stages in the last 10 minutes.

• Query the first failed queries

• Execute the following statement to query the total number of slow queries. By default, the number of slow queries for the previous month is returned.

  SELECT count(*) FROM hologres.hg_query_log;

  The following result is returned. The result indicates that 44 queries whose execution time exceeds the specified threshold were initiated in the previous month.

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

• Execute the following statement to query the number of slow queries initiated by each user:

  SELECT usename AS "User",
         count(1) as "Number of slow queries"
  FROM hologres.hg_query_log
  GROUP BY usename
  order by count(1) desc;

  The following result is returned. The value returned by the count(1) function indicates the number of slow queries initiated by each user.

  User                   | Number of slow queries
  -----------------------+-----
   1111111111111111      |  27
   2222222222222222      |  11
   3333333333333333      |   4
   4444444444444444      |   2
  (4 rows)

• Execute the following statement to query the details of a specified slow query:

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

  The following result is returned. For more information about the fields, see Query the hologres.hg_query_log table in this topic.

         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)

• Execute the following statement to query the slow queries that are most time-consuming in a recent time range, such as the last 10 minutes. You can specify a time range based on your business requirements.

  SELECT status AS "Status",
         duration AS "Time consumed (ms)",
         query_start AS "Started at",
         (read_bytes/1048576)::text || ' MB' AS "Read bytes",
         (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 "Physical 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;

  The following result is returned:

  Status     |Time consumed (ms) |    Started at            | Megabytes read | Memory  | Shuffle | CPU time | Physical 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)

• Query the number of queries that were initiated on the previous day.

  • Execute the following statement to query the total number of queries that were initiated on the previous day:

    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;

    The following result indicates that a total of 10 queries were initiated on the previous day.

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

  • Execute the following statement to query the number of each type of queries that were initiated on the previous day. The query type is specified by 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;

    The following result indicates that eight INSERT queries and two SELECT queries were initiated on the previous day.

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

• Execute the following statement to query details of queries that were initiated on the previous day:

  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; 

  The following result is returned:

  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)

• Execute the following statement to query the trend of queries that were initiated in each hour of the previous day.

  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; 

  The following result indicates that one SELECT query was initiated in the 11th hour, another SELECT query was initiated in the 13th hour, and eight INSERT queries were initiated in the 21st hour on the previous day.

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

• Execute the following statement to classify slow queries:

  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;

• Execute the following statement to query the top 10 queries that generate the largest CPU overheads on the previous day:

  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;

• Execute the following statement to query the top 10 queries that occupy the largest memory resources in the previous week. The memory is specified by 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;

• Execute the following statement to query the access amount and data read amount of slow queries initiated in each of the last 3 hours. This helps determine whether the data amount changes in each hour.

  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;

• Execute the following statement to query the data access amount of slow queries in the past 3 hours and that in the same period on the previous day for comparison. This helps determine whether the data access amount changes compared with that in the same period on the previous day.

  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;

• Execute the following statement to query the slow queries that are most time-consuming at different query stages in a recent time range, such as the last 10 minutes. You can specify a time range based on your business requirements.

  SELECT
      status AS "Status",
      duration AS "Time consumed (ms)",
      optimization_cost AS "Optimization time (ms)",
      start_query_cost AS "Startup time (ms)",
      get_next_cost AS "Execution duration (ms)",
      duration - optimization_cost - start_query_cost - get_next_cost AS "Others (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;

  The following result is returned:

  Status     | Time consumed (ms) | Optimization duration (ms) | Startup duration (ms) | Execution duration (ms) | Others (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)

• Execute the following statement to query the first failed queries:

  SELECT
      status AS "Status",
      regexp_replace(message, '\n', ' ')::char(150) AS "Error message",
      duration AS "Time consumed (ms)",
      query_start AS "Started at",
      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;

  The following result is returned:

  Status    |                                                                     Error message                                                                           | Time consumed (ms)  |        Started at        |     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)