1c-crm-red
От экспертов «1С-Рарус»: Зависание проведения документа при неоптимальных планах запросов из‑за Parameter sniffing в MS SQL. Сравнение с PostgreSQL
31.08.2022

От экспертов «1С-Рарус»: Зависание проведения документа при неоптимальных планах запросов из‑за Parameter sniffing в MS SQL. Сравнение с PostgreSQL

Непредсказуемое зависание сеанса пользователя при проведении документа в 1С

Сеть предприятий общественного питания ведет свою деятельность в «1С:УНФ 8. Управление предприятием общепита». После перехода на очередной релиз от пользователей стали поступать обращения, что при проведении документов в какой-то момент сеанс зависает и даже спустя 30–60 минут операции не завершаются. Зависание сеанса одного пользователя не вызывает замедление работы системы у остальных пользователей. Нагрузка на оборудование штатная и свободных ресурсов достаточно для нормальной работы.

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

Инфраструктура исследуемой системы

Программный продукт: 1С:УНФ 8. Управление предприятием общепита.
База данных: Microsoft SQL Server 2017 64х.
Платформа 1С:Предприятие 8: 8.3.20.1710 64х.
Операционная система: Windows Server 2012 R2.
Процессор: Intel(R) Xeon(R) Gold 6242R CPU @ 3.10GHz.
Оперативная память: 320 GB.
SSD: 3 TB.
Hypervisor: VMware ESXi, 7.0.3.

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

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

Поиск причин зависания сеанса пользователя

Собираем и анализируем логи технологического журнала

Получив данное обращение, мы поначалу оказались в небольшой растерянности. Поэтому сказали, давайте соберём логи ТЖ по событиям CALL, SDBL, DBMSSQL и посмотрим нет ли чего-то такого длительного. Хотя надежды особо не было найти, так как нерегулярность зависания любого выпуска подсказывала, что дело не в этом. Впрочем, а вдруг кто нашалил так, что длительная операция срабатывает при каких-либо сложных условиях. Ничего не обнаружили...

Второй гипотезой являлись блокировки данных. И не просто блокировки, а множество мелких блокировок, каждая из которых не достигает порога в 20 секунд, но их много. Для их анализа был настроен сбор логов по событиям TLOCK, TTIIMEOUT, TDEADLOCK, EXCP.

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

Полный текст файла logcfg.xml:


<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
       <log history="24" location="d:\logs">
             <property name="all"/>
             <event>
                    <eq property="name" value="TLOCK"/>
                    <eq property="p:processName" value="base_name"/>
             </event>
              <event>
                    <eq property="name" value="TDEADLOCK"/>
                    <eq property="p:processName" value="base_name"/>
             </event>
             <event>
                    <eq property="name" value="TTIMEOUT"/>
                    <eq property="p:processName" value="base_name"/>
             </event>
             <event>
                    <eq property="name" value="EXCP"/>
                    <eq property="p:processName" value="base_name"/>
             </event>
             <event>
                    <eq property="name" value="CALL"/>
                    <eq property="p:processName" value="base_name"/>
             </event>
             <event>
                    <eq property="name" value="SDBL"/>
                    <eq property="p:processName" value="base_name"/>
             </event>
             <event>
                    <eq property="name" value="DBMSSQL"/>
                    <eq property="p:processName" value="base_name"/>
             </event>
       </log>
       <dump location="d:\dumps\"
                    create="1"
                    type="0"
                    externaldump="1"/>
</config>

За время сбора логов по словам администратора возникло несколько таких зависаний хоть перепроведения и не запускались.

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

Собираем и анализирует логи технологического журнала

Приступим к анализу собранных логов. Их размер превышал 40 ГБ, поэтому для анализа используем bash-скрипты. Сначала посмотрим на длительность максимальных блокировок. Для этого выполняем следующие команды:

grep -i 'tlock' rphost_*/*.log| gawk -F '-' '{print $2 " " $1}'|sort -rnb|head -n 100

В результате можно увидеть, что блокировки есть, но начиная от 4 строки их длительность меньше 1 секунды.

6125036,TLOCK,4,process=rphost,p:processName=base_name,OSThread=10440,t:clientID=47,t:applicationName=1CV8C,t:computerName=SRV rphost_2908/22062816.log:50:33.518093
4874942,TLOCK,4,process=rphost,p:processName=base_name,OSThread=3020,t:clientID=62,t:applicationName=1CV8C,t:computerName=SRV rphost_2908/22062816.log:23:23.296003
3078003,TLOCK,4,process=rphost,p:processName=base_name,OSThread=10328,t:clientID=62,t:applicationName=1CV8C,t:computerName=SRV rphost_2908/22062816.log:26:44.317009
718849,TLOCK,4,process=rphost,p:processName=base_name,OSThread=8444,t:clientID=5041,t:applicationName=BackgroundJob,t:computerName=SRV rphost_2908/22062816.log:26:45.95803
608859,TLOCK,4,process=rphost,p:processName=base_name,OSThread=12536,t:clientID=51,t:applicationName=1CV8C,t:computerName=SRV rphost_2908/22062816.log:50:34.283068
421943,TLOCK,4,process=rphost,p:processName=base_name,OSThread=9088,t:clientID=62,t:applicationName=1CV8C,t:computerName=SRV rphost_2908/22062816.log:21:39.959128
188005,TLOCK,4,process=rphost,p:processName=base_name,OSThread=3020,t:clientID=5990,t:applicationName=BackgroundJob,t:computerName=SRV rphost_2908/22062816.log:53:14.32102

А вот блокировки, которые ожидали друг друга, заполняя свойство waitConnections — есть.

cat rphost_*/*.log| perl -pe 's/\n/<line>/g; s/(\d\d:\d\d\.\d+-)/\n\1/g'| grep -iP 'tlock,.*waitConnections=\d+'|perl -pe 's/<line>/\n/g' |head -n 100

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

10021:39.959128-421943,TLOCK,4,process=rphost,p:processName=base_name,OSThread=9088,t:clientID=62,t:applicationName=1CV8C,t:computerName=SRV,t:connectID=5887097,SessionID=12329,Usr=Пользователь2,AppID=1CV8C,DBMS=DBMSSQL,DataBase=10.1.0.64\base_name,Regions=AccumRg16825.DIMS,Locks='AccumRg16825.DIMS Exclusive Fld1254=0 Fld16826=226:8af5005056ad653711eafbc036d7d6d0 Fld16827=339:8afc005056ad653711eb674aacfbf722 Fld16828=67:81750050569766bb11e9c96ee9443ce3 Fld16829=216:81750050569766bb11e9d06b95cd9e33',WaitConnections=5892990,connectionID=6d456270-bdc8-4058-8f6d-af433763d226,Context='Форма.Записать : Документ.СборкаЗапасов.Форма.УОП_ФормаДокумента
Документ.СборкаЗапасов.МодульОбъекта : 687 : Документы.СборкаЗапасов.ИнициализироватьДанныеДокумента(Ссылка, ДополнительныеСвойства);
Документ.СборкаЗапасов.МодульМенеджера : 7511 : ИнициализироватьДанныеДокументаСборка(ДокументСсылкаСборкаЗапасов, СтруктураДополнительныеСвойства)
Документ.СборкаЗапасов.МодульМенеджера : 5856 : ИнициализироватьДанныеПоЗапасамСборка(ДокументСсылкаСборкаЗапасов, СтруктураДополнительныеСвойства, СуммаСборки);
Документ.СборкаЗапасов.МодульМенеджера : 2647 : СформироватьТаблицаЗапасыСборка(ДокументСсылкаСборкаЗапасов, СтруктураДополнительныеСвойства, СуммаСборки);
Документ.СборкаЗапасов.МодульМенеджера : 1050 : Блокировка.Заблокировать();'

