В моей практике ускорения 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;
Вполне логично, что все узлы, кроме первой рекурсии, не исполнялись - (never executed)
. Но вот итоговый план потянул почти на 600ms, вернув гордое "ничего из ничего".
Это поведение вполне стабильно и дает на версии PostgreSQL 10.19 воспроизводимый результат порядка 400-600 "лишних" миллисекунд.
Что интересно, на PostgreSQL 13.5 результат гораздо стабильнее, но не лучше - 600-615ms, а вот на случайно оказавшейся 13b2 на Win10 - неожиданно, всего 3ms!
Надеюсь, кто-то сможет "копнуть" ситуацию глубже и выложит детальный разбор причин, а пока что запомним: две рекурсии в одном запросе - проблемы. Кто предупрежден - вооружен!
sashocq
На одном из проектов периодически подвисала загрузка событий в БД (там в несколько потоков идут INSERT'ы при поступлении событий). В скрипт загрузки добавил EXPLAIN ANALYZE и поймал похожий план выполнения:
Меня это просто ввело в ступор и не пойму куда копать :-( В отчаянии написал и на stackoverflow.com, но понимание так и не пришло.
https://stackoverflow.com/questions/68287167/postgres-explain-analyze-total-time-greatly-exceeds-sum-of-parts
Сложность ещё в том, что проблему не удаётся поймать "вручную". Только иногда выходит (скрипт работает круглосуточно). Но при желании получается стабильно воспроизвести её проявление в скрипте.
Проблема актуально и до сих пор. Если посоветуете куда можно копнуть, буду благодарен :-)
Kilor Автор
В случае DML обычно тут скрываются триггеры, которые auto_explain не собирает по умолчанию.
Альтернативный вариант - туча индексов на таблице или медленный диск. Надо смотреть buffers и включать track_io_timings.
sashocq
Сначала был 1 триггер на
INSERT
. Он обновлял таблицу среза последних событий по объекту. И с ним как разEXPLAIN
все эти 15 секунд повесил на него. Я тогда обрадовался, что нашёл причину и убрал триггер. В результате триггера нет, а время осталось :-/Попробую посмотреть с
track_io_timings
иbuffers
, спасибо за совет!Kilor Автор
Еще имеет смысл половить Exclusive-блокировки, а то мало ли...
sashocq
Ну, сильно больше информации мне это не дало :-(
Всё-равно не пойму откуда взялись эти 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
Kilor Автор
sequence
- это просто счетчик в разделяемой памяти, поэтому его значение не влияет на скорость выполненияnextval
funny_falcon
А сколько toasted значений в каждой строчке? И сколько живых строк в таблице?