DBA: в погоне за пролетающими блокировками27.05.2020 11:17

В прошлой статье, где я рассказывал о мониторинге БД PostgreSQL, была такая фраза:

Растут wait — приложение в кого-то «уперлось» на блокировках. Если это уже прошедшая разовая аномалия — повод разобраться в исходной причине.

Такая ситуация — одна из самых неприятных для DBA:

  • на первый взгляд, база работает
  • никакие ресурсы сервера не исчерпаны
  • … но часть запросов при этом «подтормаживает»

jywaskrftah-9f7d9xwp3jvkn_q.png
Шансов поймать блокировки «в моменте» крайне мало, да и длиться они могут всего по несколько секунд, но ухудшая при этом плановое время выполнения запроса в десятки раз. А хочется-то не сидеть и ловить происходящее в онлайн-режиме, а в спокойной обстановке разобраться постфактум, кого из разработчиков покарать в чем именно была проблема — кто, с кем и из-за какого ресурса базы вступил в конфликт.

Но как? Ведь, в отличие от запроса с его планом, который позволяет детально понять, на что пошли ресурсы, и сколько времени это заняло, подобных наглядных следов блокировка не оставляет после себя…

Разве что короткую запись в логе:

process ... still waiting for ...

А давайте попробуем зацепиться именно за нее!

Ловим блокировку в лог


Но даже чтобы хотя бы эта строка оказалась в логе, сервер надо правильно настроить:

log_lock_waits = 'on'

… и установить минимальную границу для нашего анализа:

deadlock_timeout = '100ms'

Когда включён параметр log_lock_waits, данный параметр также определяет, спустя какое время в журнал сервера будут записываться сообщения об ожидании блокировки. Если вы пытаетесь исследовать задержки, вызванные блокировками, имеет смысл уменьшить его по сравнению с обычным значением deadlock_timeout.

Все deadlock, не успевшие «развязаться» за это время будут разорваны. А вот «обычные» блокировки — сброшены в лог несколькими записями:

2019-03-27 00:06:46.026 MSK [38162:84/166010018] [inside.tensor.ru] [local] csr-inside-bl10:10081: MergeRequest LOG: process 38162 still waiting for ExclusiveLock on advisory lock [225382138,225386226,141586103,2] after 100.047 ms

2019-03-27 00:06:46.026 MSK [38162:84/166010018] [inside.tensor.ru] [local] csr-inside-bl10:10081: MergeRequest DETAIL: Process holding the lock: 38154. Wait queue: 38162.

2019-03-27 00:06:46.026 MSK [38162:84/166010018] [inside.tensor.ru] [local] csr-inside-bl10:10081: MergeRequest CONTEXT: SQL statement "SELECT pg_advisory_xact_lock( '"Документ"'::regclass::oid::integer, 141586103::integer )"
PL/pgSQL function inline_code_block line 2 at PERFORM

2019-03-27 00:06:46.026 MSK [38162:84/166010018] [inside.tensor.ru] [local] csr-inside-bl10:10081: MergeRequest STATEMENT: DO $$ BEGIN
PERFORM pg_advisory_xact_lock( '"Документ"'::regclass::oid::integer, 141586103::integer );
EXCEPTION
WHEN query_canceled THEN RETURN;
END; $$;
…

2019-03-27 00:06:46.077 MSK [38162:84/166010018] [inside.tensor.ru] [local] csr-inside-bl10:10081: MergeRequest LOG: process 38162 acquired ExclusiveLock on advisory lock [225382138,225386226,141586103,2] after 150.741 ms

В этом примере видно, что у нас было всего 50мс от момента появления блокировки в логе до момента ее разрешения. Только в этом интервале мы можем получить хоть какую-то информацию о ней, и чем быстрее мы способны это делать — тем больше блокировок сможем проанализировать.

Тут самая важная для нас информация — это PID процесса, который ждет блокировку. Именно по нему мы можем сопоставить информацию между логом и состоянием базы. А заодно узнать, насколько проблемной была конкретная блокировка — то есть сколько времени она «висела».

Для этого нам достаточно всего пары RegExp на контент LOG-записи:

const RE_lock_detect = /^process (\d+) still waiting for (.*) on (.*) after (\d+\.\d{3}) ms(?: at character \d+)?$/; // ловим факт начала блокировки
const RE_lock_acquire = /^process (\d+) acquired (.*) on (.*) after (\d+\.\d{3}) ms(?: at character \d+)?$/; // ловим момент окончания


