От экспертов «1С‑Рарус»: Блокировки на СУБД при масштабировании бизнеса. Подробно о блокировках MS SQL и PostgreSQL

Описание экспертного случая

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

В качестве учетной системы использовалась типовая конфигурация «1С:УНФ 8. Управление предприятием общественного питания» с некоторыми проектными доработками, а в качестве кассовых систем — «РестАрт ред. 3».

Из-за массовой и одновременной нагрузки на один блок у клиента возникли блокировки, с которыми они обратились к нам за помощью.

Что же такого сделали сотрудники, что пошли блокировки да и еще на уровне СУБД? Давайте разбираться.

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

База данных: Microsoft SQL Server 2016.
Платформа 1С:Предприятие 8: 8.3.23.1782 64х.
Операционная система: Windows Server 2012 R2.
Процессор: Intel Xeon Silver 4210 CPU @ 2.2GHz.
Оперативная память: 256 GB.
SSD: 1.5 TB.

Схема возникновения блокировок и отключение эскалации блокировок для «скорой помощи» пользователям

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

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

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

Поскольку клиент вел учет в системе несколько лет, объем данных, которые необходимо передать, оказался значительным. Например, в справочнике «Номенклатура» было 1 миллион элементов, в «Виды меню» — 300, а в «Меню» — 3 миллиона.

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

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

Тут под Кассами следует понимать узлы Плана обмена.

Такое поведение может приводить к блокировкам при одновременном изменении данных.

Потому в свое время мы реализовали специальный механизм отложенной регистрации. Согласно этому механизму, все такие изменения фиксируются сначала не в таблицы изменений, а в служебный регистр отложенных изменений (УОП_УдаленныеКассыРегистрация) без регистрации связанных элементов.

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

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

Мы объединили факты наличия блокировок СУБД на таблицах изменений, массовой и параллельной регистрации данных к изменениям больших объемов, а также использование СУБД Microsoft SQL Server. Исходя из этого, мы предположили, что массовые операции могли спровоцировать эскалацию блокировок, которая, в свою очередь, вызвала ожидание при создании блокировки непересекающихся данных.

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

Чтобы это сделать необходимо запустить SQL Server Management Studio и выполнить запросы на отключение флагов трассировки 1224 и 1211.

DBCC TRACEON (1224, -1) ;
DBCC TRACEON (1211, -1) ;

Флаги трассировки:

• 1224 позволяет отключить запуск эскалаций блокировок по количеству блокировок.
• 1211 позволяет отключить эскалацию блокировок и по количеству, и по доступности памяти.

При использовании Windows для этого достаточно воспользоваться утилитой SQL Server Configuration Manager и выполнить следующие действия:

• В левой панеле выбрать SQL Server Services.
• В правой панели вызвать контекстном меню по службе SQL Server, а затем выбрать Properties (Свойства).

  

• Перейти на вкладку Startup Parameters (Параметры запуска).
• Написать -T1224 и выбрать Add (Добавить), а затем повторить аналогично с -T1211.

  

• Сохранить по кнопке ОК и перезапустить службу сервера.

  

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

Поиск причин возникновения блокировок — анализ логов технологического журнала, комбинация массового изменения объектов в транзакции и поэлементной регистрации

Чтобы это сделать, мы настроили сбор технологического журнала по событиям DBMSSQL, а также расширенных событий (Extended events) по событиям lock_escalation, lock_timeout_greater_than_0, lock_acquired и blocked_process_report.

<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
	<log history="24"
			location="ПутьКЛогамТЖ">
		<property name="all"/>
		<event>
			<eq property="name" value="DBMSSQL"/>
			<eq property="p:processName" value="ИмяБазы"/>		
		</event>
	</log>
</config>

CREATE EVENT SESSION [rarus_lock] ON SERVER 
ADD EVENT sqlserver.blocked_process_report(
    ACTION(sqlserver.sql_text)),
ADD EVENT sqlserver.lock_acquired(
    WHERE ([package0].[greater_than_uint64]([duration],(0)))),
ADD EVENT sqlserver.lock_escalation,
ADD EVENT sqlserver.lock_timeout_greater_than_0(
    ACTION(sqlserver.sql_text))
