Данная статья является практическим дополнением теоретической статьи о планах обмена 1С.
Сервер СУБД: Microsoft SQL Server 2014.
Предупреждение: приводимое описание недостаточно детально, чтобы его можно было использовать как инструкцию по использованию и применению у себя на сервере. Потребуется дополнительное изучение материалов по приводимым в статье ссылкам или обращение за консультацией к автору.
0. Описание задачи.
Периодически обмен между сайтом Интернет-магазина и торговой учётной системой "ложился" неизвестно почему. Изначально обратили на это внимание по причине роста количества входящих сообщений в очереди заказов покупателей. Если количество сообщений превышало настроенный порог, то об этом оповещалась система мониторинга состояния очередей. По началу грешили на зависание фоновых заданий 1С, которые обрабатывали эти очереди. Перезагружали сервер 1С, и это на какое-то время помогало. Затем обратили внимание на возникновение таймаутов ожидания на блокировках СУБД в моменты "падения" обмена. Решили расследовать причины этих блокировок.
1. Настройка мониторинга блокировок СУБД.
Для настройки мониторинга блокировок СУБД было выбрано решение от Дмитрия Короткевича Blocking Monitoring Framework, которое он описывает и рекомендует к использованию в своей книге "Expert SQL Server Transactions and Locking". Решение основано на использовании Event Notifications SQL Server, в частности настройке получения blocked process report.
Системная настройкаSQL Server "blocked process threshold" была установлена на 5 секунд, то есть отслеживается любое ожидание на блокировке продолжительностью более 5 секунд.
Установка BMFramework заняла буквально несколько минут. В результате чего на сервере была создана база данных "DBA", которая, сразу же после установки, начала собирать статистику по взаимным блокировкам и ожиданиям на блокировках. Режим мониторинга круглосуточный. Создаваемая при этом нагрузка на сервер фактически незаметна.
Кроме этого была добавлена таблица "tech_log_entries" для сбора событий технологического журнала 1С. Об этом рассказано ниже.
2. Анализ результатов мониторинга.
По результатам мониторинга был получен следующий отчёт "Топ 15 блокировок по хэшу плана запроса".
Из этого отчёта, благодаря колонке "BlockedSql" (заблокированное выражение SQL), можно понять, что наиболее частым ожиданием на блокировках является таблица _ReferenceChngR332. Обратившись за помощью к функции платформы "ПолучитьСтруктуруХраненияБазыДанных", удалось выяснить что это таблица изменений справочника "ПартииТоваров".
Ожидания на блокировках часто образуют цепочки ожиданий, у которых есть корень блокировки (виновник) и жертвы ожидания на этой блокировке. При анализе блокировок необходимо уделять внимание именно причине возникновения ожиданий, то есть непосредственно виновнику блокировки - корню цепочки. Например, другой отчёт показывает такие цепочки и их корни.
В данном случае отчёт уже отфильтрован по таблице _ReferenceChngR332. Если внимательно прочитать статью о планах обмена 1С, то анализ запросов SQL из отчёта подскажет нам, что использовались следующие вызовы методов менеджера планов обмена:
1. Запросы при вызове метода ПланыОбмена.ВыбратьИзменения (первая и вторая его части):
UPDATE T1 SET _MessageNo = @P1 ...
и
SELECT T1._IDRRef FROM dbo._ReferenceChngR332 T1 WHERE T1._NodeTRef = 0x0000000B ...
2. Запрос при вызове метода ПланыОбмена.УдалитьРегистрациюИзменений.
DELETE FROM T1 FROM dbo._ReferenceChngR332 T1 WHERE T1._IDRRef = @P1 ...
3. Запрос при вызове метода ПланыОбмена.ЗарегистрироватьИзменения.
UPDATE T1 SET _MessageNo = CAST(NULL AS NUMERIC(38,8)) FROM dbo._ReferenceChngR332 T1 ...
Другими словами становится понятно, что теоретические рассуждения о трёх конкурирующих ролях на таблицах изменений планов обмена 1С имеют в данном случае практическое подтверждение.
Теперь нужно получить контекст кода 1С, который вызывает соответствующие методы менеджера планов обмена, чтобы постараться понять каким образом это происходит и что можно с этим сделать. Для этого нужно настроить сбор событий технологического журнала 1С и получить эту информацию оттуда. Как это было сделано я расскажу немного позже, а сейчас я хочу обратить внимание на запрос SQL, который является корнем цепочки блокировок.
Запрос корня цепочки это выражение SELECT языка SQL. Однако все мы знаем, что 1С:Предприятие 8.3 работает в режиме управляемых блокировок, а, следовательно, использует режим изоляции транзакций READ COMMITTED SNAPSHOT (RCSI), который не является блокирующим чтением. Блокировки быть не должно. Однако, в данном случае SELECT выполняется в транзакции, которая ранее уже заблокировала читаемые строки. Эта транзакция выглядит следующим образом (подробнее в статье "Планы обмена 1С"):
Небольшой нюанс: в целях оптимизации блокировок и обменов выгрузка объектов 1С выполняется порциями по 3000 объектов или менее (такая настройка на уровне узла плана обмена). Таким образом фильтрация метода "ВыбратьИзменения" производится по массиву, передаваемых в него ссылок. То есть реально добавляется ещё фильтр вида ГДЕ Ссылка В (&МассивСсылок), что в свою очередь накладывает блокировки на записи по этим ссылкам на уровне СУБД: WHERE T1._IDRRef IN (@P1, @P2 ...
3. Настройка технологического журнала 1С.
Для отлова нужных событий и контекстов 1С файл настроек технологического журнала 1С был сформирован следующим образом:
<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
<dump create="false"/>
<log location="D:\tech_logs\" history="48">
<event>
<eq property="name" value="dbmssql"/>
<like property="sql" value="SELECT%"/>
<like property="sql" value="%_ReferenceChngR332%"/>
<like property="sql" value="%T1._NodeTRef%"/>
<like property="sql" value="%0x0000000B%"/>
<like property="sql" value="%T1._IDRRef%"/>
</event>
<event>
<eq property="name" value="dbmssql"/>
<like property="sql" value="UPDATE%"/>
<like property="sql" value="%_ReferenceChngR332%"/>
</event>
<event>
<eq property="name" value="dbmssql"/>
<like property="sql" value="DELETE%"/>
<like property="sql" value="%_ReferenceChngR332%"/>
</event>
<property name="all"/>
</log>
</config>
Для настройки файла logcfg.xml использовались рекомендации Юрия Пермитина из его статьи "Мониторинг SQL Server с помощью Extended Events (и не только) для 1С. Как держать руку на пульсе?", а также его же утилита для парсинга технологического журнала YY.TechJournalReaderAssistant. Утилита была доработана для того, чтобы загружать события DBMSSQL в таблицу dbo.tech_log_entries базы данных DBA (см. пункт 2 выше).
Недостатком использования ТЖ 1С явилось то, что каждый час генерировалось несколько десятков мегабайт логов. Однако, учитывая тот факт, что было заранее известно какие шаблоны SQL запросов искать, достаточно было запустить сбор логов ТЖ всего на один час или даже на 10-15 минут.
4. Анализ технологического журнала 1С.
В результате анализа записей ТЖ были получены контексты, стэки вызовов, кода 1С. О них я расскажу далее. Перед этим мне хотелось бы обратить внимание на одно открытие, которое я сделал при анализе запросов SQL виновника блокировок. В каких-то случаях они имели такой вид:
SELECT
T1._IDRRef
FROM
dbo._ReferenceChngR332 T1
WHERE T1._NodeTRef = 0x0000000B
AND T1._NodeRRef = @P1
AND (T1._IDRRef IN (@P2, @P3, @P4))
В других случаях такой:
SELECT
T1._IDRRef
FROM
dbo._ReferenceChngR332 T1
WHERE T1._NodeTRef = 0x0000000B
AND T1._NodeRRef = @P1
AND (T1._IDRRef IN
(SELECT CASE WHEN T2._INVALUELISTTRef = 0x0000002A
THEN T2._INVALUELISTRRef ELSE @P2 END AS INVALUELISTRRef
FROM
#tt7 T2 WITH(NOLOCK)
WHERE
CASE WHEN T2._INVALUELISTTRef = 0x0000002A
THEN T2._INVALUELISTRRef ELSE @P3 END IS NOT NULL))
Разница заключается в использовании временной таблицы для передачи фильтра в виде массива ссылок в метод менеджера планов обмена "ВыбратьИзменения". Это говорит о том, что в каких-то случаях 1С считает, что массив достаточно большой, чтобы начать использовать временную таблицу. Экспериментальным путём удалось выяснить, что количество ссылок в массиве, начиная с которого создаётся временная таблица, равно 129. Создание временной таблицы означает нагрузку на tempdb и дисковую систему сервера СУБД. Это может влиять на продолжительность выполнения всего метода "ВыбратьИзменения" (транзакции СУБД), особенно учитывая тот факт, что в нём выполняются последовательно сначала UPDATE, а только затем SELECT.
Поиск контекстов 1С виновника и жертв ожидания на блокировках выполнялся при помощи таблицы tech_log_entries базы данных DBA, описанных выше.
5. Виновник блокировок.
ПланыОбмена.ВыбратьИзменения
Виновник блокировок имеет следующий стэк вызовов. Ясно, что это выгрузка данных РИБ.
ОбщийМодуль.ДлительныеОперации.Модуль : 652 : ВыполнитьПроцедуру(ИмяПроцедуры, ПараметрыПроцедуры);
ОбщийМодуль.ДлительныеОперации.Модуль : 661 : ОбщегоНазначения.ВыполнитьМетод(ИмяПроцедуры, ПараметрыПроцедуры);
ОбщийМодуль.ОбщегоНазначения.Модуль : 4762 : Выполнить ИмяМетода + "(" + ПараметрыСтрока + ")";
: 1 : ОбменДаннымиРИБ.ВыгрузитьИзмененныеОбъекты(Параметры[0],Параметры[1])
ОбщийМодуль.ОбменДаннымиРИБ.Модуль : 129 : Пакет = СформироватьПакетОбмена(НастройкиОбмена, СписокМетаданных);
ОбщийМодуль.ОбменДаннымиРИБ.Модуль : 372 : Возврат РаспределитьПакетПоТипамОбъектов(Пакет, НастройкиОбмена);
ОбщийМодуль.ОбменДаннымиРИБ.Модуль : 1021 : Выборка = ПланыОбмена.ВыбратьИзменения(УзелОбмена, НомерСообщения, Фильтр);
6. Жертвы блокировок.
6.1. Конкурирующая выгрузка данных.
ПланыОбмена.ВыбратьИзменения
ОбщийМодуль.ДлительныеОперации.Модуль : 652 : ВыполнитьПроцедуру(ИмяПроцедуры, ПараметрыПроцедуры);
ОбщийМодуль.ДлительныеОперации.Модуль : 661 : ОбщегоНазначения.ВыполнитьМетод(ИмяПроцедуры, ПараметрыПроцедуры);
ОбщийМодуль.ОбщегоНазначения.Модуль : 4762 : Выполнить ИмяМетода + "(" + ПараметрыСтрока + ")";
: 1 : ОбменДаннымиРИБ.ВыгрузитьИзмененныеОбъекты(Параметры[0],Параметры[1])
ОбщийМодуль.ОбменДаннымиРИБ.Модуль : 129 : Пакет = СформироватьПакетОбмена(НастройкиОбмена, СписокМетаданных);
ОбщийМодуль.ОбменДаннымиРИБ.Модуль : 372 : Возврат РаспределитьПакетПоТипамОбъектов(Пакет, НастройкиОбмена);
ОбщийМодуль.ОбменДаннымиРИБ.Модуль : 1021 : Выборка = ПланыОбмена.ВыбратьИзменения(УзелОбмена, НомерСообщения, Фильтр);
Код ровно такой же, как в пункте 5 "Виновник блокировок". Как выяснилось, регламентное задание по выгрузке данных запускалось несколько раз. Таким образом создавались конкурирующие за одни и те же объекты конфигурации 1С фоновые задания.
6.2. Удаление регистрации изменений.
ПланыОбмена.УдалитьРегистрациюИзменений
ОбщийМодуль.ДлительныеОперации.Модуль : 652 : ВыполнитьПроцедуру(ИмяПроцедуры, ПараметрыПроцедуры);
ОбщийМодуль.ДлительныеОперации.Модуль : 661 : ОбщегоНазначения.ВыполнитьМетод(ИмяПроцедуры, ПараметрыПроцедуры);
ОбщийМодуль.ОбщегоНазначения.Модуль : 4762 : Выполнить ИмяМетода + "(" + ПараметрыСтрока + ")";
: 1 : ОбменДаннымиРИБ.ВыгрузитьИзмененныеОбъекты(Параметры[0],Параметры[1])
ОбщийМодуль.ОбменДаннымиРИБ.Модуль : 155 : ЗафиксироватьЗагрузкуОбъекта(ВыгруженныеОбъекты, УзелОбмена);
ОбщийМодуль.ОбменДаннымиРИБ.Модуль : 1882 : ПланыОбмена.УдалитьРегистрациюИзменений(УзелОбмена, Объект);
Кроме этого выяснилось, что после успешной выгрузки объекта 1С выполнялось удаление ссылки на такой объект из плана обмена, что создавало дополнительную конкуренцию за одни и те же записи таблиц изменений. Объяснением такого поведения системы является то, что выгрузка выполняется при помощи http сервисов 1С, квитирование выгрузки не выполняется - достаточно получить код ответа HTTP 200 от принимающего узла обмена.
Данная жертва является косвенным последствием порождения жертвы из пункта 6.1.
6.3. Регистрация новых изменений.
ПланыОбмена.ЗарегистрироватьИзменения
ОбщийМодуль.ОбменИнтернетМагазин.Модуль : 92 : ЗагрузитьЗаказыКлиентов(ДанныеСессии);
ОбщийМодуль.Заказы.Модуль : 1306 : ЗаказКлиента.Записать(РежимЗаписиДокумента.Проведение);
ОбщийМодуль.ОбменДаннымиМагазин.Модуль : 12 :
ОбменДаннымиСобытия.МеханизмРегистрацииОбъектовПередЗаписьюДокумента(ИмяПланаОбмена, Источник, Отказ, РежимЗаписи, РежимПроведения);
ОбщийМодуль.ОбменДаннымиСобытия.Модуль : 24 :
ЗарегистрироватьИзменениеОбъекта(ИмяПланаОбмена, Источник, Отказ, ДополнительныеПараметры);
ОбщийМодуль.ОбменДаннымиСобытия.Модуль : 1033 :
ВыполнитьПравилаРегистрацииОбъектовДляПланаОбмена(МассивУзловРезультат, Объект, ИмяПланаОбмена, ДополнительныеПараметры);
ОбщийМодуль.ОбменДаннымиСобытия.Модуль : 1324 :
ВыполнитьПравилаРегистрацииОбъектовДляПланаОбменаПопыткаИсключение(МассивУзловРезультат, Объект, ИмяПланаОбмена, ДополнительныеПараметры);
ОбщийМодуль.ОбменДаннымиСобытия.Модуль : 1431 :
ОпределитьПолучателейПоУсловию(МассивУзловРезультат, ПРО, Объект, ИмяПланаОбмена, ДополнительныеПараметры);
ОбщийМодуль.ОбменДаннымиСобытия.Модуль : 1675 :
ВыполнитьОбработчикПРОПослеОбработки(ПРО, Отказ, Объект, ОбъектМетаданных, Получатели, Выгрузка);
ОбщийМодуль.ОбменДаннымиСобытия.Модуль : 2531 : Выполнить(ПРО.ПослеОбработки);
: 31 : ПланыОбмена.ЗарегистрироватьИзменения(Получатели, Партия);
На самом деле жертв из этой категории было гораздо больше. Всех их объединяет вызов механизма регистрации объектов в обмен данными. По результатам выполнения ПРО выполняется регистрация объектов, которые в данный момент участвуют в выгрузке. Таким образом возникает ожидание на блокировке СУБД.
7. Заключение.
Таким образом была найдена причина возникновения ожиданий и даже ошибок таймаута на блокировках СУБД при выполнении обменов с Интернет-магазином. Выяснилось, что при загрузке заказов клиентов выполнялись правила регистрации для справочника "ПартииТоваров" и, как следствие, возникал конфликт с текущей выгрузкой совпадающих партий товаров в узлы обмена РИБ.
В результате полученной информации архитектор торговой учётной системы получил конкретные знания о причинах возникающих проблем. Был произведён рефакторинг архитектуры и кода. Проблему "падения" обменов с Интернет-магазином удалось решить в кратчайшие сроки.
Кроме этого попутно была выявлена скрытая проблема параллельного запуска фоновых заданий по выгрузке данных РИБ. Появился повод подумать о реорганизации выполнения правил регистрации в обмен для других объектов системы. Задумались об удалении выгруженных объектов из таблиц изменений, о квитировании и гарантировании ...
