Ловля блокировок на связке "Microsoft SQL server - 1С"

16.07.19

База данных - HighLoad оптимизация

Материал относится к базам данных на связке «1С - MS SQL Server». Один из способов отлова блокировок в бд 1С . Переход к управляемым блокировкам через режим "Автоматический и управляемый".

 

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

Способ ловли был выбран следующий:  раз в десять секунд делаем снимок select * from master..sysprocesses во времянку, обрабатываем (оставляем инфу по blocked <>0 и процессам, которые сами не заблокированы, но фигурируют в blocked - источники блокировок, headblockers). Выходит что-то вроде //infostart.ru/public/193674/.

Ловля автоматических блокировок:

 

 
 пример раз - блокировка на исполняющемся запросе

 

Подготовка данных (в тестовой бд, или в tempdb)

CREATE TABLE _test(a int, b int, c int)

declare @i int = 0, @j int = 0

while @i < 120 begin

  set @j = 0

  while @j < 120 begin

    INSERT INTO _test(a, b, c) VALUES (@i, @j, 100)

    set @j = @j +1;

  end

  set @i = @i +1;

end


В первом окне запускаем

select count(distinct t1.a) from _test t1 with(updlock) inner join _test t2 on 1=1 inner join _test t3 on 1=1 option(maxdop 1)


Во втором окне запускаем (пока в первом запрос еще исполняется)

select count(distinct t1.a) from _test t1 with(updlock)


И в третьем окне мониторим наши блокировки запросом

select spid, sqltxt = cast(st2.text as varchar(max)), *

from

  master..sysprocesses sp

  left join master.sys.dm_exec_requests er

  on sp.spid = er.session_id

  outer apply sys.dm_exec_sql_text (er.sql_handle) st2

where

  sp.dbid = 2  -- если tempDB, иначе поменять

  and

   (0=1

      or ( sp.spid > 50 and sp.blocked not in (sp.spid,0) )

      or ( exists (select * from master..sysprocesses sp2 where sp2.blocked = sp.spid ) )

    )


Наблюдаем что-то похожее на


 

Видно, что сессия 53 блокирует сессию 54, видно текст блокирующего запроса, статус блокирующего запроса (runnable) и ожидание (SOS_SCHEDULER_YIELD - процессора не хватает, да еще и maxdop зажат). Ну и табличную блокировку видно (TAB) в tempDB (2)

Понятная и прозрачная ситуация.

 
 пример два - блокировка на спящем сеансе

Несколько видоизменяем первый пример

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

begin tran
   select sum(t1.a)  from _test t1 with(updlock) option(maxdop 1)
--commit tran

Во втором окне - все то же

select count(distinct t1.a)  from _test t1 with(updlock)

Выявляющий блокировки запрос в третьем окне теперь показывает что-то вроде

Не очень информативно - не видно исполнившийся запрос

Модифицируем выявляющий запрос вот так

select 
	sqltxt_pred = cast(st1.text as varchar(max)),
	sqltxt = cast(st2.text as varchar(max)), 
	*
from 
	master..sysprocesses sp 
	left join master.sys.dm_exec_requests er 
    on sp.spid = er.session_id
	outer apply sys.dm_exec_sql_text (sp.sql_handle)  st1
	outer apply sys.dm_exec_sql_text (er.sql_handle)   st2
where
	sp.dbid = 2 
	and
	(0=1
		or	( sp.spid > 50 and sp.blocked not in (sp.spid,0) )
		or	( exists (select * from master..sysprocesses sp2 where sp2.blocked = sp.spid )  )
	)

Теперь картинка гораздо информативней

 

 

Таким образом, из master..sysprocesses можно вытащить и текст исполняющегося в настоящий момент запроса, и текст всего пакета.

Собственно, примерно тоже самое можно сделать и с помощью DMV (most_recent_sql_handle в sys.dm_exec_connections и sql_handle sys.dm_exec_requests).

 

Но, задача была  не "следить непрерывно за консолью и при появлении блокировок выяснять - кто автор", а "анализ блокировок за период с ранжированием источников (headblockers)".

Значит, кроме фиксации spid, blocked,  sqltxt_pred, sqltxt требуется 
1. обработать текст запроса как в https://kb.1c.ru/articleView.jsp?id=76 (Листинг fn_GetSQLHash.. но предпочтительней делать на C# или C++, t-sql все же не лучший выбор для обработки строк)
2. собрать сведения из техжурнала 1С (событие <eq property="name" value="dbmssql"/>) и состыковать со снимками блокировок 

 
 примерно так

 Настройка ТЖ вида 

 <log history="2" location="D:\Server1C\logsLong">
        <event>
            <eq property="name" value="dbmssql"/>
            <gt property="duration" value="10000"/>
        </event>
        <property name="all"/>
    </log>