Ранее длительные вызовы были проанализированы так:

cat rphost_*/*.log| perl -pe 's/\n/<line>/g; s/(\d\d:\d\d\.\d+-)/\n\1/g'| perl -pe 's/-/--/' |grep -iP ',Call,'| gawk -F '--' '{print $2 " " $1}'| sort -rnb |perl -pe 's/<line>/\n/g' |head -n 10000 > res_CALL.txt

Видим событие открытия формы документа «Инвентаризации запасов», которое выполнялось порядка 40 минут, а также еще ряд длительных операций по 30 и 13 минут. То есть в системе попутно обнаруживались неприятности, которые надо было исправлять, но пока речь не о них.

2468136943,CALL,1,process=rphost,p:processName=base_name,OSThread=9412,t:clientID=75,t:applicationName=1CV8C,t:computerName=SRV,t:connectID=5887148,callWait=0,first=true,Usr=Пользователь1,SessionID=12524,Context=Система.ПолучитьФорму : Документ.ИнвентаризацияЗапасов.ФормаОбъекта,Interface=bc15bd01-10bf-413c-a856-ddc907fcd123,IName=IVResourceRemoteConnection,Method=0,CallID=9991,MName=send,Memory=25590833,MemoryPeak=69635025,InBytes=49110,OutBytes=65730713,CpuTime=30812500
04:38.871038 1992482070,CALL,1,process=rphost,p:processName=base_name,t:clientID=66,t:applicationName=1CV8C,t:computerName=SRV,t:connectID=5887121,callWait=0
39:47.034087 838663041,CALL,1,process=rphost,OSThread=5296,t:clientID=6083,callWait=0,first=true,Usr=Пользователь2,SessionID=16772(12329),p:processName=base_name,Func=Backgroundjob,Module=ДлительныеОперации,Method=ВыполнитьСКонтекстомКлиента,Memory=-16050379,MemoryPeak=46637653,InBytes=420300,OutBytes=847449608,CpuTime=127828125
02:51.479100 785266020,CALL,1,process=rphost,OSThread=3020,t:clientID=5990,callWait=0,first=true,Usr=Пользователь3,SessionID=16744(12581),p:processName=base_name,Func=Backgroundjob,Module=ДлительныеОперации,Method=ВыполнитьСКонтекстомКлиента,Memory=-27457514,MemoryPeak=202644686,InBytes=35370305,OutBytes=1237823678,CpuTime=204593750
59:24.178038

Так, что же делать? Давайте соберем логи по запросам еще раз, вдруг мы что-то пропустили или собрали не в тот момент. Посмотрим на топ выполненных длительных запросов по событию SDBL:

cat rphost_*/*.log| perl -pe 's/\n/<line>/g; s/(\d\d:\d\d\.\d+-)/\n\1/g'| perl -pe 's/-/--/' |grep -iP ',SDBL,'| gawk -F '--' '{print $2 " " $1}'| sort -rnb |perl -pe 's/<line>/\n/g' |head -n 10000 > res_SDBL.txt

В результате можно увидеть запрос, который выполнялся почти все 40 минут события CALL. А это уже зацепка за нужное направление!

2427575020,SDBL,2,process=rphost,p:processName=base_name,OSThread=9412,t:clientID=75,t:applicationName=1CV8C,t:computerName=SRV-TERMINAL2,t:connectID=5887148,SessionID=12524,Usr=Пользователь1,AppID=1CV8C,DBMS=DBMSSQL,DataBase=10.1.0.64\base_name,Trans=0,Func=HoldConnection,Context='Система.ПолучитьФорму : Документ.ИнвентаризацияЗапасов.ФормаОбъекта
Документ.ИнвентаризацияЗапасов.МодульОбъекта : 54 : УОП_ЗаполнитьНаОснованииВыпускаПродукции(ДанныеЗаполнения);
Документ.ИнвентаризацияЗапасов.МодульОбъекта : 156 : ВыпускПродукции.УОП_ЗаполнитьПроизводство();
Документ.СборкаЗапасов.МодульОбъекта : 4263 : МодульПроизводства.ЗаполнитьПроизводство(СтруктураОбъекта);
ОбщийМодуль.УОП_Производство.Модуль : 496 : ЗаполнитьПроизводствоДоИнтерактива(СтруктураОбъекта, ДопДанные);
ОбщийМодуль.УОП_Производство.Модуль : 600 : ЗаполнитьПроизводственыеТаблицы(ТаблицаПроизводства, ТаблицаЗамен, СтруктураОбъекта.ПартионныеПотери, СтруктураПараметров, СтруктураОбъекта.ВидПроизводства);
ОбщийМодуль.УОП_Производство.Модуль : 3162 : РезультатЗапроса = Запрос.Выполнить();'

Полный текст события с приведенным запросом:

2427419046,SDBL,3,process=rphost,p:processName=base_name,OSThread=9412,t:clientID=75,t:applicationName=1CV8C,t:computerName=SRV,t:connectID=5887148,SessionID=12524,Usr=Пользователь1,AppID=1CV8C,DBMS=DBMSSQL,DataBase=10.1.0.64\base_name,Trans=0,Sdbl='SELECT
Q_001_T_001.Q_000_F_000,
Q_001_T_001.Q_000_F_001,
CASE  WHEN (Q_001_T_003.Fld20776  =  172:81750050569766bb11e9c96ee9443d96) THEN 99999999999.999 WHEN (Q_001_T_001.Q_000_F_002 < 0) THEN 0 ELSE Q_001_T_001.Q_000_F_002 END ,
Q_001_T_001.Q_000_F_003,
Q_001_T_001.Q_000_F_004,
ISNULL(Q_001_T_002.Fld15726, 1),
Q_001_T_004.Fld21496 sf_1,
CASE
WHEN Q_001_T_004.Fld21494 REFS Document537 THEN
CAST(Q_001_T_004.Fld21494 AS REF(Document537)).Date_Time
WHEN Q_001_T_004.Fld21494 REFS Document506 THEN
CAST(Q_001_T_004.Fld21494 AS REF(Document506)).Date_Time
WHEN Q_001_T_004.Fld21494 REFS Document594 THEN
CAST(Q_001_T_004.Fld21494 AS REF(Document594)).Date_Time
WHEN Q_001_T_004.Fld21494 REFS Document445 THEN
CAST(Q_001_T_004.Fld21494 AS REF(Document445)).Date_Time
WHEN Q_001_T_004.Fld21494 REFS Document466 THEN
CAST(Q_001_T_004.Fld21494 AS REF(Document466)).Date_Time
ELSE NULL END
sf_2
FROM
#Tf645a34eb03844fe9964aeede06c5784 Q_001_T_001 LEFT JOIN InfoRg15723 Q_001_T_002 ON (Q_001_T_001.Q_000_F_000  =  Q_001_T_002.Fld15724) AND (Q_001_T_001.Q_000_F_003  =  Q_001_T_002.Fld15725) LEFT JOIN Reference216 Q_001_T_003 ON (Q_001_T_001.Q_000_F_000  =  Q_001_T_003.ID) LEFT JOIN Reference250 Q_001_T_004 ON (Q_001_T_001.Q_000_F_003  =  Q_001_T_004.ID)
WHERE
(Q_001_T_001.Q_000_F_002 > 0)