Докапываемся до лога


Собственно, осталось немного — взять лог, научиться его мониторить и соответствующим образом реагировать.

У нас-то для этого уже все есть — и онлайн-парсер лога, и заранее активированное соединение с БД, про которые я рассказывал в статье о нашей системе мониторинга PostgreSQL:
tcpvoqmeliadskfh2rpnffg7uwo.png

Но если у вас никакой аналогичной системы не развернуто — не беда, сделаем все «прямо с консоли»!

Если установленная версия PostgreSQL 10 и выше — повезло, поскольку там появилась функция pg_current_logfile(), которая в явном виде отдает имя текущего файла лога. Получить его из консоли будет достаточно легко:

psql -U postgres postgres -t -A -c "SELECT CASE WHEN substr(current_setting('log_directory'), 1, 1) <> '/' THEN current_setting('data_directory') ELSE '' END || '/' || pg_current_logfile()"


Если версия вдруг младше — все получится, но чуть сложнее:

ps uw -U postgres \
  | grep [l]ogger \
  | awk '{print "/proc/"$2"/fd"}' \
  | xargs ls -l \
  | grep `cd; psql -U postgres postgres -t -A -c "SELECT CASE WHEN substr(current_setting('log_directory'), 1, 1) = '/' THEN current_setting('log_directory') ELSE current_setting('data_directory') || '/' || current_setting('log_directory') END"` \
  | awk '{print $NF}'


Получим полное имя файла, которое отдадим в tail -f и будем ловить там появление 'still waiting for'.

Ну а как только что-то возникло в этом потоке — вызываем…

Анализирующий запрос


Увы, объект блокировки в логе далеко не всегда является именно тем ресурсом, из-за которого возник конфликт. Например, если попытаться параллельно создать одноименный индекс, в логе будет только что-то вроде still waiting for ExclusiveLock on transaction 12345.

Поэтому нам придется снимать состояние всех блокировок с базы для интересующего нас процесса. Да и информации только о паре процессов (кто наложил блокировку / кто ее ожидает) — недостаточно, ведь нередко случается «цепочка» ожиданий разных ресурсов между транзакциями:

tx1 [resA] -> tx2 [resA]
tx2 [resB] -> tx3 [resB]
...


Классика: «Дедка за репку, бабка за дедку, внучка за бабку, ...»

Поэтому напишем запрос, который нам точно скажет, кто же стал первопричиной бед по всей цепочке блокировок для конкретного PID:

WITH RECURSIVE lm AS (
-- lock modes
  SELECT
    rn
  , CASE
      WHEN lm <> 'Share' THEN row_number() OVER(PARTITION BY lm <> 'Share' ORDER BY rn)
    END rx
  , lm || 'Lock' lm
  FROM (
    SELECT
      row_number() OVER() rn
    , lm
    FROM
      unnest(
        ARRAY[
          'AccessShare'
        , 'RowShare'
        , 'RowExclusive'
        , 'ShareUpdateExclusive'
        , 'Share'
        , 'ShareRowExclusive'
        , 'Exclusive'
        , 'AccessExclusive'
        ]
      ) T(lm)
  ) T
)
-- lock types
, lt AS (
  SELECT
    row_number() OVER() rn
  , lt
  FROM
    unnest(
      ARRAY[
        'relation'
      , 'extend'
      , 'page'
      , 'tuple'
      , 'transactionid'
      , 'virtualxid'
      , 'object'
      , 'userlock'
      , 'advisory'
      , ''
      ]
    ) T(lt)
)
-- lock modes conflicts
, lmx AS (
  SELECT
    lr.rn lrn
  , lr.rx lrx
  , lr.lm lr
  , ld.rn ldn
  , ld.rx ldx
  , ld.lm ld
  FROM
    lm lr
  JOIN
    lm ld ON
      ld.rx > (SELECT max(rx) FROM lm) - lr.rx OR
      (
        (lr.rx = ld.rx) IS NULL AND
        (lr.rx, ld.rx) IS DISTINCT FROM (NULL, NULL) AND
        ld.rn >= (SELECT max(rn) FROM lm) - lr.rn
      )
)
-- locked targets/pids
, lcx AS (
  SELECT DISTINCT
    (lr.locktype, lr.database, lr.relation, lr.page, lr.tuple, lr.virtualxid, lr.transactionid::text::bigint, lr.classid, lr.objid, lr.objsubid) target
  , ld.pid  ldp
  , ld.mode ldm
  , lr.pid  lrp
  , lr.mode lrm
  FROM
    pg_locks ld
  JOIN
    pg_locks lr ON
      lr.pid <> ld.pid AND
      (lr.locktype, lr.database, lr.relation, lr.page, lr.tuple, lr.virtualxid, lr.transactionid::text::bigint, lr.classid, lr.objid, lr.objsubid) IS NOT DISTINCT FROM (ld.locktype, ld.database, ld.relation, ld.page, ld.tuple, ld.virtualxid, ld.transactionid::text::bigint, ld.classid, ld.objid, ld.objsubid) AND
      (lr.granted, ld.granted) = (TRUE, FALSE)
  JOIN
    lmx ON
      (lmx.lr, lmx.ld) = (lr.mode, ld.mode)
  WHERE
    (ld.pid, ld.granted) = ($1::integer, FALSE) -- PID
)
SELECT
  lc.locktype "type"
