В моей практике ускорения SQL-запросов для PostgreSQL, в большинстве случаев, все сводится к применению типовых методик - их не особенно-то и много, и прочитать про большинство из них можно в моем профиле.

Но иногда обнаруживаются очень странные вещи в поведении этой, безусловно, отличной СУБД.

Все началось с запроса, который мне показали с диагнозом "необъяснимо тормозит":

EXPLAIN ANALYZE
WITH RECURSIVE ttree AS ...
-- ...
TABLE ttree;

В самом запросе не было ничего особо интересного, никаких wCTE, только попытка реализовать оптимизированный проход вниз по иерархии, а вот в плане - еще как:

CTE Scan on ttree  (actual time=0.036..0.243 rows=4 loops=1)
  CTE ttree
...
Planning time: 0.594 ms
Execution time: 413.393 ms

То есть за половину миллисекунды отработал планировщик, еще четверть заняло фактическое выполнение... и еще 412ms или 99.8% всего времени - непонятно что.

Вычленяем минимальный запрос

Если в запросе что-то ведет себя странно - начинаем отсекать "хвост" по частям, пока ситуация не станет понятной.

Режем по живому
Режем по живому

Смотрим на конец запроса:

-- ...
, tlist AS (
  SELECT * FROM thiers
)
TABLE ttree;

Понятно, что когда wCTE в запросе нет, то генерация такой CTE, у которой нет ни одного потребителя, даже в план не попадает. Но, на всякий случай закомментируем:

-- ...
/*
, tlist AS (
  SELECT * FROM thiers
)
*/
TABLE ttree;

Запрос выполняется по-прежнему, но теперь уже ничуть не тормозит:

CTE Scan on ttree  (actual time=0.025..0.240 rows=4 loops=1)
  CTE ttree
...
Planning time: 0.289 ms
Execution time: 0.316 ms

Внезапно! Как и почему от комментирования неиспользуемой CTE запрос ускорился в 500 раз?

Борьба за воспроизводимость

Итак, мы неожиданно выяснили, что "тормозить" перестает, если убрать лишнюю CTE, с обращением к другой CTE - thier. Вот только эта CTE тоже не простая, а рекурсивная.

Отсекаем все лишнее
Отсекаем все лишнее

Возьмем тестовую микротабличку:

CREATE TABLE tbl AS
SELECT
  (random() * 1e5)::integer val
FROM
  generate_series(1, 1e5);
  
CREATE INDEX ON tbl(val);

И постепенное отсечение всех элементов приводит нас к вот такой модели запроса:

EXPLAIN (ANALYZE, COSTS OFF)
-- первая рекурсия, возвращает 0 "записей" из таблицы
WITH RECURSIVE R1 AS (
  SELECT
    '{}'::tbl[] recs
UNION ALL
  SELECT
    '{}'::tbl[]
  FROM
    R1
  WHERE
    coalesce(recs, '{}') <> '{}'
)
-- "разворачиваем" якобы полученные записи в поля
, R1v AS (
  SELECT
    (rec).val
  FROM
    (
      SELECT
        unnest(recs) rec
      FROM
        R1
    ) T
)
-- вторая рекурсия
, R2 AS (
  TABLE R1v
UNION
  SELECT
    R1v.*
  FROM
    R1v
  , R2
)
-- неиспользуемый результат второй рекурсии
, X AS (
  TABLE R2
)
TABLE R1;
Куда пропали 595ms?
Куда пропали 595ms?

Вполне логично, что все узлы, кроме первой рекурсии, не исполнялись - (never executed). Но вот итоговый план потянул почти на 600ms, вернув гордое "ничего из ничего".

Это поведение вполне стабильно и дает на версии PostgreSQL 10.19 воспроизводимый результат порядка 400-600 "лишних" миллисекунд.

Что интересно, на PostgreSQL 13.5 результат гораздо стабильнее, но не лучше - 600-615ms, а вот на случайно оказавшейся 13b2 на Win10 - неожиданно, всего 3ms!


