Hologres：Lihat dan analisis log kueri lambat

Batasan berikut berlaku saat Anda mengkueri log kueri lambat di Hologres:

• Log kueri lambat disimpan selama satu bulan secara default. Anda dapat mengkueri data dari periode waktu apa pun dalam rentang satu bulan tersebut.

• Untuk memastikan stabilitas sistem dan mencegah kelebihan trafik, satu kueri dapat mengembalikan maksimal 10.000 log kueri lambat. Beberapa bidang dalam log kueri lambat memiliki batas panjang. Untuk informasi selengkapnya, lihat deskripsi bidang untuk tabel query_log.

• Log kueri lambat merupakan bagian dari gudang metadata Hologres. Pencarian log kueri lambat yang gagal tidak memengaruhi kueri bisnis di instans Anda. Oleh karena itu, stabilitas log kueri lambat tidak dicakup oleh Service-Level Agreement (SLA) produk.

Hologres menyimpan log kueri lambat di tabel sistem hologres.hg_query_log. Tabel hg_query_log hanya mencatat pernyataan SQL yang telah selesai. Kueri yang masih berjalan tidak ditulis ke tabel ini. Perilaku ini konsisten di seluruh versi Hologres V2, V3, dan versi selanjutnya. Selain itu:

• Setelah Anda meningkatkan instans ke V0.10, Hologres secara default mengumpulkan log untuk kueri DML lambat yang berjalan lebih dari 100 ms dan semua operasi DDL.

• Mulai dari V3.0.2, Hologres mendukung catatan agregasi untuk operasi DML dan kueri yang berjalan kurang dari 100 ms di tabel hologres.hg_query_log.

  • Sistem mengagregasi catatan untuk kueri DQL dan DML yang berhasil yang memiliki sidik jari dan berjalan kurang dari 100 ms.

  • Kolom utama untuk agregasi adalah server_addr, usename, datname, warehouse_id, application_name, dan digest.

  • Setiap koneksi merangkum dan melaporkan data sekali per menit.

Tabel berikut menjelaskan bidang-bidang dalam tabel sistem hologres.hg_query_log.

Anda dapat menggunakan HoloWeb untuk melihat log kueri lambat.

Anda dapat mengkueri tabel hologres.hg_query_log untuk mengambil log kueri lambat. Bagian berikut menyediakan pernyataan SQL umum untuk mendiagnosis log kueri:

• Kueri jumlah total kueri dalam query_log

• Kueri jumlah kueri lambat untuk setiap pengguna

• Kueri detail kueri lambat tertentu

• Kueri kueri konsumsi tinggi dari 10 menit terakhir

• Lihat volume kueri dan total data yang dibaca per jam selama 3 jam terakhir

• Lihat volume akses data selama 3 jam terakhir dibandingkan dengan waktu yang sama kemarin

• Kueri kueri dengan durasi tinggi di setiap tahap dari 10 menit terakhir

• Kueri pertama yang gagal

• Kueri jumlah total kueri dalam query_log (default data dari bulan terakhir).

  SELECT count(*) FROM hologres.hg_query_log;

  Hasil berikut menunjukkan bahwa 44 kueri dengan durasi lebih besar dari ambang batas yang ditentukan dieksekusi dalam bulan terakhir.

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

• Kueri jumlah kueri lambat untuk setiap pengguna.

  SELECT usename AS "User",
         count(1) as "Query Count"
  FROM hologres.hg_query_log
  GROUP BY usename
  order by count(1) desc;

  Hasil berikut dikembalikan. Satuan untuk count(1) adalah jumlah kueri.

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

• Kueri detail kueri lambat tertentu.

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

  Hasil berikut dikembalikan. Untuk informasi selengkapnya tentang parameter, lihat Tabel 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)

• Kueri kueri konsumsi tinggi dari periode waktu terbaru, seperti 10 menit terakhir. Anda juga dapat mengubah periode waktu untuk mengkueri kueri konsumsi tinggi untuk durasi tertentu sesuai kebutuhan.

  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;

  Hasil berikut dikembalikan:

  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)

• Lihat jumlah kueri baru dari kemarin.

  • Hitung jumlah total kueri baru dari kemarin.

    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;

    Hasil berikut menunjukkan bahwa total 10 kueri baru ditambahkan kemarin.

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

  • Grup dan hitung jumlah kueri baru dari kemarin berdasarkan jenis kueri (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;

    Hasil berikut menunjukkan bahwa 8 kueri INSERT baru dan 2 kueri SELECT baru ditambahkan kemarin.

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

• Lihat detail kueri baru dari kemarin.

  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; 

  Hasil berikut dikembalikan:

  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)

• Lihat tren kueri baru dari kemarin (ditampilkan per jam).

  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; 

  Hasil berikut menunjukkan bahwa pada pukul 11.00, 13.00, dan 21.00 kemarin, masing-masing ditambahkan 1 kueri SELECT, 1 kueri SELECT, dan 8 kueri INSERT.

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

• Jumlah kueri lambat yang dikategorikan.

  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;

• Kueri 10 kueri teratas dengan waktu CPU rata-rata tertinggi dalam satu hari terakhir.

  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;

• Lihat 10 kueri teratas dengan konsumsi memori rata-rata tertinggi (memory_bytes) dalam satu minggu terakhir.

  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;

• Lihat volume kueri dan total data yang dibaca per jam selama 3 jam terakhir untuk memeriksa perubahan volume data.

  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;

• Lihat volume akses data selama 3 jam terakhir dibandingkan dengan waktu yang sama kemarin untuk memeriksa perubahan volume akses data.

  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;

• Kueri kueri dengan durasi tinggi di setiap tahap dari periode waktu terbaru, seperti 10 menit terakhir. Anda juga dapat mengubah periode waktu untuk mengkueri kueri dengan durasi tinggi di setiap tahap untuk durasi tertentu sesuai kebutuhan.

  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;

  Hasil berikut dikembalikan:

  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)

• Kueri pertama yang gagal.

  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;

  Hasil berikut dikembalikan:

  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)