ADD TARGET package0.event_file(SET filename=N'ПутьККаталогуСЛогами')
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=NO_EVENT_LOSS,MAX_DISPATCH_LATENCY=0 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)
GO

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

В собранной трассе расширенных событий lock_escalation не были обнаружены, что подтвердило отсутствие эскалации. Однако, lock_timeout_greater_than_0 были найдены.

Это событие возникает при ожидании блокировок и содержит полезную информацию. В частности, id объекта (associated_object_id), на котором произошла блокировка, режим выполняемого запроса (mode), описание ресурса, на который накладывается блокировка (поля resource), тип ресурса (resource_type) и текст запроса (sql_text).

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

В данном случае, таблица в тексте запросов одна. Однако, если бы их было несколько, то для определения таблицы, на которой произошла блокировка, при типе ресурса KEY, достаточно выполнить следующий запрос, заменив ИдОбъекта на значение поля associated_object_id.

SELECT 
    sc.name as schema_name, 
    so.name as object_name, 
    si.name as index_name
FROM sys.partitions AS p
JOIN sys.objects as so on 
    p.object_id=so.object_id
JOIN sys.indexes as si on 
    p.index_id=si.index_id and 
    p.object_id=si.object_id
JOIN sys.schemas AS sc on 
    so.schema_id=sc.schema_id
WHERE hobt_id = ИдОбъекта;
GO

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

SELECT
    *
FROM dbo.ИмяТаблицы (NOLOCK)
WHERE %%lockres%% = '(ХэшКлюча)';
GO

Чтобы определить объект в терминах 1С, мы использовали обработку получения структуры хранения метаданных, которая визуализирует результат выполнения платформенной функции ПолучитьСтруктуруХраненияБазыДанных().

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

После определения таблицы, на которой произошли блокировки, мы перешли к поиску контекстов событий. Для этого нам понадобились логи технологического журнала, которые были преобразованы и загружены конфигурацией «1С-Рарус: Мониторинг производительности» в СУБД ClickHouse. Это позволило выполнять анализ не с помощью сложных регулярных выражений, а выполняя SQL-подобные запросы в его веб-интерфейсе Tabix.

Например, для поиска обращений к базе данных — события DBMSSQL — по ключевым фразам его текста запроса достаточно выполнить следующий запрос:

SELECT
*
FROM
default.mon_table
WHERE
_event = 'DBMSSQL'
and _time BETWEEN '2024-03-01 12:29:50' and '2024-03-01 12:30:00'
and sql LIKE '%dbo._ReferenceChngR21988%'
and sql LIKE '%UPDATE%'

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

Рассмотрев ряд событий мы пришли к выводу, что у них общий контекст, вызываемый из сторонней обработки «ХХХ_ФормированиеМенюПоОстаткам», с регистрацией через метод ЗарегистрироватьИзменения, а не через отложенный регистр и выполняемый в расширении клиента «ИсправлениеРегистрацииВидаМеню».

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

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

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

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

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

Теория возникновения блокировок MSSQL и PostgreSQL в связке с 1С

Что ж, от «полевых» работ перейдем в лабораторные условия. И попробуем посмотреть на блокировки СУБД под разными углами. Для экспериментов возьмем тестовый стенд — пустую серверную базу 1С на двух СУБД — MSSQL и PostgreSQL.

Все тесты проводим в условиях:

• Платформа 1С:Предприятие 8: 8.3.23.1912 64х.
• Базы данных Microsoft SQL Server 2019 и PostgreSQL 11.8.

Примечание: спасибо коллегам из 1С за статьи, позволившие легче разобраться с поставленными экспериментами:

• its.1c.ru/db/metod8dev#content:6005:hdoc:problem12,
• kb.1c.ru/articleView.jsp?id=124.

Попытка создать блокировку на СУБД

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

Повышение уровня захвата ресурса

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

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

НачатьТранзакцию();

РСНЗ = РегистрыСведений.РегистрСведений1.СоздатьНаборЗаписей();
РСНЗ.Отбор.Измерение1.Установить(Справочники.Справочник1.Элемент1);
РСНЗ.Прочитать();

//Пауза

РСНЗ.Записать();
	
