13.07.2017 06:47
gnomeby 27 7700 Источник

Предисловие


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

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



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


  • Основная база данных — 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, а старая строчка помечается как невидимая и позже будет удалена автовакуумом). Но знать стоит, вдруг когда-нибудь пригодится.

Что почитать


Поделиться с друзьями
-->

Комментарии (27)


  1. AndyKorg
    13.07.2017 12:02
    #10310436

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

    ИМХО: обычно сочетание «уникальный ключ» и «внешний ключ другой таблицы» говорят о том, что это хороший кандидат на первичный ключ. И если приходится делать update первичного ключа, то это сигнал о проблеме в архитектуре БД.


    1. gnomeby
      13.07.2017 12:06
      #10310444
      +2

      Это и есть первичный ключ, просто для СУБД он не обязан быть именно первичным.
      UPDATE первичного ключа конечно же никто не делает, но если вы делаете SELECT… FOR UPDATE, то СУБД допускает, что вы можете и такое.


  1. FractalizeR
    13.07.2017 14:35
    #10310694
    +1

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

    Мне кажется, на более-менее серьезных проектах такие проблемы недопустимы. У вас может не быть непосредственного доступа на сервер, но доступ к логам быть обязан. Для этого можно агрегировать логи в ELK стек. Или как-то еще централизованно хранить. Но ситуации, при которой логов нужно ждать ДЕНЬ(!) возникать в работе не должно. А если такая ситуация возникает с пугающей регулярностью, надо все бросать и немедленно принимать меры.


    1. gnomeby
      13.07.2017 15:19
      #10310812
      +1

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


      1. FractalizeR
        13.07.2017 16:18
        #10310988

        Но ведь ее можно удалить из логов перед отправкой, верно?


        1. gnomeby
          13.07.2017 17:27
          #10311152
          +1

          Честно говоря я не знаю способа делать это на лету и при постоянно меняющейся схеме. Может поделитесь соображениями?


      1. sl_bug
        13.07.2017 16:19
        #10310994

        А почему такая важная информация вообще в логах?


        1. gnomeby
          13.07.2017 17:22
          #10311132

          Email пользователя например. У вас упал Update на обновление контактных данных и он может быть засвечен.


          1. gnomeby
            13.07.2017 17:25
            #10311148

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


          1. RomanArzumanyan
            13.07.2017 17:38
            #10311180

            Автоматическая фальсификация чувствительных данных при логировании возможна?


            1. gnomeby
              13.07.2017 18:02
              #10311222

              В теории да, регулярками. На практике легко что-то упустить при очередном апдейте.


        1. gnomeby
          13.07.2017 18:06
          #10311238

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

          Вот мы руководствовались третьим соображением и немного вторым.


    1. ggo
      14.07.2017 09:54
      #10312180

      Проблема с доступом к логам, как правило, не техническая, а организационно-административная.
      Есть ли в логах чувствительная к разглашению информация? Кто к ней должен иметь доступ? Система в скоупе PCI DSS? И т.д.


  1. Duss
    13.07.2017 15:10
    #10310770
    +1

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


    Если права и доступы четко разграничены, значит скорее всего у вас также разграничены зоны ответственности.
    Админы, девупсы, разработчики, архитекторы и т.д. Также используется система непрерывного развертывания, гит и т.д. и т.п. Не суть на самом деле.
    Проблема с логами решается на уровне админов/девупсов, которые заводят в jenkins таску, выгружающаю с прода нужный кусок лога или весь лог за какой-то день. Доступ к этой джобу в jenkins дается разработчикам, чтобы они могли в кратчайшие сроки выгрузить то, что им нужно.
    Еще можно прикрутить Zabbix и мониторить любые ошибки базы, в случае появления которых запускать джобу и получать все логи на почту еще до того как о проблеме будет известно широкому кругу заинтересованных лиц.


    1. gnomeby
      13.07.2017 15:21
      #10310822

      Да, согласен, ну а мы поступили описанным способом и имеем гораздо более подробную информацию о происходящем и в гораздо более описательном виде.


      1. FractalizeR
        13.07.2017 16:19
        #10310992

        … но через день после запроса?


        1. gnomeby
          13.07.2017 17:20
          #10311130

          При применении описанных рецептов и отправке по sentry почти сразу.


    1. MaEcTPo
      14.07.2017 10:31
      #10312250

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


      1. gnomeby
        14.07.2017 13:01
        #10312614

        Не буду утверждать так голословно за всю компанию, но в моём отделе всё описанное вами не соответствует действительности.


        1. MaEcTPo
          14.07.2017 13:16
          #10312676

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


          1. gnomeby
            14.07.2017 14:03
            #10312798

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


      1. Wargaming
        14.07.2017 13:19
        #10312686

        Привет! Наши разработчики постоянно работают с продакшеном, и базами в том числе. Деплой и разработка все вместе контролируют и обмениваются статистикой. Также нет проблем и с админами. Наверное, бывают разные случаи, но в целом все работает именно так.


      1. Duss
        14.07.2017 17:36
        #10313220

        У нас есть специально обученные люди), занимающиеся разбором происшествий на проде.
        Они не занимаются кодингом, но имеют доступ к исходникам или части кода, который был изменен в тои или иной таске, например. Также имеют доступ к продовским БД, но тоже с ограничениями. Для чтения, не ко всем таблицам или столбцам порой к реплике продовской базы. Также могут быстро получать логи нужных систем через таски в jenkins.
        Понятно, что у них в нужный момент может не оказаться всего, что нужно для разбора инцидента, но много что есть. и если чего-то нет, быстрый доступ может появиться. Но также как у вас, через день, 2)
        Это своеобразный саппорт IT отдела (именно отделка не клиентский саппорт).
        Т.е. у них есть доступ, но изменить они ничего не могут, персональные данные тоже прикрыты, весь код унести также не получится.


  1. laxikodeje
    14.07.2017 10:22
    #10312232

    Всё это неизбежно приводит к дедлокам


    Неправильная архитектура.
    Если код из примера реальный, то это жесть…
    Неправильный выбор инструмента для решения вашей задачи.
    Девелоперы — не очень.
    Но админы молодцы, интересно.


    1. gnomeby
      14.07.2017 10:29
      #10312248
      +2

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


      1. laxikodeje
        15.07.2017 11:45
        #10313766

        ОК, понятно что в отделе разработки сами тоже админовской частью занимаются.
        Я вот за эту работу и нахваливаю.
        А конструкции update users set balance =… как в вашем примере — это на ваших масштабах ужос. Для мелкосайтиков, да, годится.


        1. gnomeby
          15.07.2017 12:23
          #10313780
          +1

          А что такого ужасного в этой конструкции, на наших масштабах?