PostgreSQL Antipatterns: рекурсивные грабли на ровном месте, или Сказка о потерянном времени

[sashocq]

На одном из проектов периодически подвисала загрузка событий в БД (там в несколько потоков идут 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

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

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

[Kilor]

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

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

[sashocq]

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

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

[Kilor]

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

[sashocq]

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

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

[Kilor]

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

[funny_falcon]

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