ЗафиксироватьТранзакцию();

Как результат — получаем ошибку управляемой взаимоблокировки, до СУБД дело не дошло:

Поведение одинаково и на MS SQL и на PоstgreSQL.

Разный порядок записи

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

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

1. В первой транзакции порядок записи:
1. РегистрСведений1.
2. РегистрСведений2.
2. Во второй транзакции порядок записи:
1. РегистрСведений2.
2. РегистрСведений1.

Первая

НачатьТранзакцию();
РСНЗ = РегистрыСведений.РегистрСведений1.СоздатьНаборЗаписей();
РСНЗ.Отбор.Измерение1.Установить(Справочники.Справочник1.Элемент1);
РСНЗ.Записать();

//Пауза

РСНЗ = РегистрыСведений.РегистрСведений2.СоздатьНаборЗаписей();
РСНЗ.Отбор.Измерение1.Установить(Справочники.Справочник1.Элемент1);
РСНЗ.Записать();
ЗафиксироватьТранзакцию();

Вторая

НачатьТранзакцию();
РСНЗ = РегистрыСведений.РегистрСведений2.СоздатьНаборЗаписей();
РСНЗ.Отбор.Измерение1.Установить(Справочники.Справочник1.Элемент1);
РСНЗ.Записать();

//Пауза

РСНЗ = РегистрыСведений.РегистрСведений1.СоздатьНаборЗаписей();
РСНЗ.Отбор.Измерение1.Установить(Справочники.Справочник1.Элемент1);
РСНЗ.Записать();
ЗафиксироватьТранзакцию();

Получаем аналогичную ошибку управляемой взаимоблокировки:

Поведение также не зависит MS SQL/PоstgreSQL.

Эскалация

И последний эксперимент — таймаут при эскалации.

Для этого выполним в одном сеансе в транзакции запись 100001 элемента:

Запрос = Новый Запрос;
Запрос.Текст = 
"ВЫБРАТЬ ПЕРВЫЕ 100001
|	Справочник1.Ссылка КАК Ссылка
|ИЗ
|	Справочник.Справочник1 КАК Справочник1
|ГДЕ
|	Справочник1.Ссылка <> ЗНАЧЕНИЕ(Справочник.Справочник1.ЭлементДляЭскалации)";
РезультатЗапроса = Запрос.Выполнить();
ВыборкаДетальныеЗаписи = РезультатЗапроса.Выбрать();
НачатьТранзакцию();
Пока ВыборкаДетальныеЗаписи.Следующий() Цикл
	ВыборкаДетальныеЗаписи.Ссылка.ПолучитьОбъект().Записать();
КонецЦикла;

//Пауза

ЗафиксироватьТранзакцию();

А во втором параллельном сеансе запись одного элемента, исключенного из первой выборки:

Справочники.Справочник1.ЭлементДляЭскалации.ПолучитьОбъект().Записать();

Получаем обычную ошибку таймаута на управляемых блокировках:

Какой из этого всего делаем вывод?

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

Таймаут СУБД на таблице изменений

Теперь попробуем реализовать «синтетический» случай таймаута на СУБД, аналогичный тому, что мы расследовали на практике выше. И покажем какими способами можно расследовать подобные проблемы. Хоть разработчики платформы и свели вероятность такой ошибки к минимуму, с ней всё же ещё можно столкнуться, или ещё чаще — имея дело со старыми версиями платформы, и нужно знать как их расследовать.

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

Узел = ПланыОбмена.ПланОбмена1.НайтиПоНаименованию("Тестовый узел");
НачатьТранзакцию();
ПланыОбмена.ЗарегистрироватьИзменения(Узел, Справочники.Справочник1.Элемент1);
//Пауза
ЗафиксироватьТранзакцию();

Ожидаемо ловим ошибку, в разных СУБД текст отличается:

• В MSSQL:

  Конфликт блокировок при выполнении транзакции:
  Microsoft OLE DB Driver for SQL Server: Lock request time out period exceeded.
  HRESULT=80040E31, SQLSrvr: SQLSTATE=HYT00, state=33, Severity=10, native=1222, line=1

