Ваш журнал показывает deadlock. Разбираемся

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

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

Про что этот текст

Мы уже писали детектив про вечерний пик, где виноватым оказался параллелизм. Тот текст про то, как найти настоящего виновника.

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

Ниже все четыре. Каждый наблюдался на одной системе, у крупной розничной сети.

Первый: одинаковый текст у двух разных причин

Вернусь к роботу и терминалу. Для терминала взаимоблокировка выглядела доказанной: в журнале по тем записям стоял 1205, это номер ошибки взаимоблокировки в MS SQL Server. Робот поднимает до десяти параллельных фоновых потоков на одну волну по одному справочнику. Гипотеза складывалась сама, и проверять её дальше стоило бы дней.

Оговорка, без которой дальше нельзя, и она же половина сюжета. Доказательство по терминалу у нас журнальное: код ошибки в записи журнала 1С. Граф дедлока из кольцевого буфера СУБД мы по этому пути не снимали, обе стороны конфликта и индекс на ресурсе данными сервера не подтверждены. Разница между "в журнале стоит 1205" и "есть граф с обеими сторонами" кажется формальной ровно до того момента, когда на слабом доказательстве строят план работ. Дальше по тексту я эту разницу буду держать явно, потому что она и есть тема статьи.

Так вот, собирать доказательства дедлока дальше мы не стали и пошли в противоположную сторону: расшили молчаливые Попытка…Исключение.

Настоящая ошибка всплыла на первом же прогоне:

Количество недоступно!

Бизнес-проверка. Не блокировка, не конкуренция.

Корень нашёлся быстро: рассинхрон двух регистров остатков. Один держал корректную физику, второй - залипшее значение "Отобрано". Формула проверки такая (имена ресурсов условные):

Доступно = Количество - Резерв - Изъятие - Отобрано

По одной позиции в первом регистре стояло Отобрано = 0, Доступно = 1, во втором - Отобрано = 1, Доступно = 0. Резерв прибавляется, расчётное "Доступно" уходит в минус, срабатывает исключение центральной процедуры.

Теперь про то, ради чего это здесь. Платформа выдаёт текст "В данной транзакции уже происходили ошибки" одинаково и на взаимоблокировку, и на проглоченную бизнес-ошибку. Одна строка в журнале, две принципиально разные причины.

Теперь те самые два счётчика. За полтора суток наблюдения в журнале набралось 24 записи "В данной транзакции уже происходили ошибки". Код 1205 стоит у 19 из них. Пять записей его не несут вообще.

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

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

Почему повтор в обработчике не помогает

Глушитель у нас стоял в двух местах: в подписке на событие перед записью и в самой записи остатков. Выглядел он привычно:

Попытка
    ЗаписатьОстатки(Набор);
Исключение
    // повтор: вдруг это была временная блокировка
    ЗаписатьОстатки(Набор);
КонецПопытки;

Замысел понятен: первая попытка не прошла из-за чужой транзакции, вторая пройдёт.

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

Повтор имеет смысл только снаружи транзакции, на уровне вызывающего кода, где можно начать её заново.

Расшивка минимальная: записать пойманное и отдать исключение наверх.

Попытка
    ЗаписатьОстатки(Набор);
Исключение
    ЗаписьЖурналаРегистрации("Диагностика.ЗаписьОстатков",
        УровеньЖурналаРегистрации.Ошибка, , ,
        ПодробноеПредставлениеОшибки(ИнформацияОбОшибке()),
        РежимЗаписиЖурналаРегистрации.Независимый);
    ВызватьИсключение;
КонецПопытки;

Три детали, каждая существенна.

ПодробноеПредставлениеОшибки(ИнформацияОбОшибке()) вместо ОписаниеОшибки(): второе даёт краткое представление, а нам нужен стек и исходный текст, ради которого всё затевалось.

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