, CASE lc.locktype
    WHEN 'relation'      THEN ARRAY[relation::text]
    WHEN 'extend'        THEN ARRAY[relation::text]
    WHEN 'page'          THEN ARRAY[relation, page]::text[]
    WHEN 'tuple'         THEN ARRAY[relation, page, tuple]::text[]
    WHEN 'transactionid' THEN ARRAY[transactionid::text]
    WHEN 'virtualxid'    THEN regexp_split_to_array(virtualxid::text, '/')
    WHEN 'object'        THEN ARRAY[classid, objid, objsubid]::text[]
    WHEN 'userlock'      THEN ARRAY[classid::text]
    WHEN 'advisory'      THEN ARRAY[classid, objid, objsubid]::text[]
  END target
, lc.pid = lcx.ldp "locked"
, lc.pid
, regexp_replace(lc.mode, 'Lock$', '') "mode"
, lc.granted
, (lc.locktype, lc.database, lc.relation, lc.page, lc.tuple, lc.virtualxid, lc.transactionid::text::bigint, lc.classid, lc.objid, lc.objsubid) IS NOT DISTINCT FROM lcx.target "conflict"
FROM
  lcx
JOIN
  pg_locks lc ON
    lc.pid IN (lcx.ldp, lcx.lrp);


Проблема #1 — медленный старт


Как видно в примере из лога, следом за строкой, сигнализирующей о возникновении блокировки (LOG), идет еще 3 строки (DETAIL, CONTEXT, STATEMENT), сообщающих расширенную информацию.

Сначала мы дожидались формирования полного «пакета» из всех 4 записей и только после этого обращались к базе. Но завершить формирование пакета мы можем только при приходе следующей (уже 5й!) записи, с реквизитами другого процесса, или по таймауту. Понятно, что и тот и другой варианты провоцируют лишнее ожидание.

Чтобы избавиться от этих задержек, мы перешли на потоковую обработку записей о блокировках. То есть теперь мы обращаемся к целевой базе сразу, как только разобрали первую же запись, и поняли, что там описана именно блокировка.

Проблема #2 — медленный запрос


Но все равно часть блокировок не успевала проанализироваться. Стали копать глубже — и выяснили, что на некоторых серверах наш анализирующий запрос выполняется по 15-20мс!

Причина оказалась банальной — общее количество активных блокировок на базе, доходящее до нескольких тысяч:

lkspexwtgdfrqhmh3siwsnx_s30.png

pg_locks


Тут надо заметить, что блокировки в PostgreSQL нигде не «хранятся», а представлены только в системном view pg_locks, которое является прямым отражением функции pg_lock_status. А мы в своем запросе читаем из нее трижды! А пока мы читаем эти тысячи экземпляров блокировок, и отбрасываем те, которые не имеют отношения к нашему PID, сама блокировка успевала «рассосаться»…

Решением стала «материализация» состояния pg_locks в CTE — после этого по ней можно бегать сколько угодно раз, она уже не меняется. Причем, посидев над алгоритмом, удалось все свести всего к двум ее сканированиям.

Избыточная «динамика»