• В PostgreSQL:

  Конфликт блокировок при выполнении транзакции:
  55P03: ERROR: canceling statement due to lock timeout
  CONTEXT: while updating tuple (1028,86) in relation "_referencechngr50"

Теперь получив ошибку в «пробирке» изучим её разными способами.

Исследование блокировок по трассе MS SQL

Если мы говорим про базы на MS SQL, то данную проблему можно расследовать с помощью трассировки Extended events.

В этом случае могут пригодиться следующие события:

• blocked_process_report — возникает, когда задача была заблокирована на период времени больше указанного в настройке blocked_process_report.
• lock_acquired — возникает при установке блокировки.
• lock_timeout_greater_than_0 — возникает при ожидании другой блокировки.
• lock_escalation — возникает при увеличении гранулярности блокировки, например, при преобразовании списка блокировок строк в блокировку таблицы целиком.

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

<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
 <log location="C:\TJlogs" history="1">
  <event>
   <eq property="name" value="SDBL"/>
   <eq property="p:processname" value="DBMS_locks"/>
  </event>
  <event>
   <eq property="name" value="DBMSSQL"/>
   <eq property="p:processname" value="DBMS_locks"/>
  </event>
  <event>
   <eq property="name" value="EXCP"/>
   <eq property="p:processname" value="DBMS_locks"/>
  </event>
  <event>
   <eq property="name" value="EXCPCNTX"/>
   <eq property="p:processname" value="DBMS_locks"/>
  </event>
  <property name="all"/>
 </log>
</config>

Запускаем трассировку и повторяем наш эксперимент с «генерацией» таймаута СУБД. В трассировке находим событие blocked_process_report:

В событии blocked_process_report интересующая нас информация находится в поле blocked_process, открываем его и видим такой текст формата XML:

<blocked-process-report monitorLoop="4450314">
 <blocked-process>
  <process id="process20fd206dc28" taskpriority="0" logused="0" waitresource="KEY: 35:72057594109100032 (8469d4d722c1)" waittime="11079" ownerId="2016483383" transactionname="user_transaction" lasttranstarted="2024-03-17T15:43:12.010" XDES="0x20edba10428" lockMode="U" schedulerid="4" kpid="28548" status="suspended" spid="53" sbid="0" ecid="0" priority="0" trancount="2" lastbatchstarted="2024-03-17T15:43:12.017" lastbatchcompleted="2024-03-17T15:43:12.013" lastattention="1900-01-01T00:00:00.013" clientapp="1CV83 Server" hostname="srv-name" hostpid="66048" loginname="user" isolationlevel="read committed (2)" xactid="2016483383" currentdb="35" currentdbname="DBMS_locks" lockTimeout="20000" clientoption1="671221856" clientoption2="128056">
   <executionStack>
    <frame line="1" stmtstart="74" stmtend="402" sqlhandle="0x02000000fd48ff0cdcff6e012c9b266e5ca3cab86caf2f490000000000000000000000000000000000000000" />
    <frame line="1" sqlhandle="0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000" />
   </executionStack>
   <inputbuf>
(@P1 varbinary(16),@P2 varbinary(16))UPDATE T1 SET _MessageNo = CAST(NULL AS NUMERIC(38,8))
FROM dbo._ReferenceChngR50 T1
WHERE T1._IDRRef = @P1 AND (T1._NodeTRef = 0x00000031 AND T1._NodeRRef IN (@P2))   </inputbuf>
  </process>
 </blocked-process>
 <blocking-process>
  <process status="sleeping" spid="61" sbid="0" ecid="0" priority="0" trancount="1" lastbatchstarted="2024-03-17T15:43:08.943" lastbatchcompleted="2024-03-17T15:43:08.943" lastattention="1900-01-01T00:00:00.943" clientapp="1CV83 Server" hostname="srv-name" hostpid="66048" loginname="user" isolationlevel="read committed (2)" xactid="2016483342" currentdb="35" currentdbname="DBMS_locks" lockTimeout="20000" clientoption1="671221856" clientoption2="128056">
   <executionStack />
   <inputbuf>