ORDER BY
sf_1,
sf_2
',Rows=1,Context='Система.ПолучитьФорму : Документ.ИнвентаризацияЗапасов.ФормаОбъекта
Документ.ИнвентаризацияЗапасов.МодульОбъекта : 54 : УОП_ЗаполнитьНаОснованииВыпускаПродукции(ДанныеЗаполнения);
Документ.ИнвентаризацияЗапасов.МодульОбъекта : 156 : ВыпускПродукции.УОП_ЗаполнитьПроизводство();
Документ.СборкаЗапасов.МодульОбъекта : 4263 : МодульПроизводства.ЗаполнитьПроизводство(СтруктураОбъекта);
ОбщийМодуль.УОП_Производство.Модуль : 496 : ЗаполнитьПроизводствоДоИнтерактива(СтруктураОбъекта, ДопДанные);
ОбщийМодуль.УОП_Производство.Модуль : 600 : ЗаполнитьПроизводственыеТаблицы(ТаблицаПроизводства, ТаблицаЗамен, СтруктураОбъекта.ПартионныеПотери, СтруктураПараметров, СтруктураОбъекта.ВидПроизводства);
ОбщийМодуль.УОП_Производство.Модуль : 3162 : РезультатЗапроса = Запрос.Выполнить();'

Данный запрос в контексте 1С:

ВЫБРАТЬ
ВТ_ОстаткиТоваров.Ингредиент КАК Ингредиент,
ВТ_ОстаткиТоваров.Характеристика КАК Характеристика,
ВТ_ОстаткиТоваров.Количество КАК Количество,
&ПараметрСниффинг2 КАК ПараметрСниффинг,
ВТ_ОстаткиТоваров.Партия КАК Партия,
ВТ_ОстаткиТоваров.ЗаказПокупателя КАК ЗаказПокупателя,
ЕСТЬNULL(ОбработкаСырья.Коэффициент, 1) КАК КоэффициентПартионныхПотерь
ИЗ
ВТ_ОстаткиТоваров КАК ВТ_ОстаткиТоваров
ЛЕВОЕ СОЕДИНЕНИЕ РегистрСведений.УОП_ОбработкаСырьяПартионная КАК ОбработкаСырья
ПО ВТ_ОстаткиТоваров.Ингредиент = ОбработкаСырья.Ингредиент
И ВТ_ОстаткиТоваров.Партия = ОбработкаСырья.Партия
ЛЕВОЕ СОЕДИНЕНИЕ Справочник.ПартииНоменклатуры КАК ПартииНоменклатуры
ПО ВТ_ОстаткиТоваров.Партия = ПартииНоменклатуры.Ссылка

УПОРЯДОЧИТЬ ПО
ПартииНоменклатуры.УОП_СрокГодности
ПартииНоменклатуры.УОП_ДокументПартии.Дата

По тексту запросов можно увидеть, что временная таблица соединяется с регистром сведений «Обработка cырья» (InfoRg15723) и со справочниками «Номенклатура» (Reference216) и «Партии номенклатуры» (Reference250) левыми соединениями.

При этом регистр сведений «Обработка сырья» у клиента не содержит записей вообще, а к справочникам идет соединение по ссылкам и кажется, что запрос вполне обычный. Да и после завершения зависшего сеанса, данный запрос отрабатывает меньше, чем за одну секунду. Что вызывает чувство противоречия и непонимания, т. к. у нас есть запрос, который в один момент времени отрабатывает за секунду, а в другой за 40 минут.

Подозреваем 1С:СЛК

Почему этот запрос один раз выполняется быстро, а в другой раз медленно? Сам запрос выполняется в рамках логики, зашифрованной с помощью компоненты защиты 1С:СЛК, которую обновляли как раз в данном релизе, но так совпало, что после выхода релиза «1С:Управление предприятием общепита» была выпущена новая версия компоненты 1С:СЛК. Т. к. срок между крайними релизами компоненты оказался слишком маленьким, а мы имеем непонятную ситуацию с запросом, то появляется подозрение на причастность данной компоненты к непонятным зависаниям. Однако, по итогу ее обновление не помогло и версия не подтвердилась.

Подозреваем 1С:СЛК

Подозреваем 1С:СЛК

Наблюдаем за поведением кластера серверов 1С и СУБД

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

Данная ситуация произошла буквально через несколько часов. В момент подключения снимаем значения показателей сеансов с периодом в 30–40 секунд и сохраняем в формате csv.

Наблюдаем за поведением кластера серверов 1С и СУБД

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

Номер сеанса Пользователь Время вызова СУБД (всего) Время вызовов (5 мин) Время вызова (всего)
12632 Пользователь1 550,484 550,422 557,703
12632 Пользователь1 723,609 723,547 730,828
12632 Пользователь1 764,734 764,672 771,953

Принимаем решение заглянуть в Management Studio и с помощью следующего текста запроса посмотреть выполняемые запросы:

SELECT
session_id,
status,
wait_type,
command,
last_wait_type,
qt.text as sql_text,
total_elapsed_time/1000 as [total_elapsed_time, sec], 
wait_time/1000 as [wait_time, sec],
(total_elapsed_time - wait_time)/1000 as [work_time, sec],
percent_complete
FROM sys.dm_exec_requests as qs 
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) as qt 
where session_id >= 50 and session_id <> @@spid

Наблюдаем за поведением кластера серверов 1С и СУБД

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

Стоит отметить, что информацию о выполняемых запросах также можно получить в Activity Monitor применив отборы по номеру процесса указанному в кластере серверов.

Наблюдаем за поведением кластера серверов 1С и СУБД

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

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

  • Запрос не использует индексы.
  • Соединение устанавливается не по правильным полям.
  • Выбираемые данные отбираются слишком поздно.

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

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

В статье «Очистка процедурного кэша SQL для 1C. Мифы, реальность, практика» мы уже упоминали про план запросов, но давайте еще раз вспомним что это.