А если еще чуть внимательнее посмотреть на запрос выше, то можно заметить, что CTE lm и lmx вообще никак не завязаны на данные, а просто вычисляют всегда одну и ту же «статичную» матрицу определения конфликтов между режимами блокировок. Так давайте просто и зададим ее в качестве VALUES.

Проблема #3 — соседи


Но часть блокировок все равно пропускались. Обычно это получалось по следующей схеме — кто-то заблокировал популярный ресурс, а в него или по цепочке дальше быстро-быстро уперлось сразу несколько процессов.

В результате, мы ловили первый PID, шли на целевую базу (а чтобы не перегружать ее, мы держим только одно соединение), делали анализ, возвращались с результатом, брали следующий PID… А на базе-то жизнь не стоит, и блокировка по PID#2 уже пропала!

Собственно, а зачем нам ходить на базу по каждому PID отдельно, если мы все равно в запросе отфильтровываем блокировки из общего списка? Давайте возьмем сразу весь список конфликтующих процессов прямо с БД и их блокировки распределим по всем попавшимся за время выполнения запроса в лог PID'ам:

WITH lm(ld, lr) AS (
  VALUES
    ('AccessShareLock', '{AccessExclusiveLock}'::text[])
  , ('RowShareLock', '{ExclusiveLock,AccessExclusiveLock}'::text[])
  , ('RowExclusiveLock', '{ShareLock,ShareRowExclusiveLock,ExclusiveLock,AccessExclusiveLock}'::text[])
  , ('ShareUpdateExclusiveLock', '{ShareUpdateExclusiveLock,ShareLock,ShareRowExclusiveLock,ExclusiveLock,AccessExclusiveLock}'::text[])
  , ('ShareLock', '{RowExclusiveLock,ShareUpdateExclusiveLock,ShareRowExclusiveLock,ExclusiveLock,AccessExclusiveLock}'::text[])
  , ('ShareRowExclusiveLock', '{RowExclusiveLock,ShareUpdateExclusiveLock,ShareLock,ShareRowExclusiveLock,ExclusiveLock,AccessExclusiveLock}'::text[])
  , ('ExclusiveLock', '{RowShareLock,RowExclusiveLock,ShareUpdateExclusiveLock,ShareLock,ShareRowExclusiveLock,ExclusiveLock,AccessExclusiveLock}'::text[])
  , ('AccessExclusiveLock', '{AccessShareLock,RowShareLock,RowExclusiveLock,ShareUpdateExclusiveLock,ShareLock,ShareRowExclusiveLock,ExclusiveLock,AccessExclusiveLock}'::text[])
)
, locks AS (
  SELECT
    (
      locktype
    , database
    , relation
    , page
    , tuple
    , virtualxid
    , transactionid::text::bigint
    , classid
    , objid
    , objsubid
    ) target
  , *
  FROM
    pg_locks
)
, ld AS (
  SELECT
    *
  FROM
    locks
  WHERE
    NOT granted
)
, lr AS (
  SELECT
    *
  FROM
    locks
  WHERE
    target::text = ANY(ARRAY(
      SELECT DISTINCT
        target::text
      FROM
        ld
    )) AND
    granted
)
, lcx AS (
  SELECT DISTINCT
    lr.target
  , ld.pid ldp
  , ld.mode ldm
  , lr.pid lrp
  , lr.mode lrm
  FROM
    ld
  JOIN
    lr
      ON lr.pid <> ld.pid AND
        lr.target IS NOT DISTINCT FROM ld.target
)
SELECT
  lc.locktype "type"
, CASE lc.locktype
    WHEN 'relation' THEN
      ARRAY[relation::text]
    WHEN 'extend' THEN
      ARRAY[relation::text]
    WHEN 'page' THEN
      ARRAY[relation, page]::text[]
    WHEN 'tuple' THEN
      ARRAY[relation, page, tuple]::text[]
    WHEN 'transactionid' THEN
      ARRAY[transactionid::text]
    WHEN 'virtualxid' THEN
      regexp_split_to_array(virtualxid::text, '/')
    WHEN 'object' THEN
      ARRAY[classid, objid, objsubid]::text[]
    WHEN 'userlock' THEN
      ARRAY[classid::text]
    WHEN 'advisory' THEN
      ARRAY[classid, objid, objsubid]::text[]
  END target
, lc.pid = lcx.ldp as locked
, lc.pid
, regexp_replace(lc.mode, 'Lock$', '') "mode"
, lc.granted
, lc.target IS NOT DISTINCT FROM lcx.target as conflict
FROM
  lcx