(@P1 varbinary(16),@P2 varbinary(16))SELECT
T2._NodeTRef,
T2._NodeRRef
FROM dbo._ReferenceChngR50 T2
WHERE T2._IDRRef = @P1 AND T2._MessageNo IS NULL AND (T2._NodeTRef = 0x00000031 AND T2._NodeRRef IN (@P2))   </inputbuf>
  </process>
 </blocking-process>
</blocked-process-report>

Он разделен на две части:

1. <blocked-process> — заблокированный процесс — по сути «жертва» в привычных терминах.
2. <blocking-process> — блокирующий процесс, т. е. «виновник».

На что здесь стоит обратить внимание:

• В обеих частях есть область тега <inputbuf> — текст запроса SQL, который выполнялся в момент блокировки.
• Поля spid — означают номера соединений в СУБД жертвы и виновника.
• В разделе заблокированного процесса есть поле waitresource = «KEY: 35:72057594109100032 (8469d4d722c1)».
  Его значение — это ресурс (строка таблицы или индекса), на котором «подрались» две транзакции.

Итак, у нас есть:

1. Данные «жертвы»:
1. Номер соединения= 53.
2. Текст запроса SQL:

   (@P1 varbinary(16),@P2 varbinary(16))UPDATE T1 SET _MessageNo = CAST(NULL AS NUMERIC(38,8))
   FROM dbo._ReferenceChngR50 T1
   WHERE T1._IDRRef = @P1 AND (T1._NodeTRef = 0x00000031 AND T1._NodeRRef IN (@P2))

2. Данные “виновника”:
1. Номер соединения = 61.
2. Текст запроса SQL:

   (@P1 varbinary(16),@P2 varbinary(16))SELECT
   T2._NodeTRef,
   T2._NodeRRef
   FROM dbo._ReferenceChngR50 T2
   WHERE T2._IDRRef = @P1 AND T2._MessageNo IS NULL AND (T2._NodeTRef = 0x00000031 AND T2._NodeRRef IN (@P2))

Поищем соответствующие события в собранных логах ТЖ. Нам нужны события DBMSSQL с определенным номером соединения и отбором по тексту запроса. Мы для простоты в качестве искомого текста возьмем только имя таблицы «_ReferenceChngR50».

Для поиска событий в логах ТЖ воспользуемся следующими bash-скриптами.

Для поиска контекста жертвы:

Для поиска контекста виновника:

В результате файл victim.txt содержит одно событие:

Тем самым мы нашли контекст кода 1С «жертвы». На это также указывает характерная длительность события ~ 20 секунд.

Файл culprit.txt содержит два события:

В них видим одинаковый контекст «виновника».

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

В нашем случае значение поля waitresource="KEY: 35:72057594109100032 (8469d4d722c1)". Оно состоит из нескольких частей:

• KEY — в начале идет тип блокировки, в нашем случае это KEY — блокировка на уровне записи таблицы. Также здесь может быть значение PAGE — блокировка на уровне страницы.
• 35 — database_id, внутренний идентификатор информационной базы.
• 72057594109100032 — hobt_id, идентификатор кучи данных или дерева B-дерева, который содержит строки для этой секции.
• (8469d4d722c1) — хэш строки таблицы.

По database_id мы можем определить имя базы данных простым запросом к таблице sys.databases:

SELECT 
    name 
FROM sys.databases 
WHERE database_id=35;

В нашем случае это база DBMS_locks:

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

• sys.partitions — содержит одну строку для каждой секции всех таблиц и большинства типов индексов базы данных.
• sys.objects — содержит строку для каждого определенного пользователем объекта области действия схемы, созданного в базе данных, включая изначально скомпилированные скалярные пользовательские функции.
• sys.indexes — cодержит строку для каждого индекса или кучи табличного объекта, такого как таблица, представление или функция с табличным значением.
• sys.schemas — cодержит по одной строке для каждой схемы базы данных.

USE DBMS_locks;
SELECT 
    sc.name as schema_name, 
    so.name as object_name, 
    si.name as index_name
FROM sys.partitions AS p
JOIN sys.objects as so on 
    p.object_id=so.object_id
JOIN sys.indexes as si on 
    p.index_id=si.index_id and 
    p.object_id=si.object_id
JOIN sys.schemas AS sc on 
    so.schema_id=sc.schema_id
WHERE hobt_id = 72057594109100032 ;

