Hologres:Mendapatkan dan menganalisis log kueri lambat

Panduan versi

Fitur ini memerlukan Hologres V0.10 atau yang lebih baru. Untuk memeriksa versi instans Anda, buka halaman detail instans di Konsol Hologres. Untuk meningkatkan instans versi sebelumnya, lihat Kesalahan umum persiapan peningkatan atau hubungi dukungan Hologres. Untuk informasi selengkapnya, lihat Bagaimana cara mendapatkan dukungan online tambahan?.

Batasan

• Log kueri lambat disimpan selama satu bulan secara default.

• Satu kueri mengembalikan maksimal 10.000 entri log kueri lambat. Beberapa bidang memiliki batas panjang — lihat deskripsi bidang di bagian tabel hg_query_log.

• Log kueri lambat merupakan bagian dari gudang metadata Hologres. Pencarian log kueri lambat yang gagal tidak memengaruhi kueri bisnis Anda, dan ketersediaan log tidak dicakup oleh Perjanjian Tingkat Layanan (SLA) Hologres.

Cara kerja

Hologres menyimpan log kueri lambat dalam tabel sistem `hologres.hg_query_log`. Tabel ini hanya mencatat pernyataan SQL yang telah selesai — kueri yang masih berjalan tidak ditulis ke dalam tabel. Perilaku ini konsisten di seluruh versi V2, V3, dan versi setelahnya.

Apa yang dicatat:

• Setelah Anda meningkatkan ke V0.10: kueri DML lambat yang berjalan lebih dari 100 ms, dan semua operasi DDL.

• Mulai dari V3.0.2: selain catatan rinci untuk kueri di atas 100 ms, catatan agregasi juga ditulis untuk kueri DQL dan DML yang selesai dalam waktu kurang dari 100 ms.

Cara kerja agregasi (V3.0.2+):

Untuk kueri cepat (di bawah 100 ms), sistem mengelompokkan kueri DQL dan DML yang berhasil dan memiliki sidik jari SQL (digest) yang sama. Kunci agregasi adalah: server_addr, usename, datname, warehouse_id, application_name, dan digest. Setiap koneksi mengirim satu catatan agregasi per menit.

Prasyarat

Untuk melihat log kueri lambat, Anda memerlukan salah satu izin berikut:

View logs for all databases in an instance:

• Superuser: Jalankan perintah berikut. Ganti ID akun Alibaba Cloud dengan username aktual. Untuk Pengguna RAM, gunakan p4_AccountID (ID akun, bukan nama Pengguna RAM).

  ALTER USER "ID akun Alibaba Cloud" SUPERUSER;

• Grup pg_read_all_stats (untuk non-superuser): Hubungi superuser untuk menambahkan Anda ke grup ini.

  -- Otorisasi PostgreSQL standar
  GRANT pg_read_all_stats TO "ID akun Alibaba Cloud";
  
  -- Model izin sederhana (SPM)
  CALL spm_grant('pg_read_all_stats', 'ID akun Alibaba Cloud');
  
  -- Model izin tingkat skema (SLPM)
  CALL slpm_grant('pg_read_all_stats', 'ID akun Alibaba Cloud');

View logs for current database only:

Aktifkan SPM atau SLPM dan tambahkan pengguna ke peran db_admin.

-- SPM
CALL spm_grant('<db_name>_admin', 'ID akun Alibaba Cloud');

-- SLPM
CALL slpm_grant('<db_name>.admin', 'ID akun Alibaba Cloud');

Pengguna biasa hanya dapat melihat kueri mereka sendiri di database saat ini, tanpa pengaturan tambahan.

Lihat log kueri lambat

Hologres menyediakan dua cara untuk melihat log kueri lambat. Gunakan HoloWeb untuk eksplorasi visual — gunakan SQL untuk filter kustom, rentang waktu, dan ekspor.

Sidik jari SQL

