Почему бесполезно разбирать один дедлок

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

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

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

Жалоба, которая увела в сторону

Началось обычно: «реализация не создаётся, блокировка». Крупная розничная сеть, складская система на 1С, платформа 8.3. Система управления базами данных (дальше СУБД) - MS SQL Server.

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

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

Объект, названный в жалобе, это тот, на котором стало больно. Виновник может быть другим. Пользователь сообщает симптом, диагноз - наша работа, другого сообщения от него ждать не стоит.

Отсюда первое правило: начинать надо с карты «бизнес-имя объекта, имя таблицы хранения», без неё любое расследование в чужой конфигурации ходит по кругу. Мы её потом собрали отдельной обработкой (Трансформатор SQL в запрос 1С) - именно после этих потерянных суток.

Что мы стали делать вместо разбора случая

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

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

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

Мы сняли 33 отчёта за тридцать минут. В каждом есть список ресурсов, на которых сессии встали. Всего таких упоминаний набралось 220, то есть примерно по 6-7 на отчёт.

Цифра поначалу смущает: в учебном дедлоке двух сессий ресурсов один-два, а тут почти семь. Но под штормом дедлок редко бывает парным: SQL Server разруливает кольцо из трёх и более сессий, и в resource-list попадают все его звенья. Парой «жертва» (сессия, которую сервер откатил) и виновник дело не ограничивается. Плюс один объект может давать несколько строк ресурсов разного типа: страница (блок 8 КБ), ключ (строка индекса), объект целиком. Для нас это скорее хорошо: чем длиннее список, тем надёжнее статистика.

Дальше простая арифметика. 187 из 220, то есть 85 процентов, приходятся на одну таблицу.

На таблицу расходного ордера - того самого, который мы в первый день перепутали с приходным. Реализации из жалобы среди виновников не было вообще.

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

Как это считается на практике

Разбирать отчёты глазами не нужно, всё вытаскивается запросом. Каждый отчёт это XML, и смысл в том, чтобы развернуть его узел resource-list в строки и сгруппировать по объекту.

WITH Grafy AS (
    SELECT CAST(target_data AS XML) AS TD
    FROM sys.dm_xe_session_targets st
    JOIN sys.dm_xe_sessions s
      ON s.address = st.event_session_address
    WHERE s.name = 'system_health'
      AND st.target_name = 'ring_buffer'
),
Sobytiya AS (
    SELECT X.value('(@timestamp)[1]', 'datetime2')     AS Moment,
           X.query('.')                                AS Graf
    FROM Grafy
    CROSS APPLY TD.nodes('//event[@name="xml_deadlock_report"]') AS T(X)
),
Resursy AS (
    SELECT s.Moment,
           R.value('@objectname', 'nvarchar(256)')     AS ImyaObiekta,
           R.value('local-name(.)', 'nvarchar(64)')    AS TipResursa
    FROM Sobytiya s
    CROSS APPLY s.Graf.nodes('//resource-list/*') AS T2(R)
    WHERE R.value('@objectname', 'nvarchar(256)') IS NOT NULL
)
SELECT ImyaObiekta,
       TipResursa,
       COUNT(*)                                        AS Instansov,
       COUNT(DISTINCT Moment)                          AS Grafov
FROM Resursy
GROUP BY ImyaObiekta, TipResursa
ORDER BY Instansov DESC;

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

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

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

Первая: группировка идёт по паре «объект плюс тип ресурса», и один и тот же объект размажется по нескольким строкам (страница, ключ, объект). Если хочется увидеть ровно ту цифру, которую видели мы, добавьте второй проход с группировкой только по ImyaObiekta. Разбивка по типам полезна отдельно: она сразу показывает, на чём именно конфликтуют, на диапазонах ключей или на целых страницах.

Вторая, и она самая обидная. target_data у кольцевого буфера отдаётся как nvarchar(max), и на больших буферах он приходит обрезанным. CAST(... AS XML) на обрезанном документе падает с ошибкой разбора, и выглядит это так, будто запрос неверный. Лечится двумя способами. Либо снимать буфер, пока он не переполнен. Либо завести собственную сессию Extended Events (та же механика, что у system_health) с записью в файл вместо кольца - такую сессию имеет смысл поднять заранее, до инцидента, тогда история не зависит от объёма кольца.

Третья мелкая: СУБД может выполнить nodes() поверх CAST внутри общего табличного выражения не один раз, и на сотне отчётов это заметно. Для регулярного использования выгоднее сложить Sobytiya во временную таблицу и уже её разворачивать.

Четыре ложных следа, на которые не надо тратить время

Прежде чем перейти к тому, что нашлось, - про то, что искали зря. Каждый из этих четырёх съел у нас часы.

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

Блокировка временной таблицы. Временная таблица видна только своей сессии. Заблокировать ею кого-то постороннего невозможно по построению.

«Долгая сессия по процессору» не равно «блокировщик». Сессия может жечь процессор часами и никого при этом не держать. Пока не посмотрели поле блокирующей сессии, это просто тяжёлая сессия.

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

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

Почему таблица ждала саму себя

Разобрались, по какому условию сессии сходились на этой таблице. Отбор шёл по реквизиту «документ-основание».