В нашем случае запрос ожидал на блокировке таблицы _ReferenceChngR50 при взаимодействии с индексом _ReferenceChngR50_2. С помощью метода ПолучитьСтруктуруХраненияБазыДанных() определяем, что это таблица изменений справочника Справочник1:

Далее по хэшу (8469d4d722c1) найдем конкретную строку таблицы. Это можно сделать отобрав в найденной таблице его значение по виртуальной колонке %%lockres%%:

SELECT
    *
FROM _ReferenceChngR50 (NOLOCK)
WHERE %%lockres%% = '(8469d4d722c1)';

Так как в нашем случае это таблица изменений, мы можем взять поле _IDRRef, то есть ссылку справочника «Справочник1» и получить по его значению ссылку 1С.

Ссылочные поля имеют тип BINARY(16), нам нужно взять часть строки после префикса 0x и выполнить преобразование в уникальный идентификатор, далее по нему получим ссылку на элемент справочника:

СтрUUID = "8113002590A7FB1511EEDC6398BA28AE";
GUID = Прав(СтрUUID, 8) + "-" + Сред(СтрUUID, 21, 4) + "-" + Сред(СтрUUID, 17, 4) + "-" + Лев(СтрUUID, 4) + "-" + Сред(СтрUUID, 5, 12);
ЭлементСправочника = Справочники.Справочник1.ПолучитьСсылку(Новый УникальныйИдентификатор(GUID));

В нашем случае им оказался «Элемент1», который мы и использовали в коде:

ПланыОбмена.ЗарегистрироватьИзменения(Узел, Справочники.Справочник1.Элемент1)

Исследование блокировок по логам ТЖ — элемент <dbmslocks>

Даже без привязки к конкретной СУБД платформа сама имеет средства для расследования блокировок СУБД. Существует возможность выводить дополнительные поля с информацией о блокировках СУБД в технологический журнал. Для этого необходимо добавить в настройку logcfg.xml специальный элемент <dbmslocks>.

Информация с ИТС

Ищем блокировки

Для разнообразия возьмем аналогичную тестовую базу на PostgreSQL и настроим ТЖ с добавленным элементом <dbmslocks/>:

<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
 <dump create="false"/>
  <log location="C:\TJlogs" history="1">
 <event>
   <eq property="name" value="SDBL"/>
   <eq property="p:processname" value="DBMS_locks_PostgreSQL"/>
  </event>
  <event>
   <eq property="name" value="DBPOSTGRS"/>
   <eq property="p:processname" value="DBMS_locks_PostgreSQL"/>
  </event>
  <event>
   <eq property="name" value="EXCP"/>
   <eq property="p:processname" value="DBMS_locks_PostgreSQL"/>
  </event>
  <event>
   <eq property="name" value="EXCPCNTX"/>
   <eq property="p:processname" value="DBMS_locks_PostgreSQL"/>
  </event>
  <property name="all"/>
 </log>
 <dbmslocks/>
</config>

Включаем ТЖ, снова повторяем наш эксперимент с двумя сеансами и ловим уже знакомую ошибку:

Далее, как указано на ИТС, выбираем первые события с наличием полей lka и lkp, для этого выполняем команды bash:

• Источник блокировки:
  cat *.log | awk -vORS= '{if(match($0, "^[0-9][0-9]\:[0-9][0-9]\.[0-9]+\-")) print "\n"$0; else print $0;}' | grep 'lka=' | sed -e "s/\xef\xbb\xbf/ /g" | head -n1 > lka.txt
• Жертва блокировки:
  cat *.log | awk -vORS= '{if(match($0, "^[0-9][0-9]\:[0-9][0-9]\.[0-9]+\-")) print "\n"$0; else print $0;}' | grep 'lkp=' | sed -e "s/\xef\xbb\xbf/ /g" | head -n1  > lkp.txt

Файл lka.txt:

Файл lkp.txt:

Далее ищем все события с отбором по lkaid=’5,6’ и lkpid=5:

В файле lka_all.txt видим три события с одинаковым контекстом, в том числе событие компиляциии запроса SDBL с длительностью 26,5 сек., запрос которого является источником блокировки.

