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

Предисловие

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

Немного о внутреннем устройстве бэкэнда

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

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

Как проявляется Deadlock

Когда у нас возникает 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 id = 2;
      Process 18254: update users set balance = balance + 10 where id = 3;

HINT: See server log for query details.
CONTEXT: while updating tuple (0,9) in relation "users"

И, наконец, запрос, на котором произошла ошибка:
STATEMENT: update users set balance = balance + 10 where id = 2;


Логирование запросов при этом не обязано быть включено.

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

Ручной захват

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

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

  SELECT * FROM pg_stat_activity;

• Результаты положить в доступное для просмотра разработчиками хранилище. Например отправить по Sentry как ошибку.

from contextlib import contextmanager

from sqlalchemy import create_engine
from sqlalchemy.exc import OperationalError

engine = create_engine('postgresql+psycopg2://postgres:12345678@localhost/postgres')


def log_pg_stat_activity():
    '''Log, write or send through Sentry pg_stat_activity'''
    debug_conn = engine.connect()
    for process in debug_conn.execute('''
        SELECT pid, application_name, state, query FROM pg_stat_activity;
    ''').fetchall():
        print(process)

@contextmanager
def connection():
    conn = engine.connect()
    try:
        yield conn
    except OperationalError as ex:
        log_pg_stat_activity()
        raise


@contextmanager
def transaction():
    with connection() as conn:
        with conn.begin() as trans:
            try:
                yield conn
            except OperationalError as ex:
                if 'deadlock detected' in ex.args[0]:
                    log_pg_stat_activity()
                    # Log exception
                    print(ex)
                    trans.rollback()
                else:
                    raise

from multiprocessing import Process
from time import sleep
from threading import Thread

from sqlalchemy.orm import sessionmaker

from db import transaction


def process1():
    with transaction() as tran:
        tran.execute('UPDATE users SET balance = balance + 10 WHERE id = 3;')
        sleep(1)
        tran.execute('UPDATE users SET balance = balance + 10 WHERE id = 1 RETURNING pg_sleep(1);')


def process2():
    with transaction() as tran:
        tran.execute('UPDATE users SET balance = balance + 10 WHERE id = 1;')
        sleep(1)
        tran.execute('UPDATE users SET balance = balance + 10 WHERE id = 3 RETURNING pg_sleep(1);')


if __name__ == '__main__':
    p1 = Thread(target=process1)
    p2 = Thread(target=process2)
    p1.start()
    p2.start()
    sleep(4)

Или на github ^[3].

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

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

application_name

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

Сказано, сделано!

from traceback import extract_stack
@contextmanager
def transaction(application_name=None):
    with connection() as conn:
        if application_name is None:
            caller = extract_stack()[-3]
            conn.execution_options(autocommit=True).execute("SET application_name = %s", '%s:%s' % (caller[0], caller[1]))
        with conn.begin() as trans:
            try:
                yield conn
            except OperationalError as ex:
                if 'deadlock detected' in ex.args[0]:
                    log_pg_stat_activity()
                    # Log exception
                    print(ex)
                    trans.rollback()
                else:
                    raise

Или на github ^[4].

Вуаля. Теперь можно быстро открывать файлы в нужных местах и смотреть код.

Думаем о серверных логах

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

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

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

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

Несколько практик избегания deadlock`ов

Частый случай №1: Классический дедлок

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

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

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

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

Частый случай №2: Сам себе злобный буратино (ССЗБ)

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

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

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

Возьмём пример:

--P1: 
BEGIN;
--P2: 
BEGIN;
--P1: 
SELECT id FROM clans WHERE id=1 FOR UPDATE;
--P2: 
INSERT INTO users(clan_id, name) VALUES(1, 'Alpha');

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

Бонус №1

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

Бонус №2

Вернёмся к ещё одной любопытной детали из первоначальной ошибки:
CONTEXT: while updating tuple (0,9) in relation "users"
Что за тупл спросите вы? Это физический адрес строчки в таблице, из-за которой возник конфликт. Дело в том, что в каждой таблице есть служебные поля, которые запросом SELECT * не выбираются. Однако стоит явно указать к примеру ctid среди полей, как мы увидим этот самый тупл:

SELECT ctid, id, nickname, balance FROM public.users;

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

Что почитать

• Deadlocks in PostgreSQL ^[5] — описание всех видов блокировок
• Explicit locking ^[6] или Явные блокировки ^[7] (на русском). Более подробнее о блокировках.
  Lock Monitoring ^[8] — скрипты, показывающие как мониторить блокировки
  System Columns ^[9] — про скрытые служебные поля в таблицах
  Introduction to PostgreSQL physical storage ^[10] — про физическое хранение данных в PostgreSQL

Автор: Wargaming

Источник ^[11]