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

    Очень коротко покажу, как настроить 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. Включить модуль на все запросы на сервере



      попутно подправлю логирование


      Не забудь применить конфиги

      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

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



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

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

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

    create index on somet (number) where number < 1000

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



    pgBadger


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

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


    Установка:

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

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



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

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

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

    Similar posts

    Comments 18

      +6
      Не упомянули ещё что auto_explain можно включать на отдельного пользователя:
      ALTER ROLE some_user SET session_preload_libraries TO 'auto_explain';
      ALTER ROLE some_user SET "auto_explain.log_min_duration" TO '100ms';


      Штука хорошая, особенно если надо ловить некий подземный стук когда план внезапно плывёт. Или интересный фокус был с приложением, которое неверно заявляло типы данных для prepared statement (передавался numeric вместо int), из-за чего планировщиком не использовался индекс, но сам запрос выполнялся корректно. Выполнялся медленно, и не ловилось через explain, т.к. не было видно передаваемый тип.

      Если интересуют просто тяжёлые запросы — лучше включить pg_stat_statements и раз в сутки (или своим мониторингом) строить отчёт по времени выполнения. Мы например кругом настраиваем вот такой отчёт с топ-40 запросами по общему времени выполнения за сутки.

      Окметр — хорошая штука, и даже если не используете его, то весьма советую посмотреть какие метрики выводятся на графиках postgresql и сделать в своём мониторинге такие же. Ну а вообще у них огромная куча метрик собирается. (циферки по конкретным запросам к слову именно pg_stat_statements и собирает)
        0
        Спасибо за качественный коммент
        Если честно — не знал, что для ролей можно определять свои настройки (хотя это же пг, кажется тут всё возможно)
      • UFO just landed and posted this here
          0
          Вы описали работу pg_stat_statements за двумя оговорками: автоматически результата explain в нём пока нет (потому что неясно какой именно план писать в результат, патчи есть для записи лучшего/худшего планов, но в pg11 они не вошли), зато нормализация запросов давно есть и отлично работает с plain text запросами даже без prepared statements.

          Попутно заметки:
          если логи пишутся на отдельный раздел, то его переполнение не приведёт к остановке базы. Просто за это время не будет логов. Logging collector не считает недостаток места поводом останавливать работу.

          Разгрести лог аварии — упомянутый pgbadger и другие утилитки такого плана.
            0
            диск 100%

            Я запоздало сообразил, что вы скорее имели в виду дисковую утилизацию в потолок.
            Вообще понять только по логам что пошло не так — весьма непросто бывает. Графики мониторинга нужны, простой график top-N запросов по общему времени выполнения — уже значительно упрощает жизнь. Цифры есть в pg_stat_statements и даже отдельно время для дисковых операций. И единственная сложность — счётчики инкрементные, значит мониторинг должен показывать разницу между метриками во времени, а не сиюминутные stateless значения, как большинство системных метрик.
        • UFO just landed and posted this here
            0
            при этом их запрос убивается количеством Filtered
            Ага, и ещё гигантские выборки могут отлично страдать от Recheck Cond
            Я так понял речеги это когда выборка слишком велика, чтобы карта версий строк влезла в ОЗУ (параметр work_mem). Тогда строится битовая карта страниц, хотя бы с одной найденной TID. Занимает меньше ОЗУ, но перепроверяет все строки страниц

            • UFO just landed and posted this here
              0
              min/max filtered. И эта чиселка в общем случае будет алертом для админа/разработчика

              А сможете описать (лучше сразу на английском), зачем вам именно счётчики фильтров, вернее чем для таких алертов не годятся min/max/mean/stddev счётчики времени выполнения?
              Если QueryDesc->totaltime->nfiltered1 и nfiltered2 — то о чём я думаю, то их совсем не сложно вытащить в pg_stat_statements. С хорошей аргументацией целесообразности патч и принять могут.

              [типовой в общем-то] случай когда все запросы оптимизированы и один-два запросов пошли вдруг к базе без индексов

              Нет, не соглашусь что это типовой случай. Общаюсь как DBA с несколькими десятками команд разработчиков, проблемы вызывают в основном новые запросы, которые выкатывают разработчики с релизом или сами релизы миграций. Внезапно поплывший план — большая редкость.

              Ну а в целом любой проект имеет конечное число уникальных запросов к БД, количество которых сводится всего к нескольким десяткам, ну максимум к сотням

              Сильно не соглашусь. У четверти из моих пары сотен подопечных серверов больше тысячи уникальных запросов в сутки. Меньше сотни — у другой четверти, включая отчёты с резервных реплик без нагрузки.

              А выборка даже по первичному ключу может замечательно тупить на частообновляемых таблицах если мешать работать автовакууму. В explain(analyze,buffers) тогда видны чудесные тысячи просмотренных страниц в поиске единственной нужной строки.
              • UFO just landed and posted this here
                  0
                  Вы написали много текста, но так и не ответили, чем не годятся уже давно предоставляемые min/max/mean/stddev счётчики времени выполнения. Как более комплексная величина они точнее покажут, что с запросом есть проблема.
                  • UFO just landed and posted this here
            • UFO just landed and posted this here
                0
                Почему это не будет?
                После lossy индексов (например gist или brin) всегда будут recheck.
                После bitmap index scan — тоже.
                  0
                  Да, именно так

                  Может кому будет интересно

                  GIN:
                  Особенность метода доступа gin состоит в том, что результат всегда возвращается в виде битовой карты: выдавать TID-ы по одному этот метод не умеет. Именно поэтому все планы запросов, которые встречаются в этой части, используют сканирование по битовой карте (bitmap scan)

                  GiST — в виду того, что хранятся в индексе не значения, а логические суммы лексем документов (сигнатуры доков) — могут быть коллизии, потому тоже речек, даже если был простой Index Scan

                  Да и вообще рекомендую прочесть все статьи из серии ) там ещё brin, sp-gist, hash, rum, bloom
                  • UFO just landed and posted this here
                      0
                      Погодите, он же работает только с битовой картой
                      Речек обязательно есть
                      Вот пример с пустой таблицей и вашим условием habrastorage.org/webt/zo/-m/mw/zo-mmw7k4vcbtwk7sgztbrlbe20.png

                      Вот с непустой таблицей — hsto.org/webt/gz/ec/gx/gzecgxj2obtrsgghgzq-htesh3o.png
                      Прошу заметить, что Bitmap Index Scan вернул одну строку, но после был её речек

                      Скрипт, можете проверить
                      create table test (f1 text[]);
                      create index on test using gin (f1);
                      
                      insert into test VALUES(ARRAY['postgresql']);
                      insert into test VALUES(ARRAY['postgresql2', 'mysql']);
                      insert into test VALUES(ARRAY['postgresql2', 'mysql', 'mssql']);
                      
                      explain ANALYSE
                      select * from test WHERE f1 @> ARRAY['postgresql']::TEXT[];
                      

                      • UFO just landed and posted this here

              Only users with full accounts can post comments. Log in, please.