Postgres auto_explain: автолог плана запроса06.05.2018 05:33

Очень коротко покажу, как настроить PG для логирования планов выполнения запросов и как потом, не искать по логам всё, что медленно исполнялось

У меня нет postgres на локальной тачке, потому сначала установлю
Ubuntu 18
> sudo apt install postgresql-10

Success. You can now start the database server using:
  /usr/lib/postgresql/10/bin/pg_ctl -D /var/lib/postgresql/10/main -l logfile start
Ver Cluster Port Status Owner  Data directory       Log file
10 main  5432 down  postgres /var/lib/postgresql/10/main /var/log/postgresql/postgresql-10-main.log
update-alternatives: using /usr/share/postgresql/10/man/man1/postmaster.1.gz to provide /usr/share/man/man1/postmaster.1.gz (postmaster.1.gz) in auto mode
Processing triggers for ureadahead (0.100.0-20) ...
Processing triggers for systemd (237-3ubuntu10) ...

> sudo -u postgres psql postgres
psql (10.3 (Ubuntu 10.3-1))
Type "help" for help.

postgres=# \password postgres
Enter new password: 1
Enter it again: 1

postgres=# create DATABASE test;

> sudo -u postgres psql test
test=# show config_file;
        config_file        
-----------------------------------------
 /etc/postgresql/10/main/postgresql.conf
(1 row)


auto_explain


Для автоматического логирования планов выполнения существует модуль auto_explain

Модуль auto_explain предоставляет возможность автоматического протоколирования планов выполнения медленных операторов, что позволяет обойтись без выполнения EXPLAIN вручную. Это особенно полезно для выявления неоптимизированных запросов в больших приложениях.

Т.е. в Postgres возможно узнать план запроса на момент его исполнения

Сделать это можно двумя путями:

  1. Включив модуль для запроса: 
    load 'auto_explain';
SET auto_explain.log_min_duration = 10;
SET auto_explain.log_analyze = true;

select count(*) from somet where number < 1000
    Это полезно, если попрофилировать нужно конкретный запрос
  2. Включить модуль на все запросы на сервере

    _23lta57pzocyny1aaajcv06ica.png

    попутно подправлю логирование
    8bpdaxakm0kii5b4yabwzqbsgd4.png

    Не забудь применить конфиги
    test=# SELECT pg_reload_conf();
 pg_reload_conf 
----------------
 t
(1 row)


Ну всё, можно тестить

Генерация тестовых данных 
CREATE EXTENSION IF NOT EXISTS "uuid-ossp";

create table somet(
  id uuid PRIMARY key, 
  number INTEGER,
  text text
);

insert into somet
select uuid_generate_v1(), round(random() * 1000000), round(random() * 1000000)::text from generate_series(1,10000000)


А вот запрос, которым будем отлаживать логи: 

select count(*) from somet where number < 1000


Го в логи, там план:

hg4j8wwrc3w7qmheecks9hsivy0.png

Собственно хорошо, только нюанс — залогировался запрос 4 раза, а план — трижды, почему так — Parallel Seq Scan, а именно — запрос начал обрабатываться в 2 потока (Workers Planned: 2) и после собрался в общий результат (новый шаг в плане выполнения PG10 — Gather). Так и получается ровно 3 плана, на каждый запрос)

Итак, собственно вот, видим «на лету», что у нас есть что-то нехорошее — Sec Scan тысяч строк

Уверен поможет индекс: 

create index on somet (number) where number < 1000


Всё, модуль автоэксплейна ничего в логи не пишет:

ncb9zfldgivja93tzhvn_urhrfe.png

pgBadger


Просматривать логи глазками неудобно, потому для поиска подобных запросов по логам есть утилита — pgbadger. Она группирует и агрегирует запросы в простенький html-отчёт. И будет он настолько подробным, насколько подробны ваши логи

Показывать буду на пг 9.6, т.к. лог 10-ки не так демонстративен
14qwecmanfpycg74j4pen1vltqi.png


Установка: 

> sudo apt install pgbadger


Генерация отчёта на основании логов: 

> pgbadger -j 4 -p '%t [%p]:[%l-1]' /var/log/postgresql/postgresql-9.6-main.log -o bad.html
[========================>] Parsed 43578 bytes of 43578 (100.00%), queries: 115, events: 1
LOG: Ok, generating html report...


И подобная красота получается:

ztun3t-u6yxvfxjmjgit-tx57do.png

В общем не буду рассказывать обо всех возможностях pgbadger, ибо и сам их не знаю, а документация у него очень хорошая, тем более есть «живой отчёт», который нагляднее покажет всё.

И коротко, как у нас:

  • auto_explain в проде отключен
  • К логам постгрес обращаемся очень редко, но pgBadger использовали
  • Для real time мониторинга используем вовсе okmeter, отлично себя показал, но лучше логов, порой, ничего нет)

© Habrahabr.ru