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

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

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

Случай первый: текст ошибки, который ничего не сообщает

Что сказала платформа и что мы услышали

Робот резервирования волны падал вот на этом:

В данной транзакции уже происходили ошибки

Рядом, на терминале сбора данных, падало то же самое, и там в журнале регистрации стоял код 1205 - взаимоблокировка MS SQL Server. Робот поднимает до десяти параллельных фоновых потоков на волну по одному справочнику. Складывать из этого версию про конкуренцию за ресурс было легко и приятно.

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

Что эта строка означает буквально

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

То есть сообщение отвечает на вопрос “почему не получилось сейчас” и молчит о вопросе “что сломалось”. Под ним одинаково прячутся:

• взаимоблокировка или таймаут на блокировке;
• проглоченная бизнес-проверка прикладного кода;
• ошибка приведения типов в обработчике проведения;
• любое пойманное и не показанное исключение.

Что оказалось на самом деле

Мы расшили молчаливые Попытка...Исключение, и первый же прогон показал:

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

Прикладная проверка остатка. Никакой конкуренции.

Дальше нашлось и основание проверки: два регистра остатков разошлись между собой. Первый держал корректную физику, во втором залипло значение ресурса “Отобрано”. Проверка считает так (имена ресурсов условные):

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

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

Сигнал, который стоил двух отборов

Полтора суток наблюдения дали в журнале 24 записи с этим текстом. Код 1205 стоял у 19. Пять записей его не несли.

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

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

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

При журнале, вылитом во внешнее хранилище, оба счётчика снимаются одним запросом. У нас журнал живёт в ClickHouse:

-- сколько записей про испорченную транзакцию и сколько из них с кодом 1205
SELECT
    countIf(positionUTF8(description, 'уже происходили ошибки') > 0) AS vsego,
    countIf(positionUTF8(description, 'уже происходили ошибки') > 0
            AND positionUTF8(description, '1205') > 0)              AS s_kodom_1205
FROM event_log
WHERE event_date >= today() - 2
  AND level = 'Error'

Без хранилища это два отбора штатного просмотра журнала по подстроке в описании. Дольше, ответ тот же. Почему штатный журнал на нагруженной базе перестаёт быть инструментом - разбирали отдельно.

Повтор в обработчике не спасает транзакцию никогда

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

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

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

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

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

Как расшить правильно

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

Здесь три обязательных детали, и каждая по отдельности решает исход.

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

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

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

Точек у нас набралось три, и настоящая ошибка всплыла на первом прогоне после правки.

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

Случай второй: буфер, который обнулили переключением узла

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

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

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

Прежде чем делать вывод из пустого буфера, посмотрите, сколько экземпляр вообще живёт и что за события в буфере лежат:

-- когда стартовал экземпляр
SELECT
    sqlserver_start_time                              AS start_ekzemplyara,
    DATEDIFF(minute, sqlserver_start_time, GETDATE()) AS minut_uptime
FROM sys.dm_os_sys_info;

-- фактический возраст событий в кольцевом буфере
SELECT
    COUNT(*)          AS sobytiy_v_bufere,
    MIN(t.event_time) AS samoe_staroe,
    MAX(t.event_time) AS samoe_svezhee
FROM (
    SELECT CAST(target_data AS XML) AS td
    FROM sys.dm_xe_session_targets AS st
    JOIN sys.dm_xe_sessions AS s ON s.address = st.event_session_address
    WHERE s.name = 'system_health' AND st.target_name = 'ring_buffer'
) AS src
CROSS APPLY (
    SELECT x.value('@timestamp', 'datetime2') AS event_time
    FROM src.td.nodes('RingBufferTarget/event[@name="xml_deadlock_report"]') AS n(x)
) AS t;

Самое старое событие моложе вашего инцидента - значит буфер физически не хранит искомое, и отсутствие строк не означает ничего.

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

-- кто сейчас основной по каждой группе доступности
SELECT ag.name                 AS gruppa,
       ars.role_desc           AS rol,
       ar.replica_server_name  AS uzel
