Hologres:Obter e analisar logs de consultas lentas

A tabela hg_query_log

A tabela possui dois tipos de registros, que compartilham o mesmo esquema, mas têm semânticas diferentes:

Entendendo o detalhamento da duration:

O campo duration representa o tempo total da consulta e é composto por três etapas:

Use extended_cost para obter detalhes adicionais de tempo além dessas três etapas.

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

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

Visualizar no HoloWeb

1. Faça login no console do HoloWeb.

2. Na barra de navegação superior, clique em Diagnostics and Optimization.

3. No painel de navegação à esquerda, clique em Historical Slow Query.

4. Defina as condições de consulta na parte superior da página Historical Slow Query. Para uma descrição dos parâmetros, consulte Consultas Lentas Históricas.

5. Clique em Search. Os resultados aparecem em duas áreas:

   • Query Trend Analysis: mostra a frequência de consultas lentas e com falha ao longo do tempo, ajudando a identificar períodos problemáticos.

   • Queries: lista informações detalhadas para cada consulta lenta ou com falha. Clique em Customize Columns para escolher quais colunas exibir.

Consultar com SQL

Consulte a tabela hologres.hg_query_log diretamente para total flexibilidade. Consulte Diagnosticar consultas para exemplos de SQL prontos para uso.

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

Controla a duração mínima da consulta para registro em log.

• Padrão: 100 ms (a partir da V2.2.7; versões anteriores têm padrão de 1.000 ms).

• Valor mínimo: 100 ms.

• Defina como -1 para desativar completamente o registro de consultas lentas.

• Apenas superusuários podem alterar isso no nível do banco de dados. Usuários regulares podem alterar no nível da sessão.

• As alterações aplicam-se apenas a novas consultas.

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

Controla se as estatísticas de execução são capturadas para uma consulta.

• Padrão: registra estatísticas para consultas com duração superior a 10 s.

• Defina como -1 para desativar a coleta de estatísticas.

• Estatísticas consomem armazenamento significativo. Reduza este valor apenas para solução de problemas pontual; restaure-o depois.

• As alterações aplicam-se apenas a novas consultas.

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

Controla se o plano de execução é capturado para uma consulta.

• Padrão: registra planos para consultas com duração superior a 10 s.

• Defina como -1 para desativar a captura de plano.

• Para solução de problemas ad hoc, use EXPLAIN — ele retorna o plano instantaneamente sem registrar em log.

• As alterações aplicam-se apenas a novas consultas.

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

Exportar para uma tabela interna do 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';

Exportar para uma tabela externa do MaxCompute

1. No MaxCompute, crie uma tabela particionada para receber os dados:

   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. No Hologres, importe a tabela do MaxCompute como uma tabela externa e exporte os logs:

   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;