Mulai dari V2.2, kolom digest dalam hg_query_log menyimpan sidik jari SQL untuk setiap kueri. Untuk SELECT, INSERT, DELETE, dan UPDATE, Hologres menghitung hash MD5 sebagai sidik jari.

Kapan menggunakan `digest` vs `query_id`:

• Gunakan digest untuk mengelompokkan dan menganalisis kueri dengan pola yang sama — misalnya, untuk menemukan pola kueri mana yang paling banyak mengonsumsi CPU rata-rata.

• Gunakan query_id untuk melacak eksekusi kueri tertentu — misalnya, untuk mengambil detail lengkap dari kueri gagal tertentu.

Cara menghitung sidik jari:

• Sidik jari hanya dikumpulkan untuk SELECT, INSERT, DELETE, dan UPDATE.

• Spasi diabaikan (spasi, jeda baris, tab).

• Nilai konstan diabaikan: SELECT * FROM t WHERE a > 1 dan SELECT * FROM t WHERE a > 2 menghasilkan sidik jari yang sama.

• Jumlah elemen array diabaikan: WHERE a IN (1, 2) dan WHERE a IN (3, 4, 5) menghasilkan sidik jari yang sama.

• Untuk INSERT dengan data konstan, sidik jari tidak dipengaruhi oleh jumlah baris yang dimasukkan.

• Huruf besar/kecil mengikuti aturan kueri Hologres.

• Sidik jari mencakup nama database dan skema fully qualified, sehingga SELECT * FROM t dan SELECT * FROM public.t memiliki sidik jari yang sama hanya jika t berada di skema public dan kedua kueri merujuk ke tabel yang sama.

Diagnosa kueri

Contoh SQL berikut mencakup skenario diagnostik paling umum. Semua kueri menargetkan hologres.hg_query_log.

Hitung semua kueri dalam log (default: bulan lalu):

SELECT count(*) FROM hologres.hg_query_log;

Contoh output — 44 kueri lambat dalam sebulan terakhir:

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

Hitung 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 output:

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

Cari kueri tertentu berdasarkan ID:

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

Untuk deskripsi bidang yang dikembalikan, lihat Tabel hg_query_log.

Temukan kueri intensif sumber daya dalam 10 menit terakhir:

Sesuaikan interval agar sesuai dengan jendela waktu target Anda.

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

Contoh output:

 Status  | Duration (ms) |       Start time       | Data read | Memory | Shuffle | CPU time | Disk reads |       Query ID     |         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)

Skenario: Diagnosa penggunaan CPU atau memori tinggi setelah peningkatan versi instans

Kueri ini sangat berguna ketika penggunaan CPU atau memori melonjak setelah Anda meningkatkan instans Hologres ke versi baru. Untuk mengidentifikasi kueri yang menyebabkan konsumsi sumber daya tinggi:

1. Sesuaikan rentang waktu dalam klausa WHERE agar mencakup periode ketika penggunaan CPU atau memori tidak normal. Misalnya, ganti interval '10 min' dengan rentang yang sesuai dengan jendela lonjakan tersebut.

2. Tambahkan ORDER BY cpu_time_ms DESC untuk menemukan kueri intensif CPU, atau ORDER BY memory_bytes DESC untuk menemukan kueri intensif memori.

3. Periksa kolom query_id, usename, dan query dalam hasil untuk mengidentifikasi kueri spesifik dan pemiliknya, lalu analisis dan optimalkan kueri tersebut.

Rincian durasi berdasarkan tahap:

Gunakan ini untuk mengidentifikasi tahap mana (optimization_cost, start_query_cost, atau get_next_cost) yang paling banyak menyumbang keterlambatan. Lihat tabel rincian durasi di bagian tabel hg_query_log untuk detail setiap tahap.

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

Contoh output:

 Status  | Duration (ms) | Optimization cost (ms) | Startup cost (ms) | Execution cost (ms) | Other cost (ms) |       Query ID     |         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)

Lihat volume kueri dan data yang dibaca per jam (3 jam terakhir):

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;

Bandingkan trafik dengan jendela yang sama kemarin:

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;

Temukan kueri gagal pertama dalam jendela waktu:

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 "Query ID",
       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;

Contoh output:

 Status |                        Error message                        | Duration (ms) |       Start time       |      Query ID      | Query
--------+--------------------------------------------------------------+---------------+------------------------+--------------------+-------
 FAILED | Query:[1070285448673xxxx] code: kActorInvokeError msg: "..." |          1460 | 2021-03-25 17:28:54+08 | 1070285448673xxxx  | S...
 FAILED | Query:[1016285560553xxxx] code: kActorInvokeError msg: "..." |           131 | 2021-03-25 17:28:55+08 | 1016285560553xxxx  | S...
(2 rows)

Temukan pola kueri baru dari kemarin (jumlah total):

Kueri yang muncul untuk pertama kalinya dibandingkan dengan hari sebelum kemarin, dikelompokkan berdasarkan sidik jari.

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 output — 10 pola kueri baru kemarin:

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

Temukan pola kueri baru dari kemarin (berdasarkan jenis):

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;

Contoh output:

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

Temukan pola kueri baru dari kemarin (dengan detail):

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;

Temukan pola kueri baru dari kemarin (berdasarkan 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;

Contoh output — pada pukul 21:00 kemarin, 8 pola INSERT; pada pukul 11:00 dan 13:00, masing-masing 1 pola SELECT:

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

Hitung kueri lambat berdasarkan sidik jari (kemarin):

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;

Temukan 10 pola kueri dengan rata-rata waktu CPU tertinggi (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;

Temukan 10 pola kueri dengan rata-rata penggunaan memori tertinggi (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;

Parameter konfigurasi

Gunakan parameter GUC berikut untuk mengontrol apa yang dicatat dan seberapa detail informasi yang diambil.

-- Tingkat database (hanya superuser)
ALTER DATABASE dbname SET log_min_duration_statement = '250ms';

-- Tingkat sesi
SET log_min_duration_statement = '250ms';

-- Tingkat database (hanya superuser)
ALTER DATABASE dbname SET log_min_duration_query_stats = '20s';

-- Tingkat sesi
SET log_min_duration_query_stats = '20s';

-- Tingkat database (hanya superuser)
ALTER DATABASE dbname SET log_min_duration_query_plan = '10s';

-- Tingkat sesi
SET log_min_duration_query_plan = '10s';

Ubah retensi log

Mulai dari V3.0.27, Anda dapat mengubah berapa lama log kueri lambat disimpan di tingkat database.

ALTER DATABASE <db_name> SET hg_query_log_retention_time_sec = 2592000;

Ekspor log kueri lambat

Ekspor data dari hg_query_log ke tabel internal Hologres, tabel eksternal MaxCompute, atau OSS untuk penyimpanan atau analisis jangka panjang.

Sebelum mengekspor, perhatikan:

• Akun yang menjalankan perintah INSERT INTO ... SELECT ... FROM hologres.hg_query_log harus memiliki akses ke hg_query_log. Untuk ekspor seluruh instans, diperlukan izin superuser atau pg_read_all_stats — jika tidak, data yang diekspor akan tidak lengkap.

• query_start adalah kolom terindeks. Selalu sertakan dalam klausa WHERE Anda untuk meningkatkan performa dan mengurangi penggunaan sumber daya.

• Jangan menerapkan fungsi pada query_start dalam klausa WHERE — ini mencegah penggunaan indeks.

  -- Benar: gunakan kondisi rentang langsung pada query_start
  WHERE query_start >= '2022-08-03' AND query_start < '2022-08-04'
  
  -- Salah: membungkus query_start dalam fungsi melewati indeks
  WHERE to_char(query_start, 'yyyymmdd') = '20220101'

-- Langkah 1: Buat tabel target
CREATE TABLE query_log_download (
    usename text,
    status text,
    query_id text,
    datname text,
    command_tag text,
    duration integer,
    message text,
    query_start timestamp with time zone,
    query_date text,
    query text,
    result_rows bigint,
    result_bytes bigint,
    read_rows bigint,
    read_bytes bigint,
    affected_rows bigint,
    affected_bytes bigint,
    memory_bytes bigint,
    shuffle_bytes bigint,
    cpu_time_ms bigint,
    physical_reads bigint,
    pid integer,
    application_name text,
    engine_type text[],
    client_addr text,
    table_write text,
    table_read text[],
    session_id text,
    session_start timestamp with time zone,
    trans_id text,
    command_id text,
    optimization_cost integer,
    start_query_cost integer,
    get_next_cost integer,
    extended_cost text,
    plan text,
    statistics text,
    visualization_info text,
    query_detail text,
    query_extinfo text[]
);

-- Langkah 2: Ekspor log untuk tanggal tertentu
INSERT INTO query_log_download
SELECT
    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,
    trans_id, command_id, optimization_cost, start_query_cost, get_next_cost,
    extended_cost, plan, statistics, visualization_info, query_detail, query_extinfo
FROM hologres.hg_query_log
WHERE query_start >= '2022-08-03'
  AND query_start < '2022-08-04';

FAQ

Baris yang dikembalikan kueri dan baris yang dibaca tidak muncul di Hologres V1.1.

Hal ini terjadi karena pengumpulan log kueri lambat tidak lengkap di versi V1.1 yang terpengaruh. Di V1.1.36 hingga V1.1.49, aktifkan parameter GUC berikut untuk mengumpulkan statistik lengkap:

-- Tingkat database (disarankan — atur sekali per database)
ALTER DATABASE <db_name> SET hg_experimental_force_sync_collect_execution_statistics = ON;

-- Tingkat sesi
SET hg_experimental_force_sync_collect_execution_statistics = ON;

Ganti <db_name> dengan nama database Anda.

Jika instans Anda lebih awal dari V1.1.36, lihat Kesalahan umum persiapan peningkatan atau hubungi dukungan Hologres. Untuk informasi selengkapnya, lihat Bagaimana cara mendapatkan dukungan online tambahan?.

Perilaku ini telah diperbaiki secara default di V1.1.49 dan versi setelahnya.

Apakah durasi dalam log kueri lambat mencakup waktu Fetching?

Tidak. Bidang duration dalam log kueri lambat Hologres hanya mengukur waktu eksekusi di sisi server, yang terdiri dari pembuatan rencana (optimization_cost), startup (start_query_cost), dan komputasi (get_next_cost). Bidang ini tidak mencakup waktu yang dihabiskan klien untuk mengambil data hasil (fase Fetching).

Jika kueri dari tool BI seperti Quick BI memakan waktu jauh lebih lama daripada pernyataan SQL yang sama yang dijalankan di HoloWeb atau dari command line, penyebab umumnya adalah:

• Tool BI mengirim beberapa kueri secara konkuren, yang meningkatkan waktu respons keseluruhan di bawah paralelisme tinggi.

• Bidang get_next_cost mencakup waktu transfer jaringan untuk mengirim data hasil dari server ke klien. Nilai get_next_cost yang tinggi mungkin mencerminkan latensi pengambilan data di sisi klien, bukan komputasi lambat di sisi server.

Untuk membedakan antara keterlambatan sisi server dan sisi klien, jalankan kueri dengan EXPLAIN ANALYZE dan periksa bidang get_next_cost. Nilai get_next_cost yang tinggi dikombinasikan dengan nilai optimization_cost dan start_query_cost yang rendah biasanya menunjukkan bahwa waktu tersebut dihabiskan untuk transfer data, bukan eksekusi kueri.

Langkah selanjutnya

Untuk memantau dan mengelola kueri aktif di instans Anda, lihat Kelola kueri.