Реквизит этот составного ссылочного типа: основанием может быть документ любого из нескольких видов. В хранилище такое поле раскладывается на три колонки: тип значения, номер таблицы (то есть вид документа-основания) и ссылка на сам объект. Отбор по нему это отбор по трём колонкам сразу.

Индекса на них не было.

Дальше очевидное. Запрос уходил в полное сканирование таблицы на 5,6 миллиона строк. Встроенная подсказка SQL Server о недостающих индексах оценила выигрыш в 99,98 процента стоимости запроса и висела там, судя по всему, годами.

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

Скажу сразу, пока не сказали в комментариях: про вред составных типов на Инфостарте давно есть каноническая статья, «Составные типы - бесплатный сыр мышеловки производительности». Тезис - общее место.

Но там речь про раздувание планов при соединениях и про обращения через точку. Слова «Индексировать» в ней нет, дедлоков нет, замеров в логических чтениях нет. Новое у нас другое: дедлок как симптом отсутствующего индекса, конкретный механизм отбора по трём колонкам и цена вопроса, посчитанная в цифрах.

Замер

A/B на копии базы с теми же 5,6 миллиона строк. Один и тот же запрос, разница только в наличии индекса.

Логические чтения упали почти в 94 тысячи раз, длительность в 119 раз.

Вопрос законный: если читать стали в 94 тысячи раз меньше, почему время сократилось всего в 119? Сканирование шло по страницам, которые уже лежали в памяти, и упиралось не в диск, а в процессор: 1 375 мс на восемь потоков это 172 мс на поток при общей длительности 155 мс, сходится. Чтение страницы из памяти стоит дёшево, отсюда фантастика в разах по чтениям при скромных секундах. Дедлоки же делает длительность, так что честная цифра здесь 119.

В объёме: 282 863 страницы по 8 килобайт это 2,16 ГиБ на один запрос. Не отчёт и не закрытие месяца - одна проверка основания при проведении одного документа.

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

Дальше второй эксперимент, и путать его с первым нельзя. Всё, что выше, это одиночный замер. Теперь пропускная способность под нагрузкой: восемь параллельных клиентов шлют запросы одновременно, не путать с восемью потоками внутри плана. Получилось 2,6 запроса в секунду против 286, то есть в 110 раз. Именно этот показатель и превращается в дедлоки на проде, а 119 из одиночного замера дают тот же порядок.

Числа двух экспериментов перемножать нельзя, и вот почему. Из одиночного замера восемь потоков должны давать 8 / 0,155 с (те же 155 мс) = 51,6 запроса в секунду без индекса и 8 / 0,0013 = 6 154 с индексом. Наблюдали 2,6 и 286: прогон медленнее ожидаемого примерно в 20 раз в обоих случаях (19,8 и 21,5). Множитель почти одинаков на обеих сторонах, и это спасает вывод: при делении сдвиг сокращается, отношение 110 выживает. Сравнивать между экспериментами можно отношения, но не абсолютные числа.

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

И вторая оговорка. На проде та же выборка одной строки занимала 1,58 секунды при холодном кэше против 155 миллисекунд на песочнице. Разницу в десять раз относим к кэшу: на проде он был холодный, на песочнице прогрет, данные и структура те же. Числа песочницы это нижняя граница проблемы, на проде было хуже.

Как правильно ставить такой индекс

Прямой CREATE INDEX в СУБД работает ровно до следующего обновления структуры базы, после чего платформа его снесёт и не спросит. Для замера на песочнице это годится, для прода нет.

Правильно это свойство «Индексировать» у реквизита в конфигураторе. Тогда индекс становится частью структуры и переживает обновления.

И момент, на котором повторение замера у вас может не получиться. Наш индекс лежит со страничным сжатием, 156 мегабайт это размер уже сжатого. Сжатие долго было только в Enterprise, в Standard появилось с SQL Server 2016 SP1; на более ранней Standard индекс займёт заметно больше, закладывайте. На выигрыш по чтениям редакция не влияет: поиск по индексу остаётся поиском.

Цена, которую мы не измерили

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

Индекс на 156 мегабайт при 5,6 миллиона строк это примерно 28 байт на строку. Цифра физичная: три колонки составной ссылки дают 21 байт (признак типа 1, ссылка на таблицу 4, идентификатор объекта 16), плюс ссылка на строку основной таблицы и служебные байты страницы. И это уже после страничного сжатия, в несжатом виде вышло бы ощутимо больше. Место тут не проблема.

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

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

Индекс, кстати, до сих пор не внедрён в прод. Дошло до песочницы и рекомендации. Значит главной пары чисел - «дедлоков в сутки было столько, стало столько» - у этой истории нет, и статья честно заканчивается лабораторным замером.

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

1. Считайте частоты. Один отчёт это анекдот, тридцать три отчёта это распределение, в котором виден виновник.
2. Список ресурсов это факт, текст запроса это гипотеза. Не путайте, на чём встали, с тем, что делали.
3. Начинайте с карты «бизнес-имя, имя таблицы». Ошибка сопоставления уводит расследование целиком, и заметить её трудно.
4. Снимайте system_health немедленно. Кольцевой буфер короткий, при шторме живёт минуты.
5. Отбор по реквизиту составного ссылочного типа без индекса это скан. Три колонки, никакого индекса, полное сканирование таблицы.
6. Ставьте «Индексировать» в конфигураторе, а не CREATE INDEX в СУБД.

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

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

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

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

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

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