выдает файлы примерно такого содержимого:

00:16.1966-58122,DBMSSQL,3,process=rphost,p:processName=СклУпр,t:clientID=3208,t:applicationName=BackgroundJob,t:connectID=44967,SessionID=29950,Usr=Фоновое__Обмен,Trans=0,dbpid=457,Sql='INSERT INTO #tt13 (_Q_001_F_000RRef, _Q_001_F_001RRef) SELECT DISTINCT
T1._Reference5235_IDRRef,
T1._Fld6417RRef
FROM _Reference5236_VT6415 T1 WITH(NOLOCK)
WHERE T1._Fld6419 = 0x01',Rows=0,RowsAffected=68785,Context='
ОбщийМодуль.РегламентныеЗадания_Обмен.Модуль : 134 : Результат = ПолучитьРезультатВычисления(Выражение,,,СтруктураВозврата);
    ВнешняяОбработка.ВыполнениеКоманд.МодульОбъекта : 1022 : РезультатыЗапроса = ДанныеПоЗапросу.ВыполнитьПакет();'

Имя файла \\SERV1\Server1C\logsLong\rphost_565304\19062412.log

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

 - датувремя события (имя файла 19062412.log + первая строка 00:16.1966 = 2019.06.24 12:00:16 ) и  длительность 58122 (в данном случае это 5 секунд для 8.2, для 8.3 было бы в микросекундах) - дерево должно укладываться в период "датавремя - длительность" - "датавремя"

 - dbpid=457  - должно соответствовать spid = 457 (или session_id =  457 - если берем дерево не из sysprocesses, а запросом из DMV)

 - имя сервера 1С, с которого взят лог ТЖ (в примере это SERV1) - должно соответствовать hostname строки дерева

 - ID рабочего процесса (из rphost_565304 следует id = 565304)  - должно соответствовать hostprocess

 


3. записать снимок в бд - вместе с датой-временем снимка, текстом запроса и контекстом 1С

И далее просто написать запрос, группирующий по fn_GetSQLHash от текстов запросов (исполняющегося и предыдущего исполненного в данной сессии). И чем суммарно больше жертв - тем больше рейтинг источника блокировок (он же "headblocker", он же "виновник", он же "причина".. кто как обзывает)

Вот ссылка на реализацию (свежая версия - с ловлей блокировок)

 

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

 

//infostart.ru/upload/iblock/ac8/ac85c0adb5c12a26c1d28d1df809cbfb.gif

Подробней:

В верхней части указывается sql-сервер и период (26 апреля  от полуночи до 4 утра были проблемы на WorkSQL)

