Разработчики и администраторы баз данных часто сталкиваются с ситуацией, когда при анализе блокировок в MS SQL Server с помощью инструмента Blocked Process Report (BPR) в секции блокирующего процесса blocking-process отображается совсем не тот запрос, который на самом деле удерживает блокировку. Вместо тяжелого UPDATE или INSERT, который заблокировал таблицу остатков, мы видим безобидный TRUNCATE TABLE #t11 или DROP TABLE, выполняющийся в самом конце транзакции проведения документа.
В этой статье мы подробно разберем, почему СУБД ведет себя подобным образом в связке с платформой 1С:Предприятие, и рассмотрим по шагам эффективные методы получения истинного виновника блокировки.
Для начала проанализируем внутренний механизм работы СУБД SQL Server. Когда время ожидания блокировки превышает заданный порог (параметр blocked process threshold), фоновый процесс СУБД генерирует отчет. В XML-структуру этого отчета для блокирующей сессии записывается значение из буфера ввода (поле inputbuf).
Критически важный нюанс: СУБД записывает в буфер ввода тот запрос, который выполняется в блокирующей сессии в конкретный миллисекундный момент генерации отчета (или последний выполненный пакет инструкций в этой сессии). СУБД не ведет историю выполнения запросов внутри транзакции по умолчанию.
Платформа 1С работает в режиме длинных неявных транзакций. Процесс проведения документа выглядит следующим образом:
BEGIN TRANSACTION.UPDATE таблицы остатков регистров. На этом этапе накладываются и удерживаются монопольные или обновляемые транзакционные блокировки.TRUNCATE TABLE #t11 или удаление временных таблиц.COMMIT TRANSACTION, и только тогда блокировки снимаются.Если другой пользователь (процесс-жертва) попытался обратиться к заблокированной таблице остатков, он встает в очередь ожидания. Спустя, к примеру, 10 секунд ожидания генерируется Blocked Process Report. В этот момент транзакция проведения документа все еще активна (так как 1С выполняет финальную очистку временных таблиц), но на уровне SQL Server в блокирующей сессии уже крутится инструкция TRUNCATE. Именно ее СУБД и записывает в отчет, скрывая от нас исторический UPDATE.
Ниже рассмотрим три надежных метода, которые помогут докопаться до истины.
Поскольку СУБД не хранит историю выполнения команд внутри сессии, самым надежным способом является сопоставление данных SQL Server с историей выполнения запросов на стороне сервера приложений 1С с помощью Технологического журнала (ТЖ).
Рассмотрим алгоритм действий по шагам:
Шаг 1. Настройка сборщика Технологического журнала.
Нам необходимо настроить сбор событий СУБД и контекста исполнения на сервере 1С. Для этого создадим файл logcfg.xml в каталоге конфигурации ТЖ (обычно это C:\Program Files\1cv8\conf) со следующим содержимым:
<?xml version="1.0" encoding="UTF-8"?>
<logconfig xmlns="http://v8.1c.ru/v8/tech-log">
<log location="C:\v8_logs\dbms" history="24">
<event>
<eq property="Name" value="DBMSSQL"/>
</event>
<property name="all"/>
</log>
<log location="C:\v8_logs\locks" history="24">
<event>
<eq property="Name" value="TLOCK"/>
</event>
<event>
<eq property="Name" value="TTIMEOUT"/>
</event>
<event>
<eq property="Name" value="TDEADLOCK"/>
</event>
<property name="all"/>
</log>
<plansql/>
<dbmslocks/>
</logconfig>
Параметр <dbmslocks/> крайне важен, так как он заставляет систему выводить информацию о взаимоблокировках и таймаутах СУБД со стороны платформы.
Шаг 2. Получение SPID блокирующего процесса.
Из полученного файла Blocked Process Report на SQL Server (или через Extended Events) мы фиксируем идентификатор сессии-виновника — SPID (например, spid=74), а также точное время возникновения блокировки.
Шаг 3. Сопоставление данных в ТЖ.
Открываем файлы логов ТЖ из папки C:\v8_logs\dbms, созданные в период блокировки. Выполняем поиск по идентификатору соединения СУБД, который в ТЖ фигурирует как dbpid (в нашем случае dbpid=74) или t:connectID.
Поскольку Технологический журнал последовательно записывает абсолютно все запросы, отправленные платформой в СУБД в рамках данного сеанса, мы увидим хронологическую цепочку:
DBMSSQL с началом транзакции.UPDATE или INSERT таблицы остатков (с указанием точного времени выполнения).TRUNCATE TABLE #t11, на котором споткнулся стандартный профайлер SQL Server.Главный плюс метода: в строке лога ТЖ для каждого события DBMSSQL будет заполнено свойство Context. Оно покажет точную строку кода конфигурации 1С (например, модуль объекта документа, процедура проведения, конкретная строка кода), которая инициировала этот самый первый, блокирующий запрос.
Если у нас нет прямого доступа к серверу приложений 1С для чтения Технологического журнала, мы можем решить задачу силами СУБД, перейдя с устаревшего SQL Profiler на механизм Extended Events.
Мы можем настроить сессию Extended Events, которая будет отслеживать событие захвата блокировок sqlserver.lock_acquired совместно с получением текста SQL-запроса и идентификатора транзакции transaction_id.
Проанализируем этот алгоритм:
transaction_id.transaction_id.UPDATE, который захватил монопольную блокировку (тип ресурса OBJECT или KEY, режим блокировки X или U), задолго до того, как транзакция дошла до стадии очистки временных таблиц.Если блокировки в вашей базе данных длятся достаточно долго (более нескольких секунд), мы можем перехватить истинный запрос в режиме реального времени, обратившись к системным динамическим представлениям (DMV) MS SQL Server.
Для этого мы можем использовать следующий диагностический SQL-скрипт:
SELECT
r.session_id AS BlockedSpid,
r.blocking_session_id AS BlockingSpid,
r.wait_time AS WaitTimeMs,
r.wait_type AS WaitType,
t.text AS BlockedQueryText,
bt.text AS BlockingQueryText,
ib.event_info AS BlockingInputBuffer
FROM sys.dm_exec_requests r
CROSS APPLY sys.dm_exec_sql_text(r.sql_handle) t
LEFT JOIN sys.dm_exec_connections c ON r.blocking_session_id = c.session_id
OUTER APPLY sys.dm_exec_sql_text(c.most_recent_sql_handle) bt
OUTER APPLY sys.dm_exec_input_buffer(r.blocking_session_id, NULL) ib
WHERE r.blocking_session_id <> 0;
Разберем, что показывает данный запрос:
BlockedQueryText — текст запроса, который в данный момент ожидает освобождения ресурсов (жертва).BlockingInputBuffer — то, что показал бы стандартный профайлер (скорее всего, очистка временной таблицы виновником).BlockingQueryText — благодаря обращению к most_recent_sql_handle через соединение блокировщика, данный скрипт с высокой долей вероятности вернет нам предыдущий активный SQL-пакет сессии-блокировщика, который и наложил ограничения.Использование одного лишь стандартного инструмента Blocked Process Report в SQL Profiler для анализа транзакционных блокировок в 1С малоэффективно из-за специфики работы платформы с СУБД.
Для гарантированного результата придерживайтесь следующих правил: