В логах у нас отражается всего 3 вида событий, которые могут происходить с блокировкой:
-
ожидание блокировки
LOG: process 38162 still waiting for ExclusiveLock on advisory lock [225382138,225386226,141586103,2] after 100.047 ms
-
получение блокировки
LOG: process 38162 acquired ExclusiveLock on advisory lock [225382138,225386226,141586103,2] after 150.741 ms
-
взаимоблокировка
ERROR: deadlock detected
deadlock'и исключим из анализа это просто ошибки, и попробуем выяснить, сколько всего времени мы потеряли из-за блокировок за конкретный день на определенном хосте.
Для начала нам понадобится таблица, куда мы будем собирать все такие записи:
CREATE TABLE lock( dt -- ключ хронологического секционирования date, host -- сервер, на котором возникла блокировка uuid, pid -- PID процесса из строки лога integer, ts -- момент события timestamp, event -- { lock-wait | lock-acquire | deadlock-detect } lockevent, type -- { relation | extend | ... } locktype, mode -- { AccessShare | RowShare | ... } lockmode, lock -- объект блокировки uuid, exectime -- продолжительность numeric(32,2));
Более подробно про организацию секционирования в нашей системе мониторинга можно прочитать в статье Пишем в PostgreSQL на субсветовой: 1 host, 1 day, 1TB, а про различные типы и режимы блокировок в DBA: кто скрывается за блокировкой.
Как слышится, так и пишется
Попробуем ответить на вопрос, вынесенный в начало статьи, простейшим способом.
Что такое время ожидания блокировки? Ну, очевидно же, это время ее получения для каждого случая ее ожидания:
- берем каждый случай ожидания (
lock-wait
) - для него находим ближайшую снизу по времени запись получения
(
lock-acquire
) этой же(lock, pid, mode)
блокировки то есть на тот же объект, в том же процессе, с тем же режимом
Тип блокировки (
type
) в нашем случае можно опустить,
поскольку он однозначно определяется самим объектом
(lock
).Дальше останется только просуммировать полученные результаты.
SELECT ts, pid, event, type, mode, lock, exectime, T.*FROM lock lc, LATERAL ( SELECT exectime waittime FROM lock WHERE ( dt , host , lock , pid , mode , event ) = ( '2020-06-19'::date , lc.host , lc.lock , lc.pid , lc.mode , 'lock-acquire' ) AND ts >= lc.ts ORDER BY ts LIMIT 1 ) TWHERE ( lc.dt , lc.host , lc.event ) = ( '2020-06-19'::date , 'e828a54d-7e8a-43dd-b213-30c3201a6d8e'::uuid , 'lock-wait'::lockevent );
Все просто и ясно! А что нам покажет
EXPLAIN
?..Оу пришлось прочитать почти 900MB данных, причем почти все из-за поиска связанной записи для каждой блокировки, не очень красиво.
Но является ли этот запрос вообще корректным для нашей задачи? Нет! Посмотрим внимательно в собранные данные:
Ой Оказывается, сервер жалуется в логи на одну и ту же неполученную блокировку иногда много-много раз. А это означает, что мы учли время ее ожидания кратно количеству таких записей в логе, что совсем не соответствует желаемому.
Помни о цели!
Собственно, а зачем мы вообще для каждой записи ожидания ищем связанную? Мы же хотим узнать, сколько заняло ожидание, а оно прямо записано в
lock-acquire
. Так давайте сразу отбирать
только их, тогда будет всего лишь один Index Scan
правильно?Почти, да не совсем. Дело в том, что под нагрузкой лог-процесс может пропускать любые из записей хоть о начале ожидания блокировке, хоть о факте ее получения:
Так неужели нет способа за одно чтение сразу получить все нужные нам данные?
Window Functions: семерых одним ударом
На помощь нам придут оконные функции.
А конкретнее модель выделения цепочек в готовой выборке из статьи SQL HowTo: собираем цепочки с помощью window functions.
Сначала поймем, что условием окончания цепочки то есть сегмента подряд идущих по ключу
(host, lock, pid, mode)
записей
блокировки для нас является или явное возникновение event
= 'lock-acquire'
или (что очень редко, но бывает)
начало нового сегмента блокировки того же объекта, чья
длительность (exectime
) начала считаться заново.Также надо учесть тот факт, что время может совпадать для нескольких записей лога даже с одного PID. В этом случае надо дополнительно сортировать по
exectime
, чтобы получить
правильную последовательность:
-- формируем условие окончания блокировкиWITH lc AS ( SELECT * , CASE WHEN event = 'lock-wait' THEN exectime > coalesce(lead(exectime) OVER(PARTITION BY lock, pid, mode ORDER BY ts, exectime), 0) -- "перелом" времени ожидания ELSE TRUE -- 'lock-acquire' - блокировка получена END cond -- условие окончания "цепочки" FROM lock lc WHERE event <> 'deadlock-detect' AND -- исключаем все deadlock ( lc.dt , lc.host ) = ( '2020-06-19'::date , 'e828a54d-7e8a-43dd-b213-30c3201a6d8e'::uuid ))-- оставляем только "последние" записи - их exectime и есть время ожидания "всей" блокировкиSELECT ts, pid, event, type, mode, lock, exectimeFROM lcWHERE cond;
Теперь мы прочитали всего 8MB данных (в 100 раз меньше!), чуть-чуть уменьшив итоговое время выполнения.
Его можно уменьшить еще, если создать индекс, идеально подходящий под
OVER
(то есть включающий lock, pid, mode,
ts, exectime
), избавившись от Sort
-узла.
Но обычно поле в индексе за timestamp делать не стоит.