FROM sys.availability_groups                 AS ag
JOIN sys.availability_replicas               AS ar  ON ar.group_id = ag.group_id
JOIN sys.dm_hadr_availability_replica_states AS ars ON ars.replica_id = ar.replica_id
ORDER BY ag.name, ars.role_desc;

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

Случай третий: события лежат под чужой подписью

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

Отбор по имени базы вернул ноль строк. При том что взаимоблокировки шли, а алерты приходили.

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

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

Проверка одна: вытащить различные имена баз из самих накопленных событий и сверить со списком ожидаемых.

-- какие имена баз реально встречаются в собранных событиях
SELECT DISTINCT
       d.name                              AS imya_bazy_iz_sobytiya,
       COUNT(*) OVER (PARTITION BY d.name) AS sobytiy
FROM dbo.DeadlockLog AS l          -- ваша таблица сборщика
CROSS APPLY (
    SELECT DB_NAME(l.database_id) AS name
) AS d
ORDER BY sobytiy DESC;

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

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

Случай четвёртый: зонд, ставший проблемой

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

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

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

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

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

Отчего так вышло

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

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

Что там растёт, видно так:

-- сколько занимает хранилище версий
SELECT SUM(version_store_reserved_page_count)   * 8 / 1024 AS version_store_mb,
       SUM(user_object_reserved_page_count)     * 8 / 1024 AS user_objects_mb,
       SUM(internal_object_reserved_page_count) * 8 / 1024 AS internal_mb
FROM sys.dm_db_file_space_usage
WHERE database_id = 2;   -- tempdb

-- кто держит границу и мешает усечению
SELECT TOP 10
       t.session_id,
       DB_NAME(t.database_id)          AS baza,
       t.elapsed_time_seconds / 3600.0 AS chasov_otkryta,
       s.login_name,
       s.program_name,
       s.host_name
FROM sys.dm_tran_active_snapshot_database_transactions AS t
JOIN sys.dm_exec_sessions AS s ON s.session_id = t.session_id
ORDER BY t.elapsed_time_seconds DESC;

Чем ещё оборачивается долгая транзакция и как разбить её на порции - в отдельном разборе. Здесь особенность в другом: эта транзакция не делала ничего.

Как искать такие сеансы руками

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

SELECT s.session_id,
       s.login_name,
       s.program_name,
       s.host_name,
       s.status,
       s.last_request_end_time,
       DATEDIFF(second, s.last_request_end_time, GETDATE()) AS sekund_bezdeystviya
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'
  AND s.is_user_process = 1
ORDER BY s.last_request_end_time;

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

Отчёты вида “кто кого блокирует” такой сеанс не покажут никогда: они стартуют от факта ожидания, а тут никто не ждёт. Поэтому проверку держат отдельным пунктом. Сами блокировочные вопросы - кто держал базу и чьи сеансы стояли - быстрее закрывать историей снимков, а не разовыми запросами: как её устроить, разобрано в статье кто блокирует базу 1С, готовый сборщик - обработка Анализ нагрузки кластера 1С.

Почему алерт увёл в сторону

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

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

И второе. Фильтр “только пользовательские процессы” включает сам мониторинг: технический логин коллектора - такой же пользовательский процесс. Исключать себя надо явно, по имени приложения в строке соединения:

-- в строке соединения коллектора: Application Name=monitoring-collector
AND s.program_name <> 'monitoring-collector'

Три вида пустоты

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

Что показал прибор	Что было
24 записи об одной ошибке	у 19 стоит 1205, у пяти не стоит
Пустой буфер system_health	буфер обнулён переключением узла
Ноль строк по имени базы	события подписаны другим именем
Ноль блокировок у сеанса	транзакция открыта четверо с половиной суток

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

Где кончаются наши данные

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

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

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

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

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

Версия, которую пришлось выбросить

Взаимоблокировка 1205 на горячем регистре остатков.

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

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

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

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

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

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

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

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

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