Изыскания на тему записи в регистр сведений

Предыстория Досталась задача на оптимизацию по незнакомому участку кода и структуре конфигурации

Краткое описание ключевой операции

1. Получение запроса от сайта, обработка данных и выдача ответа
2. Пометка в лог о взаимодействии с сайтом (фиксируем в регистр тело запроса и тело ответа) 

Первичный сбор данных MSSQL-профайлером, произведённый нашим системным администратором (вложение slow_query.trc), показал что узкое место - запись в регистр _InfoRg3656

Бросилось в глаза, что запись в регистр идёт с опцией WITH SERIALIZABLE, это означает, что блокируется вся таблица целиком. ^{(Для MSSQL это неверно, SERIALIZABLE вызывает блокировку всей таблицы только у СУБД "версионников": PostgreSQL и Oracle)}

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

Слева Автоматический режим блокировок, справа - Управляемый

Примечание: сравнение текстов проведено с помощью Notepad++ с помощью плагина Compare, подробней ЗДЕСЬ, этот механизм сравнения удобней встроенного в 1С тем, что не нужно предварительно сохранять тексты в файлы, а достаточно вставить тексты из буфера обмена на две разных закладки в Np++ , и нажать одну кнопку  

Итак, SERIALIZABLE ушёл. Но проблема не решилась. Стали копать глубже.

Что же может быть не так?

exec sp_executesql N'DELETE FROM T1
FROM dbo._InfoRg3656 T1
WHERE T1._Fld3658 = @P1 AND T1._Fld3659 = @P2',
N'@P1 nvarchar(4000),@P2 nvarchar(4000)',N'ЕстьЛиЧекиПоЗаказам',N'6d89de15-6bcb-43d4-8580-fbc0c093a612'

Посмотрим на план запроса. Перед этим небольшое отступление на случай, если с MSSQL Profiler-ом кто-то не знаком

Как читать трассировки

Записанные трассировки в Профайлере состоят из 2-х частей:

1. Верхняя, где список событий
2. И нижняя, где можно увидеть подробности выделенного сверху события.

Трассировки, приложенные к публикации в основном были собраны с фильтром на следующие 3 вида событий

1. Showplan Statistics Profile = План выполнения запроса текстом
2. Showplan XML Statistics Profile = План выполнения запроса графически
3. RPC:Completed = Текст запроса 

ВАЖНО! Трассировки достаточно большие, поэтому чтоб найти интересующие нас события, связанные с проблемной операцией, через Ctrl+F делаем поиск по маске _InfoRg3656

Трассировка 1. Набор записей с замещением без отбора по дате (DELETE+SCAN).trc

Текст запроса

DELETE FROM T1
FROM dbo._InfoRg3656 T1
WHERE T1._Fld3658 = @P1 AND T1._Fld3659 = @P2

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

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

Если внимательно посмотреть на номера таблиц/полей в нотации SQL - можно заметить что один порядковый номер пропущен. Что наводит на мысль о том, что отбор происходит по второму и третьему измерению, и они не индексированы.

Проверим в конфигураторе:

Проблемный участок кода, обратите внимание на поля, по которым ставится отбор

// ID и время для уникальности
УИДЗапроса = Строка(Новый УникальныйИдентификатор);
ВремяЗапроса = ТекущаяДата();

НаборЗаписей = РегистрыСведений.ЛогЗапросовОтСайта.СоздатьНаборЗаписей();
// Уникальный ID запроса, некое поле, искусственно созданное для дополнительной уникальности в рамках секунды
НаборЗаписей.Отбор.УидЗапроса.Установить(УИДЗапроса); // Отбор на третье измерение "УИДЗапроса"
// ИмяМетода - входящий строковый параметр, где может встречаться до 10 различных значений (иными словами, селективность низкая, но об этом позднее)
НаборЗаписей.Отбор.ТипЗапроса.Установить(ИмяМетода);  // Отбор на второе измерение "ИмяМетода"
        
