Хабрахабр

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

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

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

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

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


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

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

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

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:

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

Если установленная версия 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 lcxJOIN pg_locks lc ON lc.pid IN (lcx.ldp, lcx.lrp);

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

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

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

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

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

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

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

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 conflictFROM lcxJOIN 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 | frelation | {423576026} | f | 216547 | AccessShare | t | fadvisory | {225386226,194303167,2} | t | 24964 | Exclusive | f | trelation | {341894815} | t | 24964 | AccessShare | t | frelation | {416441672} | f | 216547 | AccessShare | t | frelation | {225964322} | f | 216547 | AccessShare | t | f...

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

SELECT $1::oid::regclass;

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

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

«Все само»

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

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)

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

Теги
Показать больше

Похожие статьи

Добавить комментарий

Ваш адрес email не будет опубликован. Обязательные поля помечены *

Кнопка «Наверх»
Закрыть