Язык запросов 1С, как и язык sql-запросов, является декларативным, т. е. мы говорим, что нам нужно найти, а не что нужно выполнять, чтобы найти. Задачей преобразования этого «что нужно» в «как это искать» занимается оптимизатор запросов. Данная компонента основываясь на информации о схеме базы данных, статистике и тексте выполняемого запроса формирует различные последовательности операций, которые приводят к требуемому результату.

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

Почему предполагаемую? При выполнении запроса данная компонента Microsoft SQL Server отталкиваясь от статистики сначала формирует именно предполагаемый план запроса (estimated execution plan), который и помещается в кэш, а уже после выполнения формируется фактический план запроса (actual execution plan), который дополняет предполагаемый план уже фактическими данными. Например, такими как: среда выполнения, затраченное время, время ЦП, количество выбираемых строк и многое другое.

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

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

ВЫБРАТЬ
СпрНоменклатура.Ссылка КАК Номенклатура
ИЗ
Справочник.Номенклатура КАК СпрНоменклатура
ГДЕ
СпрНоменклатура.Наименование ПОДОБНО &НаименованиеНоменклатуры

Эксперимент будем проводить на клиент-серверной базе. В качестве системы управления базами данных выступит Microsoft SQL Server.

Сначала для чистоты эксперимента очистим кэш планов. Для этого воспользуемся инструкцией DBCC FREEPROCCACHE.

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

Для сбора планов запроса можно воспользоваться средствами СУБД или собрать лог технологического журнала. Чтобы включить сбор планов запроса в логе технологического журнала необходимо в файл logcfg.xml добавить тег <plansql />. Подробнее про данную возможность по ссылке https://its.1c.ru/db/v8320doc/bookmark/adm/TI000000401.

Пример текста файла logcfg.xml с включенным сбором планов запроса:

<?xml version="1.0"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
  <log location="c:\log" history="24">
    <event>
      <eq property="name" value="dbmssql"/>
    </event>
    <property name="sql"/>
    <property name="plansqltext"/>
  </log>
  <plansql />
</config>

В результате получим событие, где в Sql размещается выполняемый текст запроса на уровне СУБД, а в planSQLText — план запроса:

45:07.994004-1,DBMSSQL,5,Sql="SELECT
T1._IDRRef
FROM dbo._Reference141 T1
WHERE ((T1._Fld929 = ?)) AND ((T1._Description LIKE ?))
p_0: 0N
p_1: 'Пельмешки%'
",planSQLText='
0, 1, 1.95, 0.00313, 0.000159, 127, 0.00328, 1,  |--Nested Loops(Inner Join, OUTER REFERENCES:([Expr1004], [Expr1005], [Expr1006]))
0, 0, 1, 0, 0, 8017, 0, 1,  |--Compute Scalar(DEFINE:([Expr1004]=LikeRangeStart([@P2]), [Expr1005]=LikeRangeEnd([@P2]), [Expr1006]=LikeRangeInfo([@P2])))
1, 1, 1, 0, 0, 0, 0, 1,  |    |--Constant Scan
0, 1, 1.95, 0.00313, 0.000159, 127, 0.00328, 1,  |--Index Seek(OBJECT:([grimut_upo3].[dbo].[_Reference141].[_Reference141_5] AS [T1]), SEEK:([T1].[_Fld929]=[@P1] AND [T1].[_Description] > [Expr1004] AND [T1].[_Description] < [Expr1005]),  WHERE:([grimut_upo3].[dbo].[_Reference141].[_Description] as [T1].[_Description] like [@P2]) ORDERED FORWARD)
'

Если же выполнить сбор плана средствами Extended Events Microsoft SQL Server по событиям query_post_compilation_showplan, query_post_execution_showplan и sql_batch_completed:

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

То в результате можно получить такой предварительный план запроса:

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

И такой фактический план запроса:

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

Создадим новый элемент справочника, попадающий под условие, и попробуем перевыполнить запрос. В результате СУБД сформирует только фактический план запроса, а предполагаемый возьмет из кэша:

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

В этом также можно убедиться по значению свойства QueryPlanHash, которое можно увидеть в XML представлении плана и оно же будет сохраняться для данного запроса:

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

Стоит отметить, что если мы изменим значение параметра НаименованиеНоменклатуры, например, на «Пюрешка» то план запроса все равно не поменяется:

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

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

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

Механизм сканирования параметров parameter sniffing

Данное поведение объясняется включенным механизмом сканирования параметров (parameter sniffing), который позволяет оптимизатору запросов не учитывать параметры при подборе плана из кэша.

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

Представим себе периодический регистр сведений «Цены номенклатуры» с измерениями «Номенклатура» и «Организация». Измерение «Организация» будет дополнительно индексировано:

Механизм сканирования параметров parameter sniffing

Механизм сканирования параметров parameter sniffing

В данном регистре будут фиксироваться цены организаций ООО «Плюшка-пампушка» и ИП «Пюрюшка с котлеткой» в процентом соотношении записей 99,9% к 0,1% соответственно:

Механизм сканирования параметров parameter sniffing

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

ВЫБРАТЬ
       ЦеныНоменклатуры.Период КАК Период,
       ЦеныНоменклатуры.Номенклатура КАК Номенклатура,
       ЦеныНоменклатуры.Организация КАК Организация,
       ЦеныНоменклатуры.Цена КАК Цена
ИЗ
       РегистрСведений.ТЦ_ЦеныНоменклатуры КАК ЦеныНоменклатуры
ГДЕ
       ЦеныНоменклатуры.Организация = &Организация

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

Механизм сканирования параметров parameter sniffing

Механизм сканирования параметров parameter sniffing

Как можно увидеть планы между собой отличаются. Для организации с меньшим количеством записей система приняла решение воспользоваться поиском по некластерном индексу с помощью Index seek, а потом дополняет информацию соединив с результатом поиска по кластерному индексу (Key lookup). Для организации с большим количеством записей система решила воспользоваться Clustered Index Scan, тем самым сразу просканировала по кластерному индексу.

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

Можно ли отключать parameter sniffing?

Вы можете спросить, а можно ли отключить механизм сканирования параметров (parameter sniffing) и как?

Для этого необходимо отключить флаг трассировки 4136 или начиная с версии SQL Server 2016 (13.x) это можно сделать на уровне базы данных:

Можно ли отключать parameter sniffing?

Отключение данного механизма будет работать только если в запросе не используются OPTION(RECOMPILE), WITH RECOMPILE или OPTIMIZE FOR, но их из платформы 1С:Предприятие 8 и не прилетит.

В результате отключения данного механизма из плана запроса пропадет свойство ParameterCompiledValue и планы будут формироваться заново после каждого выполнения запроса:

Можно ли отключать parameter sniffing?

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

Результат поиска причин зависания пользовательского сеанса

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

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

