Вступление
Количество пользователей нашей основной базы данных активно увеличивается за счет слияния второстепенных баз. Динамика примерно такая: 2020 – 150, 2021 – 300, 2022 – 500 (план). Поэтому оптимизация и быстродействие для нас важны: при увеличении числа пользователей проблемы растут нелинейно. Одно время даже хотели заключить договор ЦКТП, но пока справляемся своими силами.
Был один случай..
.. участились ошибки блокировки СУБД.
Анализ типов блокировок на сервере СУБД (за пол-дня). Ожидания LCK_M_X, LCK_M_U занимают доминирующие позиции.
Что делать ?
Нашел видео по ключевым словам «блокировки, эксперт», автор - Виктор Богачев. Составил краткий конспект
0-3 Вступление, рабочие инструменты
3-4 Поиск блокировок по dmv
4-5 Причина блокировок - отсутствует подходящий индекс
5-8 План запроса, поиск запроса в 1С, используя logcfg
8-10 Ключ dbmslocks
10-12 Заключение, контакты
Решил посмотреть в СУБД. В видео использован запрос
SELECT
db.name,
a.session_id,
a.blocking_session_id,
a.transaction_id,
a.wait_time,
a.wait_type,
st.text,
qp.query_plan
FROM sys.dm_exec_requests AS a
OUTER APPLY sys.dm_exec_sql_text(a.sql_handle) AS st
OUTER APPLY sys.dm_exec_query_plan(a.sql_handle) AS qp
LEFT JOIN sys.sysprocesses AS p
OUTER APPLY sys.dm_exec_sql_text(p.sql_handle) AS stblock
ON a.blocking_session_id > 0 AND a.blocking_session_id = p.spid
LEFT JOIN sys.databases db
ON a.database_id = db.database_id
WHERE NOT a.status IN ('background', 'sleeping')
ORDER BY a.cpu_time DESC
представление sys.dm_exec_requests показывает выполняемые запросы в реальном времени, оно содержит поле blocking_session_id которое указывает на блокирующую сессию. (Доступна документация)
Как я уже говорил, у нас большая компания с развитой инфраструктурой. Физически невозможно иметь доступ ко всем серверам компании. Получение информации с сервера целевой СУБД — через системного администратора. Поэтому просматривать состояние базы данных в реальном времени с помощью динамических представлений было неудобно. Мы не знали - в какой момент происходит блокировка. Договорились, что системный администратор соберет extended events по описанию (Спасибо, Юрий Пермитин) но напрямую задачу решить не удалось — события блокировок в СУБД происходят настолько часто, что производительность сервера упала. Составил более подробное описание, с фильтрами по длительности.
Количество логируемых событий сократилось до приемлемого уровня. Оказалось неожиданностью: событие lock_timeout тоже нуждается в ограничении по длительности. Оказывается, при соединении внутренних процессов с tempdb, команда SET LOCK_TIMEOUT timeout_period не выполняется, и работа с временными таблицами #tt сопровождается lock_timeout, длительность=0. Файл записался при остановке сессии сбора данных. В результате я получил файл и открыл его Management Studio на тестовом сервере.
События lock_timeout, фрагменты sql_text
1. DELETE FROM T1 FROM dbo._InfoRg18447 T1 WHERE (T1._Fld18454RRef = @P1) AND (T1._Fld1420 = @P2)
С помощью функции ПолучитьСтруктуруБазыДанных() нашел имя регистра и имя поля. Как вы догадываетесь, индекс поля отсутствует. Очень похоже на ситуацию из видео на минуте 7. Для поля поставил значение «индексировать», флаг «ведущее» использовать не стал: могут быть пустые значения. Кстати, до добавления индекса события lock_deadlock на таблице dbo._InfoRg18447 тоже происходили. Причина блокировок СУБД подробно описана в видео: отсутствует индекс, происходит сканирование (с захватом) всей таблицы в режиме исключительной блокировки. При этом управляемые блокировки не учитывают план запроса, блокируют по значениям конкретных полей, конфликта между ними не происходит.
2. UPDATE T1 SET _Description = @P1, …. FROM dbo._ScheduledJobs31390 T1 WHERE T1._ID = @P15 AND T1._Version = @P16
Может показаться, что не хватает индекса по полю Version. Я даже полез на сайте смотреть возможные индексы https://its.1c.ru/db/metod8dev/content/1590/hdoc, но потом сообразил, что это регламентное задание. Такие таблицы содержат только одну строку, индекс не нужен. Регламентное задание запускалось в устарелой версии УТ при открытии программы, для целей rls. В новой версии его можно отключить.
3. Было несколько ошибок блокировок, связанных с шиной обмена Datareon. При зависании службы шины, отслеживаемые события в 1С не записывались, создавали lock_timeout. Эта ситуация была исправлена без моего участия.
События lock_escalation
Иногда происходит эскалация при работе с ценами по регистру «Цены номенклатуры» и табличной части документа «Установка цен». Документы больше 5000 строк табличной части, решение этой проблемы лежит в области организации процессов.
Итоги работы
Стало заметно лучше. Ниже анализ ожиданий на сервере СУБД за неделю, суммарная длительность ожиданий LCK_M_X, LCK_M_U составляет 18 минут, до начала работ суммарная длительность ожиданий могла быть до 2 часов в день.
P.S. Чтобы счастье было полным
настроил технологический журнал для dbmslocks (важно, что события собираются без отборов).
<?xml version="1.0"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
<log location="C:\Log\Logs\UT" history="24">
<event>
<eq property="name" value="DBMSSQL"/>
<eq property="p:processName" value="My_Database_Name"/>
</event>
<property name="all"/>
<property name="lkaid"/>
<property name="lka"/>
<property name="lkp"/>
<property name="lkpid"/>
<property name="lksrc"/>
</log>
<dbmslocks />
</config>
Свойства описаны на сайте ИТС.
lka=‘1’ поток является источником блокировки.
lkp=‘1’ поток является жертвой блокировки.
lkpid номер запроса к СУБД, «кто кого заблокировал» (только для потока-жертвы блокировки).
lkaid список номеров запросов к СУБД, «кто кого заблокировал» (только для потока-источника блокировки).
lksrc номер соединения источника блокировки, если поток является жертвой.
lkpto время в секундах, прошедшее с момента обнаружения, что поток является жертвой.
lkato время в секундах, прошедшее с момента обнаружения, что поток является источником блокировок.
Файлы по часам получились более 6 Гб, поэтому для выделения информации использовал bash:
egrep -e ',lk.id=' -B20 -A20 '21042614.log' > result14.txt
Для строчек, содержащих lkaid / lkpid выбрать 20 строк сверху и снизу, поместить в файл. Ниже пример: два источника, одна жертва. Ожидание длилось 0,84 секунды, прежде чем команда ПланыОбмена.ЗарегистрироватьИзменения() дождалась освобождения ресурса и установила блокировку.
********************************************************************************************************************************************************************
48:57.589056-4,DBMSSQL,6,process=rphost,p:processName=My_Database_Name,OSThread=9868,t:clientID=19295,t:applicationName=1CV8C,t:computerName=my_pc,t:connectID=73248,SessionID=345069,Usr=Иванов И.И.,AppID=1CV8C,DBMS=DBMSSQL,DataBase=My_Database_Name,Trans=1,dbpid=113,Sql=TRUNCATE TABLE #tt364,lka=1,lkaid=10,lkato=0,Context='Форма.Записать : Документ.ЗаказКлиента.Форма.ФормаДокумента
Документ.ЗаказКлиента.МодульОбъекта : 914 : ПроведениеСерверУТ.ЗаписатьНаборыЗаписей(ЭтотОбъект);
ОбщийМодуль.ПроведениеСерверУТ.Модуль : 355 : Объект.Движения.Записать();
РегистрНакопления.СвободныеОстатки.МодульНабораЗаписей : 69 : СформироватьТаблицуИзмененийДвижений();
РегистрНакопления.СвободныеОстатки.МодульНабораЗаписей : 347 : Результат = Запрос.ВыполнитьПакет();'
********************************************************************************************************************************************************************
48:57.589064-2,DBMSSQL,5,process=rphost,p:processName=My_Database_Name,OSThread=9868,t:clientID=19295,t:applicationName=1CV8C,t:computerName=my_pc,t:connectID=73248,SessionID=345069,Usr=Иванов И.И.,AppID=1CV8C,DBMS=DBMSSQL,DataBase=My_Database_Name,Trans=1,dbpid=113,Sql='SELECT
T1._Fld14389
FROM dbo._Const14388 T1
WHERE ((T1._Fld1420 = ?)) AND (T1._RecordKey = ?)
p_0: 0N
p_1: 0x31
',Rows=1,RowsAffected=-1,lka=1,lkaid=10,lkato=0,Context='Форма.Записать : Документ.ЗаказКлиента.Форма.ФормаДокумента
Документ.ЗаказКлиента.МодульОбъекта : 914 : ПроведениеСерверУТ.ЗаписатьНаборыЗаписей(ЭтотОбъект);
ОбщийМодуль.ПроведениеСерверУТ.Модуль : 355 : Объект.Движения.Записать();
ОбщийМодуль.обменУправлениеРегистрацией.Модуль : 9 : ЗарегистрироватьДляВыгрузки(Источник);
ОбщийМодуль.обменУправлениеРегистрацией.Модуль : 142 : ОписанияСобытий = обменКэшированиеПовтИсп.ПолучитьОписанияСобытий(ИмяМетаданных, обменПривелигированный.ПоследнееИзменениеНастроекОбмена());
ОбщийМодуль.обменПривелигированный.Модуль : 6 : Возврат Константы.обменПоследнееИзменениеНастроекОбмена.Получить();'
********************************************************************************************************************************************************************
48:58.293069-1,DBMSSQL,5,process=rphost,p:processName=My_Database_Name,OSThread=9868,t:clientID=19295,t:applicationName=1CV8C,t:computerName=my_pc,t:connectID=73248,SessionID=345069,Usr=Иванов И.И.,AppID=1CV8C,DBMS=DBMSSQL,DataBase=My_Database_Name,Trans=1,dbpid=113,Sql='UPDATE T1 SET _Fld20718 = T1._Fld20718 + ?, _Fld20719 = T1._Fld20719 + ?, _Fld20720 = T1._Fld20720 + ?, _Fld20721 = T1._Fld20721 + ?, _Fld20722 = T1._Fld20722 + ?
FROM dbo._AccumRgT20725 T1
WHERE (T1._Period = ? AND T1._Fld20715RRef = ? AND T1._Fld20716_TYPE = 0x08 AND T1._Fld20716_RTRef = 0x00000205 AND T1._Fld20716_RRRef = ? AND T1._Fld20717RRef = ? AND T1._Fld1420 = ? AND T1._Splitter = ?) AND (T1._Fld1420 = ?)
p_0: 1679366.4N
p_1: 1679366.4N
p_2: 1679366.4N
p_3: 302N
p_4: 302N
p_5: 40210201000000
p_6: 0x8D0E005056B09D4611EB55AD87043C08
p_7: 0x8D0E005056B09D4611EB55AC6E9EE5B2
p_8: 0x8CAA005056B05DE111EAD5B0BAFEE5A6
p_9: 0N
p_10: 0N
p_11: 0N
',Rows=0,RowsAffected=1,lka=1,lkaid=10,lkato=0,Context=Форма.Записать : Документ.ЗаказКлиента.Форма.ФормаДокумента
********************************************************************************************************************************************************************
48:58.308002-843849,DBMSSQL,6,process=rphost,p:processName=My_Database_Name,OSThread=2360,t:clientID=6553,t:applicationName=1CV8C,t:computerName=my_pc,t:connectID=61336,SessionID=331639,Usr=Иванов И.И.,AppID=1CV8C,DBMS=DBMSSQL,DataBase=My_Database_Name,Trans=1,dbpid=90,Sql='UPDATE T1 SET _MessageNo = CAST(NULL AS NUMERIC(38,8))
FROM dbo._ReferenceChngR26488 T1
WHERE (T1._IDRRef = ? AND (T1._NodeTRef = 0x0000005A AND T1._NodeRRef IN (?))) AND (T1._Fld1420 = ?)
p_0: 0xA9C2001060A2672011DBFFF79783C8BB
p_1: 0x8CEE005056B09D4611EB2A5A6D45303C
p_2: 0N
',Rows=0,RowsAffected=1,lkp=1,lkpid=10,lksrc=73248,lkpto=0,Context='Форма.Записать : Документ.ЗаказКлиента.Форма.ФормаДокумента
Документ.ЗаказКлиента.МодульОбъекта : 914 : ПроведениеСерверУТ.ЗаписатьНаборыЗаписей(ЭтотОбъект);
ОбщийМодуль.ПроведениеСерверУТ.Модуль : 355 : Объект.Движения.Записать();
ОбщийМодуль.Б_ОбменССайтомСервер.Модуль : 190 : ЗарегистрироватьИзменения(Источник, Замещение);
ОбщийМодуль.Б_ОбменССайтомСервер.Модуль : 594 : ПланыОбмена.ЗарегистрироватьИзменения(МассивУзловТовары, Запись.Номенклатура);'
********************************************************************************************************************************************************************
По предварительной оценке, на подобных ожиданиях мы теряем 1 секунду в час. Эта информация интересная, вернусь к ней позже.