ВызватьИсключение без параметров возбуждает обрабатываемое сейчас исключение. Здесь это исходная ошибка первой и единственной попытки - та, что нужна. Если написать ВызватьИсключение "не удалось записать", вы замените её своим текстом и снова ослепнете.

Всего таких точек у нас получилось три. Настоящая ошибка всплыла на первом же прогоне после правки.

Второй: буфер обнуляется переключением узла

Дедлоки в MS SQL Server живут в кольцевом буфере system_health. Про сам буфер и про то, как считать по нему частоты вместо разбора одного случая, я уже писал в Почему бесполезно разбирать один дедлок, там же готовый SQL. Коротко: буфер маленький, при шторме перетирается за минуты, снимать надо сразу.

Здесь про второе его свойство, которое в тот разбор не попало. Буфер сбрасывается при переключении основного узла. После переключения он пуст.

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

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

Третий: события под чужим именем базы

У нас работал собственный сборщик дедлоков. Он собирал, слал алерты, всё было хорошо ровно до момента, когда мы полезли разбирать накопленное.

Запрос по имени базы вернул ноль строк. Дедлоки при этом были, алерты приходили.

Причина - общий слушатель событий на группу баз: события писались под другим именем. На срабатывание алертов это не влияло, потому что алерт триггерился фактом события. А при разборе давало пустоту ровно там, где искали.

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

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

Четвёртый: зонд, который сам стал проблемой

Сработал алерт "старейшая активная транзакция открыта слишком долго" на складской базе. Ожидание было очевидным: искать сеанс прикладной системы, кто-то забыл закрыть транзакцию.

Искали не там, и всё это время транзакция спокойно висела.

Транзакцию держал сам коллектор мониторинга. Расширенный запрос по представлениям СУБД показал сеанс: клиентская программа - драйвер pymssql, логин технический, статус спящий, открытых транзакций одна, блокировок ноль. Последний выполненный запрос:

SELECT COUNT(*) FROM sys.dm_exec_requests
WHERE blocking_session_id <> 0 AND wait_time >= 5000

Это запрос сборщика блокировок. Зонд, который считает заблокированные сеансы, сам оказался старейшей открытой транзакцией в базе.

Транзакция была открыта около 394 500 секунд, то есть примерно четверо с половиной суток. Порог в его собственном запросе - пять тысяч миллисекунд. Свою транзакцию он держал порядка восьмидесяти тысяч таких порогов и ни разу себя не заметил.

Механизм

Драйвер по умолчанию работает без автофиксации. Даже запрос только на чтение на постоянном соединении оставляет открытую транзакцию, если после него не сделан commit() или rollback(). Соединение живёт в пуле, транзакция висит.

В исходнике похожего сборщика, найденном рядом, ровно это: постоянные соединения, execute() и fetchall(), фиксации нет.

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

Почему искали не там

Запрос коллектора считал агрегат без разбивки: максимум длительности по всем пользовательским процессам, без меток базы, сеанса, хоста и логина. Алерт сообщал число и молчал о том, чьё оно. Моё мнение после этой истории простое: алерт, который присылает длительность без имени виновника, стоит примерно ничего. Первое, что нужно от такого сообщения, - на кого идти смотреть, а длительность уже вторым полем.

И второе: фильтр "только пользовательские процессы" включает сам мониторинг. Технический логин коллектора - такой же пользовательский процесс, как любой другой, и зонд честно попадает в собственную выборку.

Как такой сеанс ищется руками

Признак простой и проверяется одним запросом: сеанс спит, транзакция у него открыта. Наличие строки в представлении транзакций сеанса означает активную транзакцию, статус "спящий" означает, что сеанс сейчас ничего не выполняет.

SELECT s.session_id, s.login_name, s.program_name,
       s.status, s.last_request_end_time
FROM sys.dm_exec_sessions AS s
JOIN sys.dm_tran_session_transactions AS t
  ON t.session_id = s.session_id
WHERE s.status = 'sleeping'
ORDER BY s.last_request_end_time

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

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

Общий механизм

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