Движение = НаборЗаписей.Добавить();
// измерения
Движение.ВремяЗапроса = ВремяЗапроса;
Движение.УидЗапроса = УИДЗапроса;
Движение.ТипЗапроса = ИмяМетода;
// ресурсы
Движение.ВходящийJSON = ТелоЗапроса;
Движение.ОтветныйJSON = ТелоОтвета;
// запись с замещением
НаборЗаписей.Записать();

Что мы видим? При установке отбора в наборе записей не ставится отбор на первое измерение "ВремяЗапроса".

Посмотрим, какие индексы есть на этом регистре?

И действительно, измерения явно не индексированы!

В конфигураторе на всех измерениях - Не индексировать

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

Таким образом, происходит вот что (А) набор происходит с замещением, поэтому перед записью выполняется DELETE в соответствии с установленным отбором, (Б) отбор при записи набора ставится на второе и третье измерение, первое в отборе не используется, посему система не может использовать существующий "системный" индекс по измерениям, и в итоге сваливается в скан. Решить эту проблему есть несколько способов. 

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

Трассировка 2. Набор записей с замещением без отбора по дате, поменял порядок измерений в регистре (оптимальный DELETE).trc

Что видим:

1. SCAN пропал
2. Количество обработанных строк уменьшилось до одной
3. Duration устремился к нулю

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

Рассмотрим другой способ, которым можно было бы воспользоваться в данном случае. Если мы обратим внимание на заполнение измерения УидЗапроса, мы увидим что оно заполняется значением Новый УникальныйИдентификатор, то есть по сути всегда уникальное, поэтому замещение можно и отключить. Попробуем. 

НаборЗаписей.Записать(Ложь);

Трассировка 3. Набор записей БЕЗ ЗАМЕЩЕНИЯ без отбора по дате, исходный порядок измерений (SELECT вместо DELETE, скана нет).trc

Что мы видим:

1. DELETE исчез, вместо него явился SELECT
2. SELECT (для контроля уникальности платформой 1С) при отборе использует все три измерения
3. Таким образом, отбор попадает в существующий платформенный индекс по измерениям, и получается Clustered Index Seek вместо скана, всё оптимально.

Задача решена. Но не всегда можно отключить замещение. Какие ещё есть варианты? Можно ли оптимизировать запись в регистр в данном случае, не трогая структуру конфигурации вообще? Да. Чтоб платформа смогла задействовать существующий неявный индекс по измерениям - достаточно поставить отбор и на это поле тоже. Сделаем (Добавим одну строку кода, при этом конфигурацию откатим в первоначальное состояние)

// ID и время для уникальности
УИДЗапроса = Строка(Новый УникальныйИдентификатор);
ВремяЗапроса = ТекущаяДата();

НаборЗаписей = РегистрыСведений.ЛогЗапросовОтСайта.СоздатьНаборЗаписей();
// Уникальный ID запроса, некое поле, искусственно созданное для дополнительной уникальности в рамках секунды
НаборЗаписей.Отбор.УидЗапроса.Установить(УИДЗапроса); // Отбор на третье измерение "УИДЗапроса"
// ИмяМетода - входящий строковый параметр, где может встречаться до 10 различных значений (иными словами, селективность низкая, но об этом позднее)
НаборЗаписей.Отбор.ТипЗапроса.Установить(ИмяМетода);  // Отбор на второе измерение "ИмяМетода"
// ОПТИМИЗАЦИЯ ЗДЕСЬ! { 
// ВремяЗапроса - первое измерение, и именно его не хватало в отборе, чтоб был задействован индекс
НаборЗаписей.Отбор.ВремяЗапроса.Установить(ВремяЗапроса); 
// }
        
Движение = НаборЗаписей.Добавить();
// измерения
Движение.ВремяЗапроса = ВремяЗапроса;
Движение.УидЗапроса = УИДЗапроса;
Движение.ТипЗапроса = ИмяМетода;
// ресурсы
Движение.ВходящийJSON = ТелоЗапроса;
Движение.ОтветныйJSON = ТелоОтвета;
// запись с замещением
НаборЗаписей.Записать();

Трассировка 4. Набор записей с замещением с отбором по дате (DELETE без SCANа).trc

Что видим?