Время выполнения Операция Количество элементов
17:49:30 f0a167fb-eff7-4d0a-a533-fca0f62e30d1 729
17:50:54 fbbc2e75-b7d7-4b22-bf2d-12dbea06d70c 686
17:51:18 55aa4559-dce7-4f2d-b907-4750987a77de 5
17:51:20 3d49abf7-f7ce-42ca-a60c-27dfb09d0227 30
17:52:31 3d49abf7-f7ce-42ca-a60c-27dfb09d0227 2

Устраняем причины зависания сеансов пользователей

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

Самый простой способ, который доступен из платформы «1С:Предприятие 8» без дополнительных настроек СУБД — формировать текст запроса динамически. Тогда для СУБД данный запрос будет казаться новым и план запроса будет сформирован заново.

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

В упрощенном виде это выглядит приблизительно так:

ТекстЗапроса = "ВЫБРАТЬ
|      ВТ_ОстаткиТоваров.Ингредиент КАК Ингредиент,
|      ВТ_ОстаткиТоваров.Характеристика КАК Характеристика,
|      ВТ_ОстаткиТоваров.Количество КАК Количество,
|      &ПараметрСниффинг2 КАК ПараметрСниффинг,
|      ВТ_ОстаткиТоваров.Партия КАК Партия,
|      ЕСТЬNULL(ОбработкаСырья.Коэффициент, 1) КАК КоэффициентПартионныхПотерь
|ИЗ
|      ВТ_ОстаткиТоваров КАК ВТ_ОстаткиТоваров
|            ЛЕВОЕ СОЕДИНЕНИЕ РегистрСведений.УОП_ОбработкаСырьяПартионная КАК ОбработкаСырья
|            ПО ВТ_ОстаткиТоваров.Ингредиент = ОбработкаСырья.Ингредиент
|                   И ВТ_ОстаткиТоваров.Партия = ОбработкаСырья.Партия
|            ЛЕВОЕ СОЕДИНЕНИЕ Справочник.ПартииНоменклатуры КАК ПартииНоменклатуры
|            ПО ВТ_ОстаткиТоваров.Партия = ПартииНоменклатуры.Ссылка
|
|УПОРЯДОЧИТЬ ПО
|      ПартииНоменклатуры.УОП_СрокГодности";
ТекстЗапроса = СтрЗаменить(ТекстЗапроса, "&ПараметрСниффинг2", Строка(Новый УникальныйИдентификатор));

Но когда мы решили проверить данный запрос, то на уровне СУБД увидели следующий текст запроса SQL:

(@P1 nvarchar(4000),@P2 numeric(10),@P3 numeric(10),@P4 numeric(10),@P5 numeric(10),@P6 numeric(10),@P7 numeric(10),@P8 numeric(10),@P9 numeric(10),@P10 numeric(10),@P11 numeric(10),@P12 numeric(10),@P13 numeric(10))
SELECT
       T1._Q_000_F_000RRef,
       T1._Q_000_F_001RRef,
       T1._Q_000_F_003,
       @P1,
       T1._Q_000_F_004RRef,
       T1._Q_000_F_005RRef,
       ISNULL(CAST(T2._Fld19343 AS NUMERIC(8, 4)),1.0),
       T3._Fld4356,
       CASE WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x000001A6 THEN T4._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x0000018A THEN T5._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00006230 THEN T6._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000159 THEN T7._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000162 THEN T8._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x000001B3 THEN T9._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x0000019A THEN T10._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000174 THEN T11._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x0000015F THEN T12._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000185 THEN T13._Date_Time ELSE CAST(NULL AS DATETIME) END
FROM #tt34 T1 WITH(NOLOCK)

Платформа «1С:Предприятие 8» самостоятельно обернула данное поле в параметр запроса. Хотя еще пару релизов платформы назад этот вариант срабатывал «на ура». Причину почему разработчики платформы так сделали можно понять: все для того же сокращения количества формирования планов запросов и оптимизации их количества в буферном кэше.

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

ГСЧ = Новый ГенераторСлучайныхЧисел(ТекущаяУниверсальнаяДатаВМиллисекундах());
Слагаемое = ГСЧ.СлучайноеЧисло(0, 429496729) + ГСЧ.СлучайноеЧисло(0, 4294967295);
Слагаемое = ГСЧ.СлучайноеЧисло(0, 429496725) + ГСЧ.СлучайноеЧисло(0, 4294967295);

ТекстЗапроса = СтрЗаменить(ТекстЗапроса, "&Слагаемое1", Слагаемое1);
ТекстЗапроса = СтрЗаменить(ТекстЗапроса, "&Слагаемое2", Слагаемое2);

Однако выполнив этот запрос, мы увидели, что платформа выполняет данную арифметическую операции заранее, а результат передает все также через параметр. Следовательно, данный вариант не подойдет:

(@P1 numeric(10),@P2 numeric(10),@P3 numeric(10),@P4 numeric(10),@P5 numeric(10),@P6 numeric(10),@P7 numeric(10),@P8 numeric(10),@P9 numeric(10),@P10 numeric(10),@P11 numeric(10),@P12 numeric(10),@P13 numeric(10))
SELECT
       T1._Q_000_F_000RRef,
       T1._Q_000_F_001RRef,
       T1._Q_000_F_003,
       @P1,
       T1._Q_000_F_004RRef,
       T1._Q_000_F_005RRef,
       ISNULL(CAST(T2._Fld19343 AS NUMERIC(8, 4)),1.0),
       T3._Fld4356,
       CASE WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x000001A6 THEN T4._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x0000018A THEN T5._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00006230 THEN T6._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000159 THEN T7._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000162 THEN T8._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x000001B3 THEN T9._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x0000019A THEN T10._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000174 THEN T11._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x0000015F THEN T12._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000185 THEN T13._Date_Time ELSE CAST(NULL AS DATETIME) END
FROM #tt34 T1 WITH(NOLOCK)

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

ТекстЗапроса = "ВЫБРАТЬ
|      ВТ_ОстаткиТоваров.Ингредиент КАК Ингредиент,
|      ВТ_ОстаткиТоваров.Характеристика КАК Характеристика,
|      ВТ_ОстаткиТоваров.Количество КАК Количество,
|      ВТ_ОстаткиТоваров.Количество + &Слагаемое1 + &Слагаемое2 КАК ПараметрСниффинг,
|      ВТ_ОстаткиТоваров.Партия КАК Партия,
|      ЕСТЬNULL(ОбработкаСырья.Коэффициент, 1) КАК КоэффициентПартионныхПотерь
|ИЗ
|      ВТ_ОстаткиТоваров КАК ВТ_ОстаткиТоваров
|            ЛЕВОЕ СОЕДИНЕНИЕ РегистрСведений.УОП_ОбработкаСырьяПартионная КАК ОбработкаСырья
|            ПО ВТ_ОстаткиТоваров.Ингредиент = ОбработкаСырья.Ингредиент
|                   И ВТ_ОстаткиТоваров.Партия = ОбработкаСырья.Партия
|            ЛЕВОЕ СОЕДИНЕНИЕ Справочник.ПартииНоменклатуры КАК ПартииНоменклатуры
|            ПО ВТ_ОстаткиТоваров.Партия = ПартииНоменклатуры.Ссылка
|
|УПОРЯДОЧИТЬ ПО
|      ПартииНоменклатуры.УОП_СрокГодности";