Первая таблица (выделено синим) содержит источники блокировок за указанный период на искомом сервере. Источники блокировок (headblockers) упорядочены по весу - сверху наиболее тяжелые. В качестве веса (выделено красным) - количество заблокированных сессий суммарно за период. Т.е. если за 4 часа зафиксировано три дерева блокировок, в которых одна сессия блокирует пять жертв - то вес у данного сочетания "sql исполнился = sql исполняется" (выделено оранжевым) равен 15. Отсюда можно примерно вычислить время простоя жертв суммарно (деревья фиксируются раз в 10 секунд - значит, время простоя жертв = 15*10 сек ).  Кнопка "заполнить подробно" (выделено зеленым) заполняет нижнюю таблицу - с уже конкретными деревьями блокировок (на удивление, в c# нет стандартного аналога "дерева значений" из 1С.. пришлось изобразить что-то похожее вручную). Деревья можно разворачивать и просматривать информацию о жертвах.

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

Подобные проблемы излечиваются чаще оптимизацией длительных запросов (в инструменте реализован переход от дерева блокировки к плану запроса), реже разрывом или устранением транзакции (если явная) / выносом кода из транзакции проведения/записи,  еще реже  - если это сложные случаи вроде "блокировки через переиндексацию" - рассматриваются индивидуально. 

 
 отступление про переиндексацию (ALETR INDEX .. REBUILD / REORGANIZE)

1С просто и незатейливо советует sp_msforeachtable N'DBCC DBREINDEX (''?'')' (или уже есть более свежая статья?).  Microsoft настойчиво рекомендует схему "avg_fragmentation_in_percent > 5% and < = 30% - REORGANIZE, > 30% - REBUILD". На infostart.ru светится "10%-30%", "5%-30%"

И практически на всех рабочих серверах, кои мне доводилось видеть - работает то самое 5%-30% - в виде версии от Микрософт, или скрипты шведского товарища Ola Hallengren, или что-то самописное на том же принципе. Реже встречается  sp_msforeachtable. На тестовых серверах, как правило, чаще метод "мы забили на регламентное обслуживание".. 

Для мелких баз с хорошими технологическими окнами - Ola Hallengren самое то. Работает по ночам, есть не просит.
Но вот для террабайтных высоконагруженных, работающих "24/7/почти 365" - все далеко не так радужно.
Вот с  чем сталкивался:
 - Само обращение к sys.dm_db_index_physical_stats  даже с ''LIMITED'' - весьма неплохо съедает память (буферпул) sql-сервера. Далее возможны задержки непричастных запросов на физ чтениях, пока буферпул опять наполняется "нормальными" данными
 - Ошибки вида Msg 9002, The transaction log for database '...' is full due to 'ACTIVE_TRANSACTION'. - иной раз не лезет индекс в данное админом пространство под лог
 - Ошибки вида Msg 9002, The transaction log for database '...' is full due to 'LOG_BACKUP' - и, соответственно, реплики на резервных серверах могут становиться сильно неактуальными... Даже без данных завалов из-за массивных переиндексаций может быть отставание реплик в AlwaysOn

 - И, самое болезненное - собственно, блокировки на REBUILD.  Особенно для редакций Standart  - нет with(online = on) и тем более WAIT_AT_LOW_PRIORITY, сам ребилд идет в один поток (и коль заблокирует кого - то надолго). И даже в версии Enterprise с with(online = on) - блокировки все равно в наличии! Будили ночью, любовался. Собственно, в документации оно вполне отражено.  

Обычный сценарий блокировок под для Standart - некий кривоватый запрос (даже вне транзакции, с хинтами with(nolock)) блокирует alter index..rebuild , далее alter index блокирует всех.  Пробовал бороться с теми самыми "кривоватыми запросами" - легион их. Пробовал писать джоб, убивающий "кривоватые запросы", мешающие переиндексации - работает.. но однажды оно убило весьма важный процесс - отключил. Перенастроил джоб для "самых важных баз", чтобы он убивал саму реиндексацию - аналог WAIT_AT_LOW_PRIORITY ( MAX_DURATION = 1 MINUTES, ABORT_AFTER_WAIT = SELF ) - работает... но, понятное дело - не идеал.

Т.е. стандартная модель переиндексации понемногу перестает устраивать. 
Вот и Brent Ozar еще в 2012 сомневался  - а тогда еще не было широкого распространения ssd.
В настоящий момент думаю в сторону "реиндексации того, что в текущий момент сидит в оперативке (в буферпуле) - с целью минимизации размера индекса (и память освободим, и чтений меньше)".. также понемногу задираю пороги ("5-30" веду к "40-50") и отслеживаю изменение скорости типовых  запросов - посмотрим, что будет..

Опять-таки, Микрософт тоже ощущает, видимо, данную проблему.. Появление WAIT_AT_LOW_PRIORITY в MS SQL Server 2014 и RESUMABLE=ON в MS SQL Server 2017 как бы намекает. Жаль только, что все это не для standart (enterprise дорогой и в наличии далеко не на всех серверах). 

 

 

 

 

Случай посложнее - когда блокировка висит на спящей сессии (поле "sql исполняется" пустое).

Сделан искусственно кодом 

НачатьТранзакцию();
запрос = Новый Запрос;    
запрос.Текст = " ВЫБРАТЬ С.Ссылка ИЗ Документ.СборкаПродукции КАК С ГДЕ С.Дата > &Дата ДЛЯ ИЗМЕНЕНИЯ Документ.СборкаПродукции";
запрос.УстановитьПараметр("Дата", ТекущаяДата()-60*60*2);
рез = запрос.Выполнить();
выборка = рез.Выбрать();
Предупреждение("ждем.."); 
ОтменитьТранзакцию();

По REPEATABLEREAD видно, что конфигурация в автоматическом режиме, ДЛЯ ИЗМЕНЕНИЯ трансформировалось в UPDLOCK.

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

Чего только не находилось за последние несколько лет в транзакциях проведения документов или записи набора регистров:

  - Предупреждение() или Вопрос() - это самое любимое

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

  - разнообразные файловые операции

  - обращения к другим базам через com-объекты

  - обращения к другим базам посредством Новый COMОбъект("ADODB.Connection")  (ага, а на соседнем сервере уже запрос через то самое ADODB... тоже висит на блокировке! и такое было..) 

 - работа с ftp

 - обращение к web-сервису

 - запуск на исполнение сторонних программ

  

Отдельно стоит упомянуть эскалацию блокировок на уровне sql-сервера. Неважно, на спящей или на running/runable сессии возникли блокировки - стоит смотреть на поле waitresource (или wait_resource из sys.dm_exec_requests).  Если там TAB: (Object()) - то скорее всего мы нарвались на эскалацию. Чаще всеж стоит поправить прочитавший таблицу запрос - с большой  вероятностью он кривой и сканирующий .. но иногда можно и выключить эскалацию на уровне таблицы. Если будете выключать - это небезопасно, пару раз у меня вылезала нехватка оперативки для sql-сервера при реструктуризации такой таблицы (саму идею эскалации ведь не просто так придумали).

 

 

Итого.

По сообщениям пользователей вида "мы зависли" определялось наличие/отсутствие деревьев блокировок, при наличии - почти всегда обнаруживалась явная причина. И устранялась. Плюс еженедельно просмотр статистики по блокировкам за 7 дней + тоже поиск причин и устранение. И так несколько лет.

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

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

 - крупные транзакции, запросы в которых уже "вылизаны до блеска", но разорвать их - или никак, или оч дорого.

 - много программистов непрерывно добавляют новый / модифицируют старый код, стоит ошибиться в запросе - любом запросе - в транзакции популярного (часто проводимого) документа - и имеем коллапс рабочей бд (да, нагрузочное тестирование релизов - хорошая идея, но его почти нет)

 - и вообще, надо уже идти к управляемым блокировкам, ибо "все идут".. ну и реально это поможет облегчить/устранить предыдущие пункты

 

 

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

Второстепенные бд так и перевели.

Основная база данных, надо отметить, уже к тому моменту подбиралась ко второму терабайту и тысяче пользователей, и работала "почти 24"/7.

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

Т.е. оставался перевод конфигурации в режим "Автоматический и управляемый" и переход пообъектно

В один из релизов и установили в корне "Автоматический и управляемый".

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

Нет, мы "перед тем, как" все протестировали, даже с подобием нагрузочного теста (как оказалось позже - подобие было "не очень")

Релиз откатили спустя три часа, после многочисленной ругани пользователей. База висела на блокировках.

Если точнее - источниками блокировок были спящие (sleeping) после выполнения запросов вида 

SELECT T1._Период, T1._UseTotals, T1._ActualПериод, T1._UseSplitter, T1._MinПериод
FROM _РегистрНакопления.ОстаткиТоваров(НастройкиХраненияИтоговРегистраНакопления) T1
WHERE T1._RegСсылка = @P1

А технологический журнал, с предусмотрительно настроенным 

<log location="C:\LOGS\TLOCKS" history="4">
  <event>
      <eq property="Name" value="TLOCK"/>
      <gt property="duration" value="5000"/>
  </event>
  <event>
      <eq property="Name" value="TTIMEOUT"/>
  </event>
  <event>
      <eq property="Name" value="TDEADLOCK"/>
  </event>
   <property name="all"/>
</log>

в итоге выдавал по тем спящим сессиям  либо длительный TLOCK, либо TTIMEOUT

 
 откуда взял, что именно "по тем спящим сессиям"?

Каждые десять секунд - обращение к рабочему кластеру 1С через V83.COMConnector и запись снимка сеансов рабочей бд "консоли серверов 1С" в sql-базу. Таким образом, можно связать session_id на sql=сервере с сеансом, соединением и пользователем рабочей бд. Понятное дело, если соединение с субд висело достаточно долго.  

Есть еще один способ связать session_id с сеансом/соединением, но он опасен и детально не исследован, и про него я, пожалуй, здесь не напишу.

Т.е. первая сессия блокировала вторую на уровне sql-сервера, а вторая блокировала первую на уровне 1С-сервера управляемой блокировкой. Управляемые  блокировки в первой итерации мы не добавляли, это были .. управляемые блокировки при записи наборов регистров.

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

 

Соответственно, для нормального разбора проблем фиксацию деревьев блокировок надо модернизировать - добавив управляемые блокировки из техжурнала. Рядом с полем blocked сделать поле blocked_by_ls, и перестроить дерево с его учетом. Если вы имеете в бд снимок блокировок на уровне sql-сервера, снимок сеансов нужной базы из "консоли серверов 1С" и загруженные в sql-таблицу файлы техжурнала с TLOCK - то это возможно. Не сказать, что точность получается идеальная - но для работы вполне хватает. 

Ниже иллюстрация подобной ситуации (не связанная непосредственно с началом перехода в "автоматический и управляемый" - тех картинок уж нет, увы..):

 
 картинка с ресурсами и видео

 

 

Говорова Светлана запускала "очень важную обработку" и "висела и вылетала" - ниже видно, в чем было дело.

 

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

А далее.. планомерный пообъектный перевод.

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

Далее берем регистр Б... в документах, которых двигают только А и Б - можно менять режим.. И до победного конца.

Процесс при этом может занимать годы.

 

А что же потом?

В полностью управляемом режиме блокировки на уровне sql-сервера (даже в read committed snapshot) не исчезают на 100%.  Так что непрерывный мониторинг необходимо продолжать.  Пишите свою систему, используйте сервис Гилева или ПерфЭксперт, или мою систему.

 

 
 а что есть кроме фиксации моментальных снимков деревьев блокировок?

 1. как минимум System Monitor и счетчик  SQL Server: Locks \ Average Wait Time (ms)

 2. eXtended Events и событие blocked_process_report - если есть возможность менять настройки sql-сервера ( blocked process threshold ).. более точная штука, чем деревья, но есть пара отрицательный момент.. блокировки ловит отлично, но деревья предоставляют кое-какие возможности и помимо ловли блокировок. пока расшифровывать не буду.

 3. eXtended Events и событие Lock:Acquired - покажет, на каких таблицах и у каких пользователей были проблемы. Но вытащит источники блокировок отсюда сложно. Данные за период такой трассы очень хорошо коррелируют с данными в деревьях блокировок.

дополняйте..

 

 

 

 

Блокировка дедлок взаимоблокировка запрос оптимизация неоптимальность производительность план исполнения система сбора и анализа информации по производительности работы баз данных Microsoft

См. также

Опыт оптимизации 1С на PostgreSQL

HighLoad оптимизация Бесплатно (free)

При переводе типовой конфигурации 1C ERP/УТ/КА на PostgreSQL придется вложить ресурсы в доработку и оптимизацию запросов. Расскажем, на что обратить внимание при потерях производительности и какие инструменты/подходы помогут расследовать проблемы после перехода.

20.11.2023    5730    ivanov660    4    

61

ТОП проблем/задач у владельцев КОРП лицензий 1С на основе опыта РКЛ

HighLoad оптимизация Бесплатно (free)

Казалось бы, КОРП-системы должны быть устойчивы, быстры и надёжны. Но, работая в рамках РКЛ, мы видим немного другую картину. Об основных болевых точках КОРП-систем и подходах к их решению пойдет речь в статье.

15.11.2023    3648    a.doroshkevich    20    

64

Начните уже использовать хранилище запросов

HighLoad оптимизация Запросы

Очень немногие из тех, кто занимается поддержкой MS SQL, работают с хранилищем запросов. А ведь хранилище запросов – это очень удобный, мощный и, главное, бесплатный инструмент, позволяющий быстро найти и локализовать проблему производительности и потребления ресурсов запросами. В статье расскажем о том, как использовать хранилище запросов в MS SQL и какие плюсы и минусы у него есть.

11.10.2023    13607    skovpin_sa    14    

82

Как эффективно настроить autovacuum в Postgres для 1С

HighLoad оптимизация Администрирование СУБД Платформа 1С v8.3 Бесплатно (free)

Кто не любит убирать мусор? Думаю, практически все, а вот в Postgres это обязательный ритуал для эффективной работы. Как эффективно настроить уборку за 1С в Postgres, можно прочитать в этой статье и еще раз задуматься о бесплатности Postgres.

05.08.2023    4216    1CUnlimited    5    

48

MS SQL Server: изучаем планы запросов

Запросы HighLoad оптимизация Запросы Бесплатно (free)

Многие знают, что для ускорения работы запроса нужно «изучить план». При этом сам план обычно обескураживает: куча разноцветных иконок и стрелочек; ничего не понятно, но очень интересно! Аналитик производительности Александр Денисов на конференции Infostart Event 2021 Moscow Premiere рассказал, как выполняется план запроса и что нужно сделать, чтобы с его помощью находить проблемы производительности.

20.06.2023    10910    Филин    37    

101

Простой способ проверки быстродействия

HighLoad оптимизация Платформа 1С v8.3 Бесплатно (free)

Простой (а точнее, мегапростой) способ проверки быстродействия, когда очень важно его, быстродействие, улучшить

10.04.2023    3502    vkrivov@yandex.ru    15    

36
Оставьте свое сообщение