В файле lkp_all.txt видим только одно событие, то же самое, что было в файле lkp.txt, это и есть «жертва» блокировки с контекстом:

Как итог — мы нашли контексты обеих сторон. Кажется, этого должно быть достаточно для анализа и разбора проблемы.

Исследование блокировок по логам PostgreSQL

Если мы имеем дело с базами на PostgreSQL, то для расследования блокировок можно воспользоваться логами СУБД. В этом случае нам нужно обратить внимание на следующие параметры в файле postgresql.conf (подробнее можно почитать в документации postgrespro.ru/docs/postgrespro/11/runtime-config-logging):

• log_lock_waits — определяет нужно ли фиксировать в журнале события, когда сеанс ожидает получения блокировки дольше, чем указано в deadlock_timeout.
  По-умолчанию отключено.
• log_statement — управляет тем, какие SQL-команды записывать в журнал. Допустимые значения: none (отключено), ddl, mod и all (все команды).
• log_line_prefix — строка в стиле функции printf, которая выводится в начале каждой строки журнала сообщений.

В нашем случае настройки ставим следующие:

• log_lock_waits = on.
• log_statement = all — будьте осторожны, на продуктиве с такой настройкой логов может быть много.
• log_line_prefix = ’%m [%p] %q%u@%d %x’ - из важных параметров здесь %p — id процесса, %d — имя базы данных, %x — id транзакции.

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

<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
 <log location="C:\TJlogs" history="1">
  <event>
   <eq property="name" value="SDBL"/>
   <eq property="p:processname" value="DBMS_locks"/>
  </event>
  <event>
   <eq property="name" value="DBPOSTGRS"/>
   <eq property="p:processname" value="DBMS_locks"/>
  </event>
  <event>
   <eq property="name" value="EXCP"/>
   <eq property="p:processname" value="DBMS_locks"/>
  </event>
  <event>
   <eq property="name" value="EXCPCNTX"/>
   <eq property="p:processname" value="DBMS_locks"/>
  </event>
  <property name="all"/>
 </log>
</config>

Далее генерируем нашу стендовую блокировку, и получаем уже такую родную ошибку:

Для начала найдем в наших логах PostgreSQL сообщения, относящиеся к нашей базе и с текстом ошибки «canceling statement due to lock timeout». Для этого воспользуемся следующим bash-скриптом:

Обратите внимание, как интересно логируются события: ошибка отдельно, контекст ошибки отдельно, запрос отдельно.

Из этих строк узнаем данные «жертвы» — id процесса указан в квадратных скобках — 1207, а в строке STATEMENT находим текст запроса SQL.

Далее найдем событие ожидания блокировки связанное с найденным процессом, ищем строки с текстом «still waiting for ShareLock», захватывая следующие:

Узнаем из строк:

• «process 1207 still waiting for ShareLock on transaction 454151499» — id транзакции виновника 454151499.
• «Process holding the lock: 31950. Wait queue: 1207.» — id процесса виновника 31950.

По ним найдем в логах события виновника:

Здесь мы можем увидеть два текста запроса SQL виновника блокировки.

Теперь, как и в случае расследования по трассе MSSQL, отберем события из технологического журнала по найденным dbpid и тексту запроса жертвы и виновника:

• События жертвы:
  cat *.log | awk -vORS= '{if(match($0, "^[0-9][0-9]\:[0-9][0-9]\.[0-9]+\-")) print "\n"$0; else print $0;}' | grep ',DBPOSTGRS,.*dbpid=1207.*_ReferenceChngR50' | sed -e "s/\xef\xbb\xbf/ /g" | head > victim.txt
• События виновника:
  cat *.log | awk -vORS= '{if(match($0, "^[0-9][0-9]\:[0-9][0-9]\.[0-9]+\-")) print "\n"$0; else print $0;}' | grep ',DBPOSTGRS,.*dbpid=31950.*_ReferenceChngR50' | sed -e "s/\xef\xbb\xbf/ /g" | head > culprit.txt

Тем самым находим контекст жертвы:

И контекст виновника:

На этом самая легкая часть завершена и можно приступить к анализу кода 1С на предмет исправления. Удачи!

Заметка про эскалацию СУБД