ГСЧ = Новый ГенераторСлучайныхЧисел(ТекущаяУниверсальнаяДатаВМиллисекундах());
Слогаемое1 = ГСЧ.СлучайноеЧисло(0, 429496729) + ГСЧ.СлучайноеЧисло(0, 4294967295);
Слогаемое1 = ГСЧ.СлучайноеЧисло(0, 429496725) + ГСЧ.СлучайноеЧисло(0, 4294967295);

ТекстЗапроса = СтрЗаменить(ТекстЗапроса, "&Слогаемое1", Слогаемое1);
ТекстЗапроса = СтрЗаменить(ТекстЗапроса, "&Слогаемое2", Слогаемое2);

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

Устраняем причины зависания сеансов пользователей

Основная часть текста запроса, которая была выполнена:

(@P1  numeric(10),@P2 numeric(10),@P3 numeric(10),@P4 numeric(10),@P5 numeric(10),@P6  numeric(10),@P7 numeric(10),@P8 numeric(10),@P9 numeric(10),@P10 numeric(10),@P11 numeric(10),@P12 numeric(10))
SELECT
T1._Q_000_F_000RRef,
T1._Q_000_F_001RRef,
T1._Q_000_F_003,
((T1._Q_000_F_003 + 23423.0) + 454631.0),
T1._Q_000_F_004RRef,
T1._Q_000_F_005RRef,
ISNULL(CAST(T2._Fld19343 AS NUMERIC(8, 4)),1.0),
T3._Fld4356,
CASE WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x000001A6 THEN T4._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x0000018A THEN T5._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00006230 THEN T6._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000159 THEN T7._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000162 THEN T8._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x000001B3 THEN T9._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x0000019A THEN T10._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000174 THEN T11._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x0000015F THEN T12._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000185 THEN T13._Date_Time ELSE CAST(NULL AS DATETIME) END FROM #tt34 T1 WITH(NOLOCK)

Мы выяснили, что арифметическая операция над полем решает данную проблему, а константы в полях преобразовываются в параметры, но что будет если просто вставить заранее верное условие в область ГДЕ? Т. е. когда значение параметров &Параметр1 и &Параметр2 равны. Тогда текст запроса выглядел бы так:

ТекстЗапроса = "ВЫБРАТЬ
|      ВТ_ОстаткиТоваров.Ингредиент КАК Ингредиент,
|      ВТ_ОстаткиТоваров.Характеристика КАК Характеристика,
|      ВТ_ОстаткиТоваров.Количество КАК Количество,
|      &ПараметрСниффинг2 КАК ПараметрСниффинг,
|      ВТ_ОстаткиТоваров.Партия КАК Партия,
|      ЕСТЬNULL(ОбработкаСырья.Коэффициент, 1) КАК КоэффициентПартионныхПотерь
|ИЗ
|      ВТ_ОстаткиТоваров КАК ВТ_ОстаткиТоваров
|            ЛЕВОЕ СОЕДИНЕНИЕ РегистрСведений.УОП_ОбработкаСырьяПартионная КАК ОбработкаСырья
|            ПО ВТ_ОстаткиТоваров.Ингредиент = ОбработкаСырья.Ингредиент
|                   И ВТ_ОстаткиТоваров.Партия = ОбработкаСырья.Партия
|            ЛЕВОЕ СОЕДИНЕНИЕ Справочник.ПартииНоменклатуры КАК ПартииНоменклатуры
|            ПО ВТ_ОстаткиТоваров.Партия = ПартииНоменклатуры.Ссылка
|
|ГДЕ
|      &ПараметрСниффинг1 = &ПараметрСниффинг2
|
|УПОРЯДОЧИТЬ ПО
|      ПартииНоменклатуры.УОП_СрокГодности";
ЗначениеПараметра = Строка(Новый УникальныйИдентификатор);
ТекстЗапроса = СтрЗаменить(ТекстЗапроса, "&ПараметрСниффинг1", ЗначениеПараметра);
ТекстЗапроса = СтрЗаменить(ТекстЗапроса, "&ПараметрСниффинг2", ЗначениеПараметра);

Если посмотреть на выполняемый текст запроса, то можно увидеть, что условие преобразовалось в 1 = 1. Причем значения параметров не влияют на результат, т. е. можно передать ГУИД = ГУИД или Число = Число или АрифметическаяОперация1 = АрифметическаяОперация2 — все преобразовывается в 1 = 1. Даже если выполнять несколько пар с разными значениями.

Следовательно, динамическое изменение текста в данном случае не поможет:

(@P1 numeric(10),@P2 numeric(10),@P3 numeric(10),@P4 numeric(10),@P5 numeric(10),@P6 numeric(10),@P7 numeric(10),@P8 numeric(10),@P9 numeric(10),@P10 numeric(10),@P11 numeric(10),@P12 numeric(10))
SELECT
T1._Q_000_F_000RRef,
T1._Q_000_F_001RRef,
T1._Q_000_F_003,
T1._Q_000_F_004RRef,
T1._Q_000_F_005RRef,
ISNULL(CAST(T2._Fld19343 AS NUMERIC(8, 4)),1.0),
T3._Fld4356,
CASE WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x000001A6 THEN T4._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x0000018A THEN T5._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00006230 THEN T6._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000159 THEN T7._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000162 THEN T8._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x000001B3 THEN T9._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x0000019A THEN T10._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000174 THEN T11._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x0000015F THEN T12._Date_Time WHEN T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x00000185 THEN T13._Date_Time ELSE CAST(NULL AS DATETIME) END
FROM #tt34 T1 WITH(NOLOCK)
LEFT OUTER JOIN dbo._InfoRg19340 T2
ON ((T1._Q_000_F_000RRef = T2._Fld19341RRef) AND (T1._Q_000_F_004RRef = T2._Fld19342RRef)) AND (T2._Fld929 = @P1)
LEFT OUTER JOIN dbo._Reference181 T3
ON ((T1._Q_000_F_004RRef = T3._IDRRef)) AND (T3._Fld929 = @P2)
LEFT OUTER JOIN dbo._Document422 T4
ON (T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x000001A6 AND T3._Fld4354_RRRef = T4._IDRRef) AND (T4._Fld929 = @P3)
LEFT OUTER JOIN dbo._Document394 T5
ON (T3._Fld4354_TYPE = 0x08 AND T3._Fld4354_RTRef = 0x0000018A AND T3._Fld4354_RRRef = T5._IDRRef) AND (T5._Fld929 = @P4)
WHERE 1=1
ORDER BY (T3._Fld4356)

Несмотря на динамическое изменение текста запроса платформа «1С:Предприятие 8» дополнительно старается помочь оптимизировать количество построение планов. Из всех рассматриваемых нами вариантов лишь арифметическая операция над полем выборки позволила решить задачу принудительного перестроения планов запроса.

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