Надеюсь, кто-то сможет "копнуть" ситуацию глубже и выложит детальный разбор причин, а пока что запомним: две рекурсии в одном запросе - проблемы. Кто предупрежден - вооружен!

Комментарии (7)


  1. sashocq
    14.02.2022 18:39

    На одном из проектов периодически подвисала загрузка событий в БД (там в несколько потоков идут INSERT'ы при поступлении событий). В скрипт загрузки добавил EXPLAIN ANALYZE и поймал похожий план выполнения:

    Insert on tests  (cost=0.00..0.01 rows=1 width=94) (actual time=0.051..0.051 rows=0 loops=1)
      ->  Result  (cost=0.00..0.01 rows=1 width=94) (actual time=0.010..0.010 rows=1 loops=1)
    Planning time: 0.014 ms
    Execution time: 15624.374 ms

    Меня это просто ввело в ступор и не пойму куда копать :-( В отчаянии написал и на stackoverflow.com, но понимание так и не пришло.

    https://stackoverflow.com/questions/68287167/postgres-explain-analyze-total-time-greatly-exceeds-sum-of-parts

    Сложность ещё в том, что проблему не удаётся поймать "вручную". Только иногда выходит (скрипт работает круглосуточно). Но при желании получается стабильно воспроизвести её проявление в скрипте.

    Проблема актуально и до сих пор. Если посоветуете куда можно копнуть, буду благодарен :-)


    1. Kilor Автор
      14.02.2022 18:50
      +1

      В случае DML обычно тут скрываются триггеры, которые auto_explain не собирает по умолчанию.

      Альтернативный вариант - туча индексов на таблице или медленный диск. Надо смотреть buffers и включать track_io_timings.


      1. sashocq
        14.02.2022 20:03

        Сначала был 1 триггер на INSERT. Он обновлял таблицу среза последних событий по объекту. И с ним как раз EXPLAIN все эти 15 секунд повесил на него. Я тогда обрадовался, что нашёл причину и убрал триггер. В результате триггера нет, а время осталось :-/

        Попробую посмотреть с track_io_timings и buffers, спасибо за совет!


        1. Kilor Автор
          14.02.2022 20:22

          Еще имеет смысл половить Exclusive-блокировки, а то мало ли...


        1. sashocq
          14.02.2022 20:27

          Ну, сильно больше информации мне это не дало :-(

          Insert on public.tests  (cost=0.00..0.01 rows=1 width=94) (actual time=0.092..0.092 rows=0 loops=1)
            Buffers: shared hit=12
            ->  Result  (cost=0.00..0.01 rows=1 width=94) (actual time=0.008..0.008 rows=1 loops=1)
                  Output: nextval('tests_id_seq'::regclass), 'Мираж'::text, 'E602'::text, 7173, NULL::smallint, '2022-02-14 20:08:52.904853'::timestamp without time zone, '2022-02-14 17:08:52.904853'::timestamp without time zone
                  Buffers: shared hit=1
          Planning time: 0.016 ms
          Execution time: 10964.870 ms

          Всё-равно не пойму откуда взялись эти 10 секунд. Диск там виртуальный на SSD, но как я понял `shared hit` означает что данные вообще в кэше были и диск не задействовался.

          Правда, теперь ещё на nextval('tests_id_seq'::regclass) обратил внимание. Может в нём быть дело? Базе несколько лет, id уже > 1 500 000 000:

          Добавлено:

          Колонка объявлена так:
          id bigint NOT NULL DEFAULT nextval('tests_id_seq'::regclass)

          Наверное, проблема всё-таки в ней. PostgreSQL 9.6


          1. Kilor Автор
            15.02.2022 08:40

            sequence - это просто счетчик в разделяемой памяти, поэтому его значение не влияет на скорость выполнения nextval


          1. funny_falcon
            15.02.2022 09:43

            А сколько toasted значений в каждой строчке? И сколько живых строк в таблице?