1. Clustered Index Delete без скана
2. В отборе используется все три поля, индекс задействован, всё оптимально
3. В точки зрения плана запроса трассировка идентична той, когда мы меняли порядок измерений

Хорошо. Имеем 3 способа решить эту задачу.

А как изменится трассировка, если всё вернём в первоначальный вид, но проиндексируем используемое в отборе поле с низкой селективностью (ТипЗапроса)

Трассировка 5. Набор записей с замещением без отбора по дате (DELETE, поиск по диапазону индекса), проиндексировано второе измерение с низкой селективностью.trc

Ситуация в некотором смысле промежуточная:

1. Индекс используется, но из-за низкой селективности отбирается по нему не 1 строка сразу, а 29тыс (напомню, всего в таблице 151тыс строк)
2. А дальше уже по этому набору находятся нужная одна - и по ней идёт удаление
3. Duration - не 0 как в других вариантах, но 6 миллисекунд - тоже замечательно 

Добро. Теперь сравним этот вариант с похожим. Что будет, если опять же CF оставить первозданным, но проиндексировать не второе измерение, а третье (УидЗапроса с уникальными значениями и, соответственно, с наивысшей селективностью)?

Трассировка 6. Набор записей с замещением без отбора по дате (DELETE, поиск по индексу), проиндексировано третье измерение с высокой селективностью.trc

7. Менеджер с замещением без отбора, измерения не индексированы, статистика после обновления не обновлена.trc

Данный вариант не совсем по теме регистров сведений, но тоже относится к оптимизации с точки зрения обслуживания баз на уровне СУБД, точнее обновления статистики. Явился он в процессе исследования еще одного способа решения исходной задачи. Через смену способа записи в регистр: что если использовать менеджер записи вместо набора записей? (СF изначальный)

ЗаписьВЛог = РегистрыСведений.ЛогЗапросовОтСайта.СоздатьМенеджерЗаписи();
// измерения
ЗаписьВЛог.ТипЗапроса = СтроковоеИмяМетода;
ЗаписьВЛог.УидЗапроса = УИДЗапроса;
ЗаписьВЛог.ВремяЗапроса = ТекущееВремя;
// ресурсы
ЗаписьВЛог.ВходящийJSON = ТелоЗапроса;
ЗаписьВЛог.ОтветныйJSON = ТелоОтвета;
// запись в базу
Замещать = Истина;
ЗаписьВЛог.Записать(Замещать);

 В трассировке наблюдаем странное: обычно запросы идут парами Showplan+RPC:Completed (ПланВыполненияЗапроса+ТекстСамогоЗапроса ), а тут перед запросом (RPC:Completed) аж 3 плана (Showplan), причём первые два с пометками "Предупреждение: Столбцы без статистики" 

Последний из 3х планов выглядит отлично, но время сравнительно медленное. Смею предположить, что оно было потрачено на построение 2х первых "неподходящих" планов, после чего был инициирован пересчёт статистик по связанным объектам, и поэтому... (см. trace 8)

8. Менеджер с замещением без отбора, измерения не индексированы, статистика после обновления не обновлена, второе выполнение, почему-то уже ОДИН план вместо 3х до DELETE.trc

Мораль сей басни

1. Если не настроен регламентный достаточно частый пересчёт статистик, при надобности статистика пересчитается на лету, чем нагрузит базу данных в рабочее время, и незначительно будут замедлены запросы на построение не подходящих планов
2. Запись в независимый регистр сведений (набора из одной строки) оптимальней делать через менеджер записи, а не набором записей(с точки зрения производительности ниже риск непопадания в индекс + изящней в коде)

Конечный вариант оптимизации на этой конкретной задаче

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

Версия платформы, на которой проводились работы

8.3.16.1148, подозреваю, что на всех 8.3 будет аналогично.

Благодарности

1. Моему уважаемому коллеге, который нечаянно создал сложившуюся неоптимальность, чем подарил мне возможность провернуть все эти эксперименты и собрать материал для статьи
2. Дмитрию Юхтимовскому, за знания полученные на курсе и вообще 

Вместо эпилога

Всем добра, любви и процветания
Спасибо за внимание
До свидания! (с)

Что-нибудь жмите, что-нибудь пишите! (с)