Практический вывод: пустота бывает трёх видов. События не было, событие потеряно, событие лежит не там.

Границы того, что мы знаем

Честно про то, где наши данные кончаются.

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

Рост хранилища версий не измерен. Что открытая транзакция мешает его усечению - следует из устройства механизма. Насколько именно оно выросло за четверо суток, мы не замерили, и это главная дыра в четвёртом случае.

Исправление по коллектору предложено, но не подтверждено. Включить автофиксацию - это наша рекомендация по итогам разбора. Инцидент по ней не закрыт. Что правка применена и что после неё метрика старейшей транзакции вернулась в норму, подтверждения у нас нет: повторного замера на длинном окне никто не делал. Пишу это прямо, потому что в статье про недоверие к приборам "мы всё починили" без замера было бы смешно.

По первому случаю графа дедлока нет. Взаимоблокировка на пути терминала подтверждена кодом 1205 в журнале 1С, а не отчётом СУБД с обеими сторонами конфликта. Кольцевой буфер по тому пути не снимали. Для сюжета статьи это ничего не меняет, там речь про соседний путь, где дедлока не было вовсе. Но если кто-то захочет взять наш разбор терминала как образец доказательства, знайте: доказательство там на ступеньку слабее, чем принято считать достаточным.

Ни одно из четырёх не отменяет наблюдений. Но выводы про масштаб из них делать нельзя.

Гипотеза, которую пришлось выбросить

Дедлок 1205 на горячем регистре остатков.

Отбрасывать её было тяжело: на соседнем пути 1205 в журнале стоял, робот действительно поднимает до десяти параллельных потоков по одному справочнику, текст ошибки совпадает, симптом совпадает.

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

Отдельно про качество опоры. Гипотезу подпирал код ошибки в журнале, снятого графа под ней не было. То есть слабое доказательство с соседнего пути мы молча перенесли на путь робота, где не было и его. Так это обычно и происходит: доказательство не выдумывают, его берут рядом и не проверяют, к тому ли объекту оно относится.

Взаимоблокировка на пути терминала никуда не делась и осталась отдельной задачей. К падению робота она отношения не имела.

Что забрать себе

1. При "В данной транзакции уже происходили ошибки" сначала расшить молчаливые Попытка. Один текст на две причины, стоимость путей отличается на порядок.
2. Повтор внутри транзакции не спасает её никогда. Он только стирает причину.
3. Пустой буфер system_health смотреть на том узле, который был основным в нужное время.
4. Сверять различные имена баз в событиях со списком ожидаемых. Сумма по именам из самих событий сойдётся всегда и не покажет ничего.
5. Искать сеансы с открытой транзакцией и нулём блокировок отдельно: в блокировочные отчёты они не попадают по определению.
6. Хорошая гипотеза опаснее плохой. Плохую проверяют, хорошую защищают.

Открытый вопрос

Мой тезис: показаниям инструментов диагностики нельзя верить без проверки того, как они получены.

Слабое место вижу сам: доведённая до предела позиция парализует разбор. Если каждую цифру проверять на способ получения, инцидент не закончится никогда.

Границу я для себя провожу так: проверяю способ получения тогда, когда цифра подтверждает удобную гипотезу. Когда мешает - её и так проверят десять раз.

Правило про психологию, а не про инженерию, и меня оно не устраивает.

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

Другие наши инструменты диагностики 1С:

• Карта объёмов базы 1С - из чего состоит база и куда ушли гигабайты. Первое, что стоит посмотреть, когда непонятно, где вообще искать.
• Чек-ап СУБД под 1С - 40 с лишним проверок настроек SQL Server под платформу, в том числе тех, что меняют поведение блокировок.
• Трансформатор SQL в запрос 1С - когда в графе дедлока видно имя таблицы, а надо понять, какой объект конфигурации за ней стоит.
• Оптимизатор временных таблиц в пакетных запросах - когда выяснилось, что дело всё-таки в плане запроса.