Как отловить плавающий по времени запрос?

Question

[Владимир]

Есть плавающий по времени запрос.
Большее количество времени он выполняется за миллисекунды, но периодически случаются провалы до 6 секунд.
После, с параметрами которые отрабатывали 3-6 секунд, запрос выполняется с нормальной скоростью в ms

Как можно понять что происходит?

По процессору нет изменений в это время.
По дискам совсем небольшая просадка по времени.
В памяти тоже нет пиков.

Включён auto_explain, но не можем включить его на analyze уровень т.к это сильно замедлит БД.
пока не совсем понимаю за что зацепиться

Answer 1

[Melkij]

После, с параметрами которые отрабатывали 3-6 секунд, запрос выполняется с нормальной скоростью в ms

Симптоматика медленного чтения с дисков.
Поставьте pg_stat_statements, включите track_io_timing и посмотрите в blk_read_time, blk_write_time этого запроса относительно числа вызовов и общего времени их выполнения.

PS: обратите внимание, что для СУБД критична латентность дисковой системы. Есть графики латентности io на чтение и запись?

Comments

[Владимир]

Melkij

Вообще нет совпадений задержек диска и замедления запросов 1 в 1.

Вот для этой картинки например в 15:00 были задержки.


Врубил track_io_timing и вижу что он всё же читает с диска. (пока не было выбросов, но похоже IO может влиять). Это повод задуматься о том что у нас что-то не лезет в ОЗУ?

[Melkij]

shared_blks_read - только про отсутствующие блоки в shared_buffers. Узнать, дошёл ли запрос до диска или был из системного page cache выполнен - никак. Поэтому однозначно не сказать, что не хватает памяти. Ну разве только у вас больше 75% ram отдано под shared buffers, когда в системном page cache мало что может уместиться.
Тем не менее факт говорит о том, что половину суммарного времени выполнения этих 100тыс запросов ждали IO. 1мс латентности, конечно, не предел мечтаний.
Дальше пока наблюдать, ждать проблемный пик и смотреть как изменятся цифры.

auto_explain для этих запросов ведь не фиксирует изменение плана?

[Владимир]

Melkij

Да, планы у запросов одинаковые.
Будем смотреть. сейчас 4Gb из 15Gb под shared_buffers, может попробуем докинуть пару гигов и посмотрим на результат.