pg_trace — трассировщик запросов от компании "Тантор Лабс"

Дисклеймер

В компании "Тантор Лабс" я отвечаю за развитие направления 1С, поэтому все примеры я буду рассматривать в связке работы приложения 1С с "СУБД Tantor Special Edition 1C". Однако на месте 1С может быть любое приложение, поэтому весь предоставленный ниже материал универсален и будет полезен каждому слушателю.

Профайлеры запросов

pg_trace

Постановка задачи

Установка pg_trace

shared_preload_libraries = 'pg_trace'

systemctl restart tantor-se-1c-server-16.service

postgres=# CREATE EXTENSION pg_trace;
CREATE EXTENSION

pg_trace.plan_format = 'json'

Разграничение прав
Трассировка —это функция, которая должна быть доступна только определенной группе пользователей, отвечающих за SRE. Настроить доступы к функциям управления трассировкой (старт/стоп) можно через команды управления доступом GRANT/REVOKE. Например:

REVOKE EXECUTE ON FUNCTION pg_trace_start FROM public;
REVOKE EXECUTE ON FUNCTION pg_trace_stop FROM public;

GRANT EXECUTE ON FUNCTION pg_trace_start TO superuser;
GRANT EXECUTE ON FUNCTION pg_trace_stop TO superuser;

Сбор трассировки

postgres=# SELECT pg_trace_start(
    plan := TRUE, duration := '1000ms', database_id := 707533240
);
 pg_trace_start
----------------
 t
(1 строка)

nc -U /tmp/pg_trace.sock > trace_file.txt

python3 client.py --unix-socket=/tmp/pg_trace.sock --format=json > trace_file.log

postgres=# SELECT pg_trace_start(
    plan := TRUE, database_id := 707533240, query_like := '%_AccumRg51156%'
);
 pg_trace_start
----------------
 t
(1 строка)

postgres=# SELECT pg_trace_stop();
 pg_trace_stop
---------------
 t
(1 строка)

Автоматическое завершение трассировки
Трассировка — это функция, которая не должна быть включена на постоянной основе в продуктиве, потому что она может влиять на производительность. В MS SQL она будет собираться до тех пор, пока вы ее не остановите или не будет достигнут максимальный размер файла или максимальное количество строк трассировки. С учетом этого опыта мы специально реализовали функцию автоматического завершения трассировки.

Влияние на производительность

Трассировка как инструмент анализа

python3 client.py --format=csv --unix-socket=/tmp/pg_trace.sock > output.csv

postgres=# CREATE DATABASE traces;

traces=# CREATE TABLE pg_trace_columnar (
    queryid bigint,
    dbid integer,
    userid integer,
    tuplescount numeric,
    start_time bigint,
    end_time bigint,
    total_time float8,
    startup_time float8,
    sys_time float8,
    user_time float8,
    rows int8,
    shared_blks_hit int8,
    shared_blks_read int8,
    shared_blks_written int8,
    shared_blks_dirtied int8,
    local_blks_hit int8,
    local_blks_read int8,
    local_blks_written int8,
    local_blks_dirtied int8,
    blk_read_time float8,
    blk_write_time float8,
    temp_blk_read_time float8,
    temp_blk_write_time float8,
    wal_records int8,
    wal_fpi int8,
    wal_bytes numeric,
    jit_functions int8,
    jit_generation_time float8,
    jit_optimization_time float8,
    jit_inlining_time float8,
    jit_emission_time float8,
    query VARCHAR(1500),
    plan text
) using columnar;

traces=# COPY pg_trace_columnar
FROM '/var/lib/postgresql/output.csv'
WITH (DELIMITER ';',FORMAT csv, HEADER true);
----------------------------
COPY 8792996

traces=# \timing on
traces=# SELECT
    SUM(total_time) AS queries_total_time,
    AVG(total_time) AS queries_avg_time,
    MAX(total_time) AS queries_max_time,
    MIN(total_time) AS queries_min_time,
    SUM(shared_blks_hit) AS shared_blks_hit,
    SUM(shared_blks_read) AS  shared_blks_read ,
    SUM(local_blks_hit) AS  local_blks_hit,
    SUM(local_blks_read) AS   local_blks_read
FROM
    pg_trace_columnar;
 
 queries_total_time |  queries_avg_time  | queries_max_time | queries_min_time | shared_blks_hit | shared_blks_read | local_blks_hit | local_blks_read
--------------------+--------------------+------------------+------------------+-----------------+------------------+----------------+-----------------
  29614580.94511461 | 3.3679738902547673 |          29347.5 |          0.00075 |      6836559844 |          4328714 |      963126388 |         2704980
(1 строка)
 
Время: 808,669 мс

traces=# SELECT
    COUNT(1) AS queries_count
FROM
    pg_trace_columnar
WHERE total_time > 1000;
 
 queries_count
---------------
          2179
(1 строка)
 
Время: 318,811 мс