JOIN
  locks lc
    ON lc.pid IN (lcx.ldp, lcx.lrp);


Теперь мы успеваем проанализировать даже блокировки, существующие всего 1-2 мс после попадания в лог.

Analyze This


Собственно, а ради чего мы так долго старались? Что нам это в результате дает-то?..

type     | target                  | locked | pid    | mode        | granted | conflict
---------------------------------------------------------------------------------------
relation | {225388639}             | f      | 216547 | AccessShare | t       | f
relation | {423576026}             | f      | 216547 | AccessShare | t       | f
advisory | {225386226,194303167,2} | t      |  24964 | Exclusive   | f       | t
relation | {341894815}             | t      |  24964 | AccessShare | t       | f
relation | {416441672}             | f      | 216547 | AccessShare | t       | f
relation | {225964322}             | f      | 216547 | AccessShare | t       | f
...


В этой табличке нам пригодятся значения target с типом relation, ведь каждое такое значение — OID таблицы или индекса. Теперь остается совсем немного — научиться опрашивать базу на предмет еще неизвестных нам OID, чтобы перевести их в человекопонятный вид:

SELECT $1::oid::regclass;


Теперь, зная полную «матрицу» блокировок и все объекты, на которые они были наложены каждой из транзакций, мы можем сделать вывод «что вообще происходило», и какой ресурс вызвал конфликт, даже если заблокировавший запрос нам остался неизвестен. Это легко может произойти, например, когда время выполнения блокирующего запроса недостаточно велико для попадания в лог, но транзакция после его завершения была активна и создавала проблемы еще долго.

4m4mj7nqgpeoxe13qoldzrmhhr8.png

Но про это — уже в другой статье.

«Все само»


А пока соберем полный вариант «мониторилки», который будет автоматически снимать для нашего архива состояние блокировок, как только в логе появляется что-то подозрительное:

ps uw -U postgres \
  | grep [l]ogger \
  | awk '{print "/proc/"$2"/fd"}' \
  | xargs ls -l \
  | grep `cd; psql -U postgres postgres -t -A -c "SELECT CASE WHEN substr(current_setting('log_directory'), 1, 1) = '/' THEN current_setting('log_directory') ELSE current_setting('data_directory') || '/' || current_setting('log_directory') END"` \
  | awk '{print $NF}' \
  | xargs -l -I{} tail -f {} \
  | stdbuf -o0 grep 'still waiting for' \
  | xargs -l -I{} date '+%Y%m%d-%H%M%S.%N' \
  | xargs -l -I{} psql -U postgres postgres -f detect-lock.sql -o {}-lock.log


А рядышком в detect-lock.sql кладем последний запрос. Запускаем — и получаем пачку файлов с искомым содержимым внутри:

# cat 20200526-181433.331839375-lock.log
     type      |     target     | locked |  pid   |     mode     | granted | conflict
---------------+----------------+--------+--------+--------------+---------+----------
 relation      | {279588430}    | t      | 136325 | RowExclusive | t       | f
 relation      | {279588422}    | t      | 136325 | RowExclusive | t       | f
 relation      | {17157}        | t      | 136325 | RowExclusive | t       | f
 virtualxid    | {110,12171420} | t      | 136325 | Exclusive    | t       | f
 relation      | {279588430}    | f      |  39339 | RowExclusive | t       | f
 relation      | {279588422}    | f      |  39339 | RowExclusive | t       | f
 relation      | {17157}        | f      |  39339 | RowExclusive | t       | f
 virtualxid    | {360,11744113} | f      |  39339 | Exclusive    | t       | f
 virtualxid    | {638,4806358}  | t      |  80553 | Exclusive    | t       | f
 advisory      | {1,1,2}        | t      |  80553 | Exclusive    | f       | t
 advisory      | {1,1,2}        | f      |  80258 | Exclusive    | t       | t
 transactionid | {3852607686}   | t      | 136325 | Exclusive    | t       | f
 extend        | {279588422}    | t      | 136325 | Exclusive    | f       | t
 extend        | {279588422}    | f      |  39339 | Exclusive    | t       | t
 transactionid | {3852607712}   | f      |  39339 | Exclusive    | t       | f
(15 rows)


Ну а дальше — садимся и анализируем…

© Habrahabr.ru