Как мы ловим Deadlock`и на PostgreSQL и чиним их

Ситуация: есть высоконагруженная мета-игра для наших танков под названием Глобальная карта. Эдакая пошаговая настолка для команд, где бои происходят в реальном танковом клиенте. В пиковые часы на карте несколько тысяч руководителей кланов производят игровые действия: атакуют друг друга, перемещают дивизии, покупают, продают, грабят корованы. Помимо этого, существует десяток сервисов, которые также могут вносить изменения в игровую ситуацию: подкидывают деньжат, штрафуют, добавляют игроков в клан и прочее.

Всё это неизбежно приводит к дедлокам. Так вот, хочу вам поведать историю о том, как мы эти периодические проблемы держим в допустимых рамках.

• Основная база данных — PostgreSQL 9.5.
• Уровень изоляции транзакций — стандартный по умолчанию READ COMMITED.
• ORM — SQLAlchemy.

Часть 1: Мониторинг

Когда у нас возникает Deadlock, то падает исключение следующего вида:

ERROR: deadlock detected DETAIL: Process 18293 waits for ShareLock on transaction 639; blocked by process 18254. Process 18254 waits for ShareLock on transaction 640; blocked by process 18293. HINT: See server log for query details. CONTEXT: while updating tuple (0,9) in relation "users" Первое, на что следует обратить внимание, — это строчка: HINT: See server log for query details.

Действительно, если мы посмотрим серверные логи, то увидим для этого же места следующее: ERROR: deadlock detected И дальше конкретику:

DETAIL: Process 18293 waits for ShareLock on transaction 639; blocked by process 18254. Process 18254 waits for ShareLock on transaction 640; blocked by process 18293. Process 18293: update users set balance = balance + 10 where > Process 18254: update users set balance = balance + 10 where > HINT: See server log for query details. CONTEXT: while updating tuple (0,9) in relation "users" И, наконец, запрос, на котором произошла ошибка:

STATEMENT: update users set balance = balance + 10 where >

Круто. Но первая глобальная проблема для любого более-менее серьёзного проекта — то, что у вас нет доступа к серверным логам вследствие политики безопасности. Иногда вообще нет никакого доступа. А иногда можно попросить участок, но надо ждать. Иногда это 30 минут, иногда день.

А хотелось бы получать такую информацию сразу. В особенности, если у вас в проекте есть Sentry, и большинство ошибок команда разработки получает сразу.

Как-то подкрутить сервер, чтобы он такую информацию выдавал обычным клиентам — нельзя. Вследствие политики безопасности разработчиков базы. Но, если у вашего пользователя к базе доступ обычный, без всяких там ограничений на выполнения служебных функций и без Row-Level security policies, то организовать себе доступ к подобной информации всё же можно.

Мы можем преобразовать наши классы так, чтобы вручную получать похожую информацию. И даже больше. Для этого после отлова исключения о дедлоке, нам необходимо:

• Временно ничего не откатывать в текущем соединении с базой и вообще ничего не трогать там.
• Создать ещё одно соединение и выполнить в нём простейший запрос:

deadlock_test.py

В данном случае у нас есть высокая вероятность того, что мы увидим какой именно запрос сломал нам транзакцию, вычислив его по PID и посмотрев текущий query.

Но бывает и так, что вычислив соединение по PID и посмотрев на query вы можете увидеть совсем не тот query, который устроил нам дедлок, а какой-нибудь следующий за ним по логике. Ведь пока вы ловили исключение и открывали соединение, нужный нам запрос для отлова мог и завершиться. Всё что мы можем здесь сделать — это работать через pgBouncer или его аналоги для минимизации времени установления соединения и использовать application_name.

Даже если вы получили тот запрос, который вызвал дедлок, у вас всё равно могут возникнуть трудности с пониманием, в каком месте логики он был вызван. И вот здесь на помощь приходит поле application_name. По умолчанию оно инициализируется не сильно полезной информацией, но его можно менять. А что если писать туда то место, откуда мы начинали транзакцию?

Вуаля. Теперь можно быстро открывать файлы в нужных местах и смотреть код. pid application_name state query 1 8613 deadlock_test.py:10 idle in transaction (aborted) UPDATE users SET balance = balance + 10 WHERE RETURNING pg_sleep(1); 2 8614 deadlock_test.py:17 active UPDATE users SET balance = balance + 10 WHERE RETURNING pg_sleep(1); 3 8617 active SELECT pid, application_name, state, query FROM pg_stat_activity;

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

• Обговорить понятную процедуру получения нужных участков серверных логов в разумное время с заинтересованными сторонами.
• Делать их в требуемом вами формате, изменив log_line_prefix в postgresql.conf. На машине разработчика например можно так: log_line_prefix = 'APP:%a PID:%p TR:%x ' .

Часть 2: Как бороться с дедлоками

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

Самый наш частый случай следующий:

• Происходит игровое действие, затрагивающее сразу несколько игроков.
• При этом игроки нередко могут совершать несколько действий в одно и то же время. Например, у нас: у крупных кланов есть много подразделений, участвующих в боях.
• При выигрыше или проигрыше начисляются очки клану. И таких начислений параллельно может быть очень много.

Всё что тут можно сделать: или выстраивать начисления в цепочку, но это медленно, или позволять начислениям падать и пробовать начислить чуть позже.

У нас походовая игра. Раз в ход происходит пересчёт баланса игроков, учитывая большое количество совершённых ими игровых действий. На время изменения баланса мы блокировали другие изменения через SELECT… FOR UPDATE. Хотя мы блокировали не сразу всех, а чанками по 100, всё равно иногда уходили в дедлок с процессом, который начисляет бонусы за бой, который не останавливается на время расчёта хода.

Так вот, оказалось, что мы были неправы. SELECT… FOR UPDATE — слишком мощная блокировка, необходимая только если выполняются 2 условия:

• Условный id текущей таблицы используется как внешний ключ в другой.
• Этот же условный id может быть изменён/удалён в результате дальнейших действий.

P2 в данной ситуации повиснет, поскольку мы даём СУБД понять, что запись с может перестать существовать. Однако в P1 мы не делаем ничего такого, только хотим защитить баланс клана от изменений. Поэтому, когда мы изменили FOR UPDATE на FOR NO KEY UPDATE, мы перестали ловить дедлоки.

SELECT… FOR UPDATE в примере выше вызван явно. Но вы получите аналогичный эффект, если затронете своими изменениями уникальный ключ, на который ссылается внешний ключ из других таблиц. А любой UPDATE, который не затрагивает своими изменениями подобные ключи, вызовет блокировку аналогичную SELECT… FOR NO KEY UPDATE. Я вам рекомендую ознакомиться с этими особенностями в статье «Явные блокировки» в списке литературы ниже.

Вернёмся к ещё одной любопытной детали из первоначальной ошибки:

CONTEXT: while updating tuple (0,9) in relation "users"

Что за тупл спросите вы? Это физический адрес строчки в таблице, из-за которой возник конфликт. Дело в том, что в каждой таблице есть служебные поля, которые запросом SELECT * не выбираются. Однако стоит явно указать к примеру ctid среди полей, как мы увидим этот самый тупл:

Пользы от него немного в случае дедлока, ибо разблокированный процесс скорее всего обновит конфликтную строчку, и у неё изменится этот ctid (поскольку любой UPDATE в PostgreSQL на самом деле INSERT, а старая строчка помечается как невидимая и позже будет удалена автовакуумом). Но знать стоит, вдруг когда-нибудь пригодится.