Ранее мы уже научились перехватывать блокировки из лога сервера PostgreSQL. Давайте теперь положим их в БД и разберем, какие фактические ошибки и проблемы производительности можно допустить на примере их простейшего анализа.

В логах у нас отражается всего 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
  ) T
WHERE
  (
    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
, exectime
FROM
  lc
WHERE
  cond;



Теперь мы прочитали всего 8MB данных (в 100 раз меньше!), чуть-чуть уменьшив итоговое время выполнения.

Его можно уменьшить еще, если создать индекс, идеально подходящий под OVER (то есть включающий lock, pid, mode, ts, exectime), избавившись от Sort-узла. Но обычно поле в индексе «за timestamp» делать не стоит.