Мы проанализировали события логирования в журнале регистрации и увидели, что все запросы, которые начинали выполняться — завершились. Что подтверждало факт отсутствия обращений от пользователей:

Устраняем причины зависания сеансов пользователей

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

Стоит отметить, что в Microsoft SQL Server есть дополнительные возможности влияния на решения оптимизатора запроса. Одним из них является механизм хинтов.

Данных механизм переопределяет поведение оптимизатора запросов на время выполнения SQL-инструкции.

Однако, повлиять с помощью хинта со стороны платформы не получиться. Для этого потребуется настроить новое руководство планов (Plan Guides):

Устраняем причины зависания сеансов пользователей

Устраняем причины зависания сеансов пользователей

В результате оптимизатор запросов будет добавлять выбранный хинт к запросу. На картинке представлена команда запуска рекомпиляции плана, но в данное поле можно добавить уже фиксированный план. Подробнее про данный механизм можно прочитать в документации https://docs.microsoft.com/ru-RU/sql/relational-databases/performance/plan-guides?view=sql-server-ver15.

Альтернативный способ — Force plan

Альтернативным способом решения задачи может стать Force Plan от MS SQL. Таким подходом можно воспользоваться, например, когда нельзя вносить изменения в типовое решение, стоящее на поддержке.

Force plan это функционал блока Query Store, который появился в версии SQL Server 2016 CTP2. Query Store — это хранилище планов запросов и статистической информации для каждой базы данных в отдельности.

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

Проведём подготовительные работы для использования Force plan

Для включения функции Query Store необходимо в настройках базы установить Operation mode в режим Read Write, т. е. сервер будет как собирать, так и сохранять данные запросов:

Проведём подготовительные работы для использования Force plan

Коротко о настройках Query Store:

General

  • Operation Mode(Actual) — текущий режим работы.
  • Operation Mode(Requested) — желаемый режим работы.
    • Off — Query Store выключен.
    • Read Only — режим только чтения, т. е. новые планы не пишутся в память.
    • Read Write — чтение и запись планов.

Monitoring

  • Data Flush Interval (Minutes) — периодичность в минутах, с которой данные планов записываются на диск, так же в момент записи проверяется достижение предельного объема памяти для Query Store.
  • Statistics Collection Interval — определяет длительность временного окна, в течение которого собирается статистика времени выполнения для планов запросов. Чем меньше значение этого интервала, тем чаще будет сохранение статистики, но учтите, что это потребует больше дискового пространства.

Query Store Retention

  • Max Size (MB) — объем памяти, отводимый под хранилище запросов. информация хранится непосредственно в базе. Если достигнут предельный объем то хранилище переходит в режим Read Only.
  • Query Store Capture Mode — режим записи текущего активного запроса.
    • Auto — Записываются соответствующие запросы на основе показателя выполнения и объема потребления ресурсов.
    • All — все запросы.
    • None — новые запросы не пишутся, только обновляется информация по уже ранее записанным запросам.
  • Size Based Cleanup Mode — режим автоматической очистки.
    • Auto — при достижении потребляемой памяти 90% от максимального объема памяти удаляются самые дешевые и старые запросы, пока объем не снизится до 80%.
    • Off — автоматическая очистка не выполняется.
  • Stale Query Threshold (Days) — Период хранения устаревших запросов. Для динамически развиваемого решения рекомендуется ставить период побольше, например, 90 дней. Для стабильной системы 30 дней хватит.

Так же это можно сделать запросом:

ALTER DATABASE <database_name>
SET QUERY_STORE = ON (OPERATION_MODE = READ_WRITE);

Где <database_name> — это имя базы для которой хотим включить хранилище запросов.

После включения хранилища запросов в дереве объектов нашей базы появится соответствующая папка Query Store:

Проведём подготовительные работы для использования Force plan

Которая содержит следующие варианты срезов:

  • Regressed Queries — запросы, по которым показатели ухудшились.
  • Overall Resource Consumption — общее потребление ресурсов для базы в целом.
  • Top Resource Consuming Queries — самые затратные запросы.
  • Queries With Forced Plans — запросы по которым используется принудительное использование форсированных планов.
  • Queries With High Variation — запросы, по которым высокий разброс показателей производительности.
  • Tracked Queries — монитор показателей выбранных запросов.

Настраиваем использование Force plan

Возьмем пример с периодическим регистром сведений «Цены номенклатуры». Ранее мы разобрались, что в зависимости от первоочередности запроса кэшировался первый или второй план. Давайте форсируем оптимальный план для обоих случаев и посмотрим, что получится.

После включения Query Store выполним оба запроса с очисткой кэша ещё раз и найдем наш запрос в хранилище запросов.

План запроса для 999000 записей:

Настраиваем использование Force plan

План запроса для 1000 записей:

Настраиваем использование Force plan

Сформировалось два плана, как и ожидалось: 6132404 и 6132420.

Теперь форсируем план, который использует Clustered Index Scan, т. к. его применение вернет результат за приемлемое время на любом объеме выборки в отличии от второго плана.

Для этого нажимаем Force Plan и у нашего плана появляется признак закрепления:

Настраиваем использование Force plan

Теперь проверим в Extended Events какой план будет выполняться по различным параметрам запроса с очисткой кэша:

Настраиваем использование Force plan

Настраиваем использование Force plan

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

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

Как будет вести себя PostgreSQL в аналогичной ситуации

В теории

Кэширование в системе управления базами данных PostgreSQL устроено иначе, чем в MSSQL Server. Как такового понятия процедурного кэша в данной СУБД не существует.

Этапы выполнения запроса в PostgreSQL

Каждый запрос, даже если он повторяется из раза в раз, проходит все перечисленные этапы заново:

  • Разбор
    • Синтаксический разбор текста запроса.
      Текст запроса разбирается на лексемы и представляется в виде дерева.
    • Семантический анализ.
      Определяется на какие объекты базы данных ссылается данный запрос и есть ли у пользователя доступ к ним.
  • Трансформация
    На данном этапе разобранный запрос может быть переписан с учетом таких вещей, как подстановки текста запроса вместо имени представления, разграничению доступа на уровне строк (row-level security), правил трансформаций (в том числе пользовательских) и т. д.
  • Планирование
    Происходит перебор различных способов выполнения запроса и их оценки на основе некоторой математической модели исходя из собранной статистики. Тот способ, для которого прогнозируется минимальная стоимость представляется в виде дерева плана запроса.
    План выполнения запроса также представляется в виде дерева, но его узлы содержат не логические, а физические операции над данными.
  • Выполнение
    Запрос выполняется в соответствии с планом. При этом, узлы дерева работают как конвейер, запрашивая и передавая друг другу строки. Родительские узлы дерева запрашивают у дочерних, а получив все строки, отдают их выше. После того, как корневой узел дерева плана получил все данные, они отдаются клиенту.

Такой подход имеет ряд как недостатков, так и преимуществ:

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

Оптимизация построения планов планировщиком

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

