news.shamcode.ru | Как мы ловим Deadlock`и на PostgreSQL и чиним их

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

пятница, 14 июля 2017 г. в 03:12:21

https://habrahabr.ru/company/wargaming/blog/323354/

Python
PostgreSQL
Блог компании Wargaming

Предисловие

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

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

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

Основная база данных — 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, то организовать себе доступ к подобной информации всё же можно.

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

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

Временно ничего не откатывать в текущем соединении с базой и вообще ничего не трогать там.
Создать ещё одно соединение и выполнить в нём простейший запрос:
```
SELECT * FROM pg_stat_activity;
```
Результаты положить в доступное для просмотра разработчиками хранилище. Например отправить по Sentry как ошибку.

Пример: реализация сбора информации по дедлоку на SQLAlchemy

db.py

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

deadlock_test.py

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.

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

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

application_name

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

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

Пример: реализация установки application_name через SQLAlchemy

db.py

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.

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

	pid	application_name	state	query
1	8613	deadlock_test.py:10	idle in transaction (aborted)	UPDATE users SET balance = balance + 10 WHERE id = 1 RETURNING pg_sleep(1);
2	8614	deadlock_test.py:17	active	UPDATE users SET balance = balance + 10 WHERE id = 3 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: Как бороться с дедлоками

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

Несколько практик избегания 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 — описание всех видов блокировок
Explicit locking или Явные блокировки (на русском). Более подробнее о блокировках.
Lock Monitoring — скрипты, показывающие как мониторить блокировки
System Columns — про скрытые служебные поля в таблицах
Introduction to PostgreSQL physical storage — про физическое хранение данных в PostgreSQL