В наших изысканиях мы также попытались воспроизвести ошибку таймаута, связанную с эскалацией блокировок СУБД. Как мы уже писали выше, при стандартных настройках эскалация СУБД на таблице должна возникать при достижении 5000 блокировок. Поэтому для эксперимента мы в одном сеансе взяли 10000 элементов справочника, за исключением специального элемента «ЭлементДляЭскалации», и регистрировали их в одной транзакции с паузой перед завершением.

При достижении паузы в другом сеансе выполняли код регистрации изменений элемента «ЭлементДляЭскалации».

Выполнялся следующий код.

В первом сеансе:

Узел = ПланыОбмена.ПланОбмена1.НайтиПоНаименованию("Тестовый узел");
Запрос = Новый Запрос;
Запрос.Текст = 
"ВЫБРАТЬ ПЕРВЫЕ 10000
|  Справочник1.Ссылка КАК Ссылка
|ИЗ
|  Справочник.Справочник1 КАК Справочник1
|ГДЕ
|  Справочник1.Ссылка <> ЗНАЧЕНИЕ(Справочник.Справочник1.ЭлементДляЭскалации)";
	
РезультатЗапроса = Запрос.Выполнить();
ВыборкаДетальныеЗаписи = РезультатЗапроса.Выбрать();
МассивСсылок = Новый Массив;
Пока ВыборкаДетальныеЗаписи.Следующий() Цикл
  МассивСсылок.Добавить(ВыборкаДетальныеЗаписи.Ссылка);
КонецЦикла;
  
НачатьТранзакцию();
	
ПланыОбмена.ЗарегистрироватьИзменения(Узел , МассивСсылок);
//Пауза
ЗафиксироватьТранзакцию();

Во втором сеансе:

Узел = ПланыОбмена.ПланОбмена1.НайтиПоНаименованию("Тестовый узел");
ПланыОбмена.ЗарегистрироватьИзменения(Узел, Справочники.Справочник1.ЭлементДляЭскалации);

И к нашему удивлению — эскалации не происходило.

Что может влиять на использование эскалации? В первую очередь флаги трассировки 1211 и 1224, мы о них уже упоминали. Из документации (learn.microsoft.com/ru-ru/sql/t-sql/database-console-commands/dbcc-traceon-trace-flags-transact-sql?view=sql-server-ver15) :

• 1211 — отключает укрупнение блокировки, основанное на слишком активном использовании памяти или на количестве блокировок.
• 1224 — отключает укрупнение блокировок на основе количества блокировок. Однако слишком активное использование памяти может включить укрупнение блокировок.

Проверили их состояние с помощью команды:

DBCC TRACESTATUS (1224, 1211)

В нашей базе флаги были не включены.

Следующий пункт проверки — настройки эскалации на уровне таблиц. Их можно посмотреть, выполнив следующий запрос в контексте нужной базы:

USE DBMS_locks;
SELECT top 100 lock_escalation, lock_escalation_desc, name FROM sys.tables

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

Как мы выяснили позже — это связано с версией платформы. При реструктуризации базы на более ранних релизах в таблицах указывался режим AUTO/TABLE:

Чтобы убедиться в том, что это зависит от платформы, мы настроили трассировку Extended events по событиям sql_batch_complited:

И увидели, что с некоторого релиза в текст запроса создания таблицы стала добавляться дополнительная команда установки режима эскалации = DISABLE.

Заключение

Давайте попытаемся сделать выводы.

Прежде всего заметим, что знания это и вправду — сила. Вот уж кажется и не встретишь более никаких блокировок на СУБД, ан нет — вот они красуются. И в этот момент нельзя сказать «как же так, мы так не договаривались», надо решать задачу. Поэтому не напрасно преподается этот раздел на курсах, экзаменуется на «Эксперте». Реальная жизнь эксперта богаче ожиданий.

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

Кроме этого заметим, что теперь следует в обязательном порядке знать и понимать подходы, применяемые как на MS SQL так и на PostgreSQL, а они совершенно различны. И, конечно, знания bash-скриптов чрезвычайно важны, даже если у вас есть под рукой мощные инструменты. Например, мы быстро расследовали логи PostgreSQL.

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