Но в ситуациях, когда рассмотрение всех возможных вариантов выполнения запросов занимает слишком много времени и памяти, планировщик запросов в PostgreSQL имеет ряд особенностей для ускорения и «удешевления» построения плана.

Например, такие оптимизации имеют место при выполнении запросов с большим количеством операций соединения. Чтобы выбрать разумный (но не обязательно наилучший) план запроса за приемлемое время, PostgreSQL использует генетический оптимизатор запросов, когда количество соединений превышает некоторый предел. Более подробно об этом можно прочитать в документации (https://postgrespro.ru/docs/postgrespro/14/planner-optimizer).

Предварительная подготовка запроса

В том случае, когда нам все же необходимо запомнить дерево разбора запроса, это можно сделать, подготавливая запрос командой PREPARE.

Подготовка запроса (https://postgrespro.ru/docs/postgrespro/14/sql-prepare) разбирает и трансформирует его обычным образом, но полученное дерево разбора сохраняется в памяти сеанса. При последующем выполнении команды EXECUTE подготовленный оператор планируется и исполняется. Такое разделение труда исключает повторный разбор запроса, при этом позволяет выбрать наилучший план выполнения в зависимости от определенных значений параметров. Более подробно мы уже рассказывали о данном механизме в сравнении с MSSQL в статье об очистке процедурного кэша.

Отмечу лишь то, что из-за отсутствия глобального кэша, даже если запрос уже был разобран одним сеансом, другой будет вынужден разобрать его заново. Поэтому, при использовании 1С в связке с postgres, данный механизм, на наш взгляд, не является приоритетным.

Варианты не «из коробки»

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

  • Adaptive Query Optimizer (https://github.com/postgrespro/aqo) — расширение, которое дает обратную связь планировщику от реального выполнения запроса, по результатам которого, планировщик корректирует свои планы в будущем.
  • Pg_hint_plan (https://github.com/ossc-db/pg_hint_plan) — расширение, которое позволяет управлять планом выполнения запроса с помощью специальных указаний, записываемых в комментариях.

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

На практике

Проверим на практическом примере, как PostgreSQL справляется с построением планов запросов и их исполнением для одинаковых запросов с разным значением передаваемых параметров.

Для проведения эксперимента будем использовать тестовую копию базы «1С:УНФ 8. Управление предприятием общепита», в которой проводилось расследование в первой части статьи.

Базу развернем на виртуальной машине под управлением Ubuntu 20.04 в связке с 1С 8.3.20.1710 и PostgreSQL 14. План эксперимента будет следующий:

  • Настроить сбор логов технологического журнала 1С на события выполнения запросов в СУБД с выводом планов запросов.
  • Воспроизвести ситуацию с выполнением запроса, который был виновником ситуации с неоптимальным переиспользованием планов в первой части статьи.
  • Воспроизвести выполнение того же самого запроса, но с меньшим количеством данных.
  • Сравнить полученные планы запросов.

Настройка сбора логов

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

mkdir -p /var/log/log_tj

Далее нам необходимо назначить пользователя, от имени которого запущен сервер 1С владельцем созданной директории:

chown usr1cv8 /var/log/log_tj

После этого создаем/открываем существующий файл настроек сбора логов, например, при помощи nano:

nano /opt/1cv8/conf/logcfg.xml

Настраиваем сбор на события DBPOSTGRS, которое фиксирует исполнение операторов SQL в postgres, а также SDBL, которое фиксирует исполнение запросов к модели базы данных платформы 1С. Также не забываем указать необходимость сбора планов запросов при помощи тега plansql:

<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
        <log history="24" location="/var/log/log_tj">
                <property name="all"/>
                <event>
                        <eq property="name" value="SDBL"/>
                </event>
                <event>
                        <eq property="name" value="DBPOSTGRS"/>
                </event>
        </log>
        <plansql/>
</config>

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

ls /var/log/log_tj

Настройка сбора логов

Воспроизведение проблемного запроса

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

Воспроизведение проблемного запроса

Корнем длительного выполнения в MSSQL было использование одного и того же плана запроса при разном количестве строк во временной таблице ВТ_ОстаткиТоваров.

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

Воспроизведение проблемного запроса

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

mv  /opt/1cv8/conf/logcfg.xml  /opt/1cv8/conf/_logcfg.xml

И проверим наличие собранных логов при помощи команды tree:

Воспроизведение проблемного запроса

Анализ логов и просмотр планов запросов

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

Для этого, нам необходимо сопоставить текст запроса в 1С с текстом запроса в postgres. Воспользуемся обработкой, которая выводит структуру хранения метаданных и найдем в ней имена интересующих нас таблиц, а именно регистра накопления «Запасы»:

Анализ логов и просмотр планов запросов

И регистра сведений «УОП_ОбработкаСырьяПартионная»:

Анализ логов и просмотр планов запросов

Далее, при большом объеме логов технологического журнала 1С мы можем воспользоваться инструментами bash или же специальными инструментами, например «1С-Рарус: СОК (анализ лога технологического журнала)».

В нашем случае, мы собирали логи точечно и объем совсем небольшой, поэтому просто попробуем выполнить поиск по имени таблиц регистров:

Анализ логов и просмотр планов запросов

В результате нашли 2 события DBPOSTGRS с искомым текстом запроса и 2 события SDBL для все того же запроса:

Анализ логов и просмотр планов запросов

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

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

Анализ логов и просмотр планов запросов

Производить анализ в текстовом виде неудобно, существует несколько неплохих сторонних инструментов визуализации, например, explain.tensor.ru. Воспользуемся данным инструментом и взглянем на собранные планы запроса.

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

Анализ логов и просмотр планов запросов

Оптимизатор выбрал план запроса, в котором соединение временной таблицы остатков с таблицей регистра сведений выполняется оператором nested loops.

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

Анализ логов и просмотр планов запросов

Какой вывод можно сделать из увиденного? Оптимизатор запросов в postgres выбирает разные планы запросов для одного и того же запроса с разными значениями параметров исходя из имеющейся у него статистической информации и алгоритмов подбора планов.

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

Подведем небольшие итоги

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

Второе, если говорить собственно о проблематике, то следует обратить внимание, что «прибить» гвоздиком план бывает не так просто. Вспомните ситуацию, когда оптимизатор платформы преобразовывал guid в секции ВЫБРАТЬ в параметр и придется поискать решение, например, воспользовавшись force plan.

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

Всем удачи на нелегком пути экспертизы!

Авторы статьи

Гримута Артем
Гримута Артем
Чесноков Дмитрий
Чесноков Дмитрий
Кудин Антон
Кудин Антон
Черанев Андрей
Черанев Андрей
Есть вопросы по статье? Задайте их нам!
info-big
Рассылка «Новости компании»: узнавайте о новых продуктах, услугах и спецпредложениях
Отправляя эту форму, Вы соглашаетесь с Политикой конфиденциальности и даете согласие на обработку персональных данных компанией «1С-Рарус»

Остались вопросы?
Нужна консультация?
Свяжитесь с нами!