Комментарии 7
На одном из проектов периодически подвисала загрузка событий в БД (там в несколько потоков идут 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, но понимание так и не пришло.
Сложность ещё в том, что проблему не удаётся поймать "вручную". Только иногда выходит (скрипт работает круглосуточно). Но при желании получается стабильно воспроизвести её проявление в скрипте.
Проблема актуально и до сих пор. Если посоветуете куда можно копнуть, буду благодарен :-)
В случае DML обычно тут скрываются триггеры, которые auto_explain не собирает по умолчанию.
Альтернативный вариант - туча индексов на таблице или медленный диск. Надо смотреть buffers и включать track_io_timings.
Сначала был 1 триггер на INSERT. Он обновлял таблицу среза последних событий по объекту. И с ним как раз EXPLAIN все эти 15 секунд повесил на него. Я тогда обрадовался, что нашёл причину и убрал триггер. В результате триггера нет, а время осталось :-/
Попробую посмотреть с track_io_timings и buffers, спасибо за совет!
Еще имеет смысл половить Exclusive-блокировки, а то мало ли...
Ну, сильно больше информации мне это не дало :-(
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
PostgreSQL Antipatterns: рекурсивные грабли на ровном месте, или Сказка о потерянном времени