Блокировка индекса на уровне страниц. Практическое расследование взаимоблокировки

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

Первоначальная задача и связанная с ней проблема

Начальные условия

Имеется нетиповая конфигурация «Управление производственным предприятием 1.3», работает в режиме совместимости с 8.2.13 на платформе 8.3. Используемая СУБД: MS SQL Server 2014. В конфигурации существуют некий работающий механизм переразнесения входящих платежных поручений по определенному графику платежей (в разрезе статей ДДС). Данный график уточняется (изменяется) в течении месяца, а в конце месяца все входящие платежные поручения должны быть переразнесены согласно этому графику.

Задача

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

Методика решения

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

Проблема

При выполнении многопоточного перепроведения начали «падать» ошибки взаимоблокировок на уровне СУБД:

Конфликт блокировок при выполнении транзакции:
Microsoft SQL Server Native Client 11.0: Transaction (Process ID 93) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
HRESULT=80004005, SQLSrvr: SQLSTATE=40001, state=34, Severity=D, native=1205, line=1

Анализ проблемы

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

Технологический журнал

Первым делом необходимо настроить технологический журнал на сбор событий EXCP и DBMSSQL (последнее используется для получения исполняемых запросов на СУБД MS SQL Server). Для события EXCP достаточно установить только фильтр по имени базы, по этому событию мало пишется данных в технологический журнал. А вот событие DBMSSQL, наоборот, пишет очень много данных, поэтому здесь необходимо либо установить фильтры, либо разбирать огромный файл в поисках необходимой информации. Не буду останавливаться на этом вопросе подробно, скажу лишь то что обязательно должны писаться все события DBMSSQL с отбором по свойству lkp=1 (необходимо для получения информации о жертве конфликта блокировок на уровне СУБД). Если же захочется найти источника блокировки, тогда, необходимо будет писать хотя бы все запросы с отбором по таблице на которой происходит конфликт.

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

Далее воспроизводим проблемную ситуацию и смотрим результаты технологического журнала:

Event	Date	Duration	ConnectID	Regions	WaitConnections	Status	Context	SQL Text
DBMSSQL	2016.07.27 11:31:32.199082	4133991	16196	dbo._AccumRg17539	16240	Victim	ОбщийМодуль.УправлениеЗакрытиемРегУчетаКлиентСервер.Модуль : 919 : ДокументОбъектППВ.Записать(РежимЗаписиДокумента.Проведение); Документ.ПлатежноеПоручениеВходящее.МодульОбъекта : 836 : ОбщегоНазначения.УдалитьДвиженияРегистратора(ЭтотОбъект, Отказ, Истина, Режим); ОбщийМодуль.ОбщегоНазначения.Модуль : 5490 : УдалитьЗаписанныеДвиженияДокумента(ДокументОбъект, Отказ, ВыборочноОчищатьРегистры, РежимПроведенияДокумента); ОбщийМодуль.ОбщегоНазначения.Модуль : 5607 : ПолныеПрава.УдалитьДвиженияПеречняРегистров(СоответствиеУдалятьДвижения, ДокументОбъект.Ссылка); ОбщийМодуль.ПолныеПрава.Модуль : 1353 : ЗаписатьНаборЗаписейНаСервере(ЭлементСоответствиеПереченьРегистров.Ключ, СсылкаНаДокумент,, ЭлементСоответствиеПереченьРегистров.Значение); ОбщийМодуль.ПолныеПрава.Модуль : 1343 : Набор.Записать(); РегистрНакопления.ОборотыБюджетов.МодульНабораЗаписей : 248 : ПроверитьГраницыПериодовБюджетированияИЗадачиУтвержденияБюджетов(Регистратор, Отказ); РегистрНакопления.ОборотыБюджетов.МодульНабораЗаписей : 338 : Результат = Запрос.Выполнить();	INSERT INTO #tt4 WITH(TABLOCK) (_Q_001_F_000RRef, _Q_001_F_001, _Q_001_F_002RRef, _Q_001_F_003RRef, _Q_001_F_004RRef, _Q_001_F_005RRef, _Q_001_F_006RRef, _Q_001_F_007RRef, _Q_001_F_008RRef, _Q_001_F_009RRef, _Q_001_F_010, _Q_001_F_011RRef, _Q_001_F_012RRef, _Q_001_F_013RRef, _Q_001_F_014_TYPE, _Q_001_F_014_RTRef, _Q_001_F_014_RRRef, _Q_001_F_015, _Q_001_F_016RRef, _Q_001_F_017RRef) SELECT DISTINCT T1._Fld17540RRef, T1._Period, T1._Fld23565RRef, T1._Fld17541RRef, T1._Fld17542RRef, T1._Fld17543RRef, T1._Fld17544RRef, T1._Fld17545RRef, T1._Fld17546RRef, T1._Fld24225RRef, T1._Fld24226, T1._Fld23564RRef, T1._Fld23566RRef, T1._Fld26026RRef, T1._Fld26027_TYPE, T1._Fld26027_RTRef, T1._Fld26027_RRRef, T1._Fld26565, T1._Fld38490RRef, T1._Fld38489RRef FROM dbo._AccumRg17539 T1 LEFT OUTER JOIN #tt3 T2 WITH(NOLOCK) ON (T1._Fld17540RRef = T2._Q_001_F_000RRef) WHERE (T1._RecorderTRef = 0x00000185 AND T1._RecorderRRef = p_0) AND T2._Q_001_F_000RRef IS NULL p_0: 0x8E769C8E9919A5F011E6523D15F913A7

Жертвой оказался запрос типа SELECT по таблице _AccumRg17539 с отбором по регистратору (найден по свойству lkp=1). Данный запрос должен был установить совмещаемые (Shared, S) блокировки. С помощью обработки из статьи «Получение информации о структуре хранения базы данных в терминах 1С:Предприятие и СУБД» получим информацию о том что это основная таблица оборотного регистра «Обороты бюджетов»

Поскольку совмещаемая блокировка не может конфликтовать с другой совмещаемой блокировкой, пытаемся в технологическом журнале найти конфликтующие запросы типа INSERT, DELETE или UPDATE с отбором по номеру соединения источника (для этого-то я и включил запись всех событий DBMSSQL). При этом учитываем что запрос жертвы должен был использовать индекс по регистратору и, значит, должен был установить совмещаемые блокировки только по своему регистратору. Поскольку в регистр накопления невозможно записать движения без отбора по регистратору, ищем запрос типа INSERT/DELETE/UPDATE по таблице _AccumRg17539 с отбором по номеру соединения источника и отбором по регистратору из текста SQL запроса жертвы (0x8E769C8E9919A5F011E6523D15F913A7). Но, к сожалению, подобного запроса у источника найти не удается, поэтому следующим шагом приходит мысль проверить точно ли запрос жертвы использует предполагаемый мной индекс.

План выполнения запроса

Для ускорения выполнения, планы исполняемых запросов кэшируются, этим-то мы и воспользуемся чтобы понять какой план запроса был использован. Для того чтобы найти план, выполним запрос к динамическим функциям: dm_exec_query_stats, dm_exec_sql_text, dm_exec_query_plan (более подробно эта тема рассмотрена в статье «Методы получения плана запроса в СУБД MS SQL Server») с отборами по времени выполнения и фрагментам запроса.

Уже в плане запроса начинает смущать толстая стрелка исходящая из Index Seek, тем не менее, как видно, использован индекс по регистратору (_ByRecorder)

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

Так же можно выполнить сам SQL запрос жертвы (из технологического журнала) в Management Studio и увидеть предполагаемый и актуальный планы запросов. В моем случае в актуальном плане запроса количество выбранных строк равно двум, в то время как в предполагаемом плане запроса количество строк ожидается 17230. Данный факт может говорить о неактуальной статистике, поэтому необходимо проверить эту версию. В моем случае статистика актуальна и, ожидаемо, обновление статистики и очистка процедурного кэша не дают никакого результата. При этом я запомню то что оптимизатор не смог правильно вычислить предполагаемое количество строк, хоть пока мне и не понятно что с этим делать.

Граф взаимоблокировки

Поскольку предыдущие шаги не дали результатов, получим граф взаимоблокировки. Для этого необходимо настроить Profiler на получение события Deadlock graph с отбором по исследуемой базе данных и выполнить действие еще раз. Во время выполнения операции, количество взаимоблокировок было не единично. Полученный список событий обширен, а графы разнообразны, но все они связаны с таблицей _AccumRg17539. При разборе взаимоблокировок необходимо начинать с самой простой, поэтому выберем самый простой граф.

Из графа уже можно понять проблему: процесс 92 установил IX блокировку на страницу индекса и процесс 84 установил IX блокировку на ту же страницу индекса. Блокировка IX совместима с другой блокировкой IX. Затем каждый из процессов запрашивает S блокировку (хочет конвертировать блокировку до уровня SIX) на ту же страницу индекса, но SIX блокировка не совместима с IX блокировкой, поэтому возникает взаимоблокировка и процесс 92 выбирается жертвой. Если посмотреть на запросы, то окажется что у обоих процессов S блокировку хотел установить запрос аналогичный вышеприведенному запросу жертвы из технологического журнала.

Метод расследования при помощи таймаута

Взаимоблокировки не частое явление, поэтому может не быть достаточного опыта анализа графа блокировки, в этом случае можно воспользоваться методикой расследования основанной на воспроизведении таймаута. Суть данного метода заключается в том чтобы в первом сеансе в транзакции перепровести один из документов и «повесить» транзакцию на ожидании, не дав ей завершится. В другом сеансе перепровести второй документ и получить таймаут. Код перепроведения документа в транзакции приведен ниже:

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

Тут же хочу упомянуть о двух возникших у меня проблемах в данном методе:

1. При проведении появилось ожидание на управляемой блокировке, которое ранее не проявлялось (т.к. в реальном механизме переразнесения платежей использовалось перепроведение документа без отмены проведения, а конфликтующий регистр не изменялся и, соответственно, не записывался). Разбор этой проблемы в данной статье приводится не будет
2. Не любой документ из набора конфликтовал, поэтому пришлось по технологическому журналу подобрать «правильный» документ (перепроведение которого выполняло конфликтующее соединение в тот же период времени)

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

Текущие установленные блокировки

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

В Management Studio выполним запрос из статьи «Получение информации о текущих блокировках в СУБД MS SQL Server».

Как видно на рисунке, установлены исключительные (X) блокировки на ключи индексов, а также IX блокировки на страницы индексов. При этом одна из блокировок (на уровне страниц) установлена в режиме SIX (была конвертирована из IX блокировки в результате выполнения запроса, приводящего к конфликту.

Текущие запросы

Теперь, не снимая с ожидания выполняющуюся транзакцию, выполним тот самый (конфликтующий) запрос напрямую из Management Studio с подстановкой соответствующего параметра (ссылки на второй документ). Запрос должен повиснуть на выполнении.

Теперь выполним запрос для получения информации о текущих исполняемых запросах, он приведен в статье «Получение информации о текущих исполняемых запросах MS SQL Server»

Как видно, запрос ожидает получения S блокировки на той же странице индекса. А сессия, которая не дает установить необходимую блокировку, соответствует сессии транзакции остановленной на ожидании.

Эксперименты

Дальнейшие эксперименты включающие в себя:

1. Перестроение индекса
2. Обновление статистики
3. Очистку процедурного кэша
4. Проведение различных регистраторам (того же типа)

Дают следующие результаты:

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

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

Получив распределение количества регистраторов от количества записей по регистратору, выявляется сильно неоднородное распределение количества записей по регистраторам. Так 93% уникальных регистраторов содержат лишь 9% строк от общего количества строк в таблице и, наоборот, 7% регистраторов содержат 91% строк записей от всей таблицы.

Также при анализе количества записей по регистраторам был выявлен документ содержащий 3% записей (91115 из 3079082). После отмены проведения данного документа (как оказалось этот документ никому уже не нужен) проблема исчезла.

Выводы

Причиной возникновения взаимоблокировки является попытка установки проблемным запросом S блокировки на уровне страницы индекса. При этом сам запрос как на уровне платформы 1С, так и на уровне СУБД является правильным. Выбор на каком уровне (строк/страниц/таблиц) будут установлены блокировки происходит на уровне СУБД. Причиной такой ошибки является «плохое» распределение статистики по используемому запросом индексу (индексу по регистратору), что было подтверждено дальнейшим расследованием. Изменение запроса таким образом, чтобы использовался другой индекс, без нарушения логики невозможно.

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

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

1. Ограничение количества проводимых документом записей (а большие документы разбивать на несколько)
2. Для больших документов создать отдельный регистр
3. Отключить блокировку индекса на уровне страниц (вероятно, нарушает лицензионное соглашение 1С) и внести соответствующие изменения в регламентные заданий SQL Server

Отключение блокировки индекса на уровне страниц

Одним из решений конфликта блокировок является установка свойства ALLOW_PAGE_LOCKS для данного индекса (по регистратору в таблице _AccumRg17539) в значение «OFF». Поскольку с выключенным значением данного свойства индекс не может быть реорганизован, необходимо внести соответствующие изменения в планы обслуживания. С выключенным значением данного свойства блокировка устанавливается на уровне ключей и не конфликтует.

Запрос для изменения данного свойства приведен ниже:

Данное решение приведено для расширения круга знаний и не рекомендуется для использования на продукционной базе (тем более если есть возможность решить проблему иным способом).