Hologres:Get and analyze slow query logs

La table hg_query_log

La table contient deux types d'enregistrements, qui partagent le même schéma mais ont des sémantiques différentes :

Comprendre la décomposition de duration :

Le champ duration représente le temps total de la requête et est composé de trois étapes :

Utilisez extended_cost pour obtenir des détails de synchronisation supplémentaires au-delà de ces trois étapes.

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

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

Afficher dans HoloWeb

1. Connectez-vous à la console HoloWeb.

2. Dans la barre de navigation supérieure, cliquez sur Diagnostics and Optimization.

3. Dans le volet de navigation de gauche, cliquez sur Historical Slow Query.

4. Définissez les conditions de requête en haut de la page Historical Slow Query. Pour une description des paramètres, consultez Requêtes lentes historiques.

5. Cliquez sur Search. Les résultats apparaissent dans deux zones :

   • Query Trend Analysis : affiche la fréquence des requêtes lentes et échouées au fil du temps, vous aidant à identifier les périodes problématiques.

   • Queries : répertorie les informations détaillées pour chaque requête lente ou échouée. Cliquez sur Customize Columns pour choisir les colonnes à afficher.

Interroger avec SQL

Interrogez directement la table hologres.hg_query_log pour une flexibilité totale. Consultez Diagnostiquer les requêtes pour des exemples SQL prêts à l'emploi.

SELECT count(*) FROM hologres.hg_query_log;

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

SELECT usename AS "User",
       count(1) AS "Query count"
FROM hologres.hg_query_log
GROUP BY usename
ORDER BY count(1) DESC;

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

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

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;

 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)

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;

 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)

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;

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;

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;

 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)

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;

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

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;

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

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;

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;

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

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;

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;

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;

log_min_duration_statement

Contrôle la durée minimale de requête pour la journalisation.

• Par défaut : 100 ms (à partir de la V2.2.7 ; les versions antérieures utilisent 1 000 ms par défaut).

• Valeur minimale : 100 ms.

• Définissez sur -1 pour désactiver complètement la journalisation des requêtes lentes.

• Seuls les superutilisateurs peuvent modifier ce paramètre au niveau de la base de données. Les utilisateurs réguliers peuvent le modifier au niveau de la session.

• Les modifications s'appliquent uniquement aux nouvelles requêtes.

-- Database level (superuser only)
ALTER DATABASE dbname SET log_min_duration_statement = '250ms';

-- Session level
SET log_min_duration_statement = '250ms';

log_min_duration_query_stats

Contrôle si les statistiques d'exécution sont capturées pour une requête.

• Par défaut : enregistre les statistiques pour les requêtes s'exécutant pendant plus de 10 s.

• Définissez sur -1 pour désactiver la collecte de statistiques.

• Les statistiques utilisent un espace de stockage important. Abaissez cette valeur uniquement pour un dépannage ciblé ; rétablissez-la ensuite.

• Les modifications s'appliquent uniquement aux nouvelles requêtes.

-- Database level (superuser only)
ALTER DATABASE dbname SET log_min_duration_query_stats = '20s';

-- Session level
SET log_min_duration_query_stats = '20s';

log_min_duration_query_plan

Contrôle si le plan d'exécution est capturé pour une requête.

• Par défaut : enregistre les plans pour les requêtes s'exécutant pendant plus de 10 s.

• Définissez sur -1 pour désactiver la capture du plan.

• Pour un dépannage ponctuel, utilisez plutôt EXPLAIN — cela renvoie le plan instantanément sans journalisation.

• Les modifications s'appliquent uniquement aux nouvelles requêtes.

-- Database level (superuser only)
ALTER DATABASE dbname SET log_min_duration_query_plan = '10s';

-- Session level
SET log_min_duration_query_plan = '10s';

ALTER DATABASE <db_name> SET hg_query_log_retention_time_sec = 2592000;

Exporter vers une table interne Hologres

-- Step 1: Create the target table
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[]
);

-- Step 2: Export logs for a specific date
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';

Exporter vers une table externe MaxCompute

1. Dans MaxCompute, créez une table partitionnée pour recevoir les données :

   CREATE TABLE IF NOT EXISTS mc_holo_query_log (
       username        STRING COMMENT 'The username for the query',
       status          STRING COMMENT 'The final status of the query: success or failed',
       query_id        STRING COMMENT 'The query ID',
       datname         STRING COMMENT 'The name of the database for the query',
       command_tag     STRING COMMENT 'The type of query',
       duration        BIGINT COMMENT 'The query duration in milliseconds (ms)',
       message         STRING COMMENT 'The error message',
       query           STRING COMMENT 'The text content of the query',
       read_rows       BIGINT COMMENT 'The number of rows read by the query',
       read_bytes      BIGINT COMMENT 'The number of bytes read by the query',
       memory_bytes    BIGINT COMMENT 'The peak memory consumption on a single node (not exact)',
       shuffle_bytes   BIGINT COMMENT 'The estimated number of bytes for data shuffle (not exact)',
       cpu_time_ms     BIGINT COMMENT 'The total CPU time in milliseconds (not exact)',
       physical_reads  BIGINT COMMENT 'The number of physical reads',
       application_name STRING COMMENT 'The query application type',
       engine_type     ARRAY<STRING> COMMENT 'The engine used for the query',
       table_write     STRING COMMENT 'The table to which the SQL statement writes data',
       table_read      ARRAY<STRING> COMMENT 'The table from which the SQL statement reads data',
       plan            STRING COMMENT 'The execution plan for the query',
       optimization_cost BIGINT COMMENT 'The time to generate the query execution plan',
       start_query_cost  BIGINT COMMENT 'The query startup time',
       get_next_cost     BIGINT COMMENT 'The query execution duration',
       extended_cost   STRING COMMENT 'Other detailed costs of the query',
       query_detail    STRING COMMENT 'Other extended information about the query (JSON format)',
       query_extinfo   ARRAY<STRING> COMMENT 'Other extended information about the query (ARRAY format)',
       query_start     STRING COMMENT 'The query start time',
       query_date      STRING COMMENT 'The query start date'
   ) COMMENT 'Hologres instance query log'
   PARTITIONED BY (ds STRING COMMENT 'stat date')
   LIFECYCLE 365;
   
   ALTER TABLE mc_holo_query_log ADD PARTITION (ds=20220803);

2. Dans Hologres, importez la table MaxCompute en tant que table externe et exportez les journaux :

   IMPORT FOREIGN SCHEMA project_name LIMIT TO (mc_holo_query_log)
   FROM SERVER odps_server INTO public;
   
   INSERT INTO mc_holo_query_log
   SELECT
       usename AS username, status, query_id, datname, command_tag, duration,
       message, query, read_rows, read_bytes, memory_bytes, shuffle_bytes,
       cpu_time_ms, physical_reads, application_name, engine_type,
       table_write, table_read, plan, optimization_cost, start_query_cost,
       get_next_cost, extended_cost, query_detail, query_extinfo,
       query_start, query_date,
       '20220803'
   FROM hologres.hg_query_log
   WHERE query_start >= '2022-08-03'
     AND query_start < '2022-08-04';

-- Database level (recommended — set once per database)
ALTER DATABASE <db_name> SET hg_experimental_force_sync_collect_execution_statistics = ON;

-- Session level
SET hg_experimental_force_sync_collect_execution_statistics = ON;