Hologres：Lihat dan analisis log kueri lambat

Kueri terhadap log kueri lambat di Hologres tunduk pada batasan berikut:

• Secara default, log kueri lambat menyimpan data selama satu bulan. Anda dapat mengkueri data dari periode apa pun dalam satu bulan terakhir.

• Untuk memastikan stabilitas sistem dan mencegah kelebihan trafik, satu kueri mengembalikan maksimal 10.000 entri 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 sistem gudang metadata Hologres. Kegagalan dalam mengkueri log kueri lambat tidak memengaruhi kueri bisnis yang sedang berjalan 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. Secara spesifik:

• Setelah Anda meningkatkan instans ke V0.10 atau versi yang lebih baru, Hologres secara otomatis mengumpulkan kueri DML lambat yang memerlukan waktu lebih dari 100 ms dan semua operasi DDL.

• Mulai dari V3.0.2, Hologres mengagregasi catatan operasi DML dan kueri yang selesai dalam waktu kurang dari 100 ms dan menyimpannya di tabel hologres.hg_query_log yang sama.

  • Sistem mengagregasi kueri DQL dan DML yang berhasil dengan sidik jari yang sama dan selesai dalam waktu kurang dari 100 ms.

  • Kunci agregasi mencakup: server_addr, usename, datname, warehouse_id, application_name, dan digest.

  • Setiap koneksi melaporkan data agregasi sekali per menit.

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

Anda dapat melihat log kueri lambat secara visual di HoloWeb.

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

• Jumlah total kueri dalam query_log

• Kueri lambat per pengguna

• Detail kueri lambat tertentu

• Kueri sumber daya tinggi dalam 10 menit terakhir

• Volume kueri per jam dan total data yang dibaca dalam 3 jam terakhir

• Perbandingan akses data antara 3 jam terakhir dan periode yang sama kemarin

• Kueri dengan durasi spesifik fase tinggi dalam 10 menit terakhir

• Temukan kueri gagal pertama

• Jumlah total kueri dalam query_log (default: data bulan lalu)

  SELECT count(*) FROM hologres.hg_query_log;

  Contoh berikut menunjukkan output, yang mengindikasikan bahwa 44 kueri melebihi ambang batas dalam sebulan terakhir:

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

• Jumlah kueri lambat per pengguna

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

  Contoh berikut menunjukkan hasil eksekusi. Nilai count(1) adalah jumlah kueri.

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

• Detail kueri lambat tertentu

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

  Contoh berikut menunjukkan output. Untuk informasi selengkapnya tentang bidang, lihat View the query_log table.

         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 sumber daya tinggi dalam 10 menit terakhir (Anda dapat menyesuaikan rentang waktu 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;

  Contoh berikut menunjukkan output:

  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)

• Kueri baru dari kemarin

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

    Contoh berikut menunjukkan output, yang mengindikasikan bahwa ada 10 kueri baru:

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

  • Kueri baru dari kemarin dikelompokkan berdasarkan jenis (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)

• 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)

• Tren kueri baru dari kemarin (rincian 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 eksekusi menunjukkan bahwa satu kueri SELECT ditambahkan pada pukul 11:00, satu lagi pada pukul 13:00, dan delapan kueri INSERT ditambahkan pada pukul 21:00 kemarin.

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

• Jumlah kueri lambat berdasarkan kategori.

  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;

• 10 kueri teratas berdasarkan rata-rata waktu CPU dalam sehari 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;

• 10 kueri teratas berdasarkan rata-rata konsumsi memori dalam seminggu 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;

• Volume kueri per jam dan total data yang dibaca dalam 3 jam terakhir (untuk mendeteksi perubahan volume)

  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;

• Perbandingan akses data antara 3 jam terakhir dan periode yang sama kemarin (untuk mendeteksi perubahan pola akses)

  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 dengan durasi spesifik fase tinggi dalam 10 menit terakhir (Anda dapat menyesuaikan rentang waktu sesuai kebutuhan.)

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

  Contoh berikut menunjukkan output:

  Status   | Duration (ms)| Optimization (ms)| Startup (ms)| Execution (ms)| Other (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 gagal pertama

  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;

  Berikut ini menunjukkan hasil eksekusi:

  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)