Технологические вопросы крупных внедрений
13.05.2016

Методика выявления длительной транзакции, которая привела к значительному расходу tempdb

Описание проблемы

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

К таким транзакциям стоит относиться подозрительно и стараться их не допускать.

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

Информацию по типичным причинам избыточных блокировок вы сможете найти в статье "Типичные причины избыточных блокировок и методы оптимизации".

В этой методике будет рассмотрена ещё одно достаточно неприятное проявление - избыточное потребление места в tempdb при работе с MS SQL Server.

  

Методика выявления длительной транзакции, которая привела к значительному расходу tempdb

1 - Зафиксировать значительное потребление tempdb

В целом объем свободного места можно оценить даже простейшим запросом

Копировать в буфер обмена
SELECT

SUM(unallocated_extent_page_count) AS [free pages],

(SUM(unallocated_extent_page_count)*1.0/128) AS [free space in MB]

FROM sys.dm_db_file_space_usage;

Для оперативной реакции на рост объема tempdb можно использовать "Инциденты и генерацию оповещений в ЦКК".

  

2 - Найти номер транзакции в MS SQL Server Management Studio

На этом шаге мы понимаем, что сейчас происходит значительное потребление места в tempdb. 

Для всех систем, работающих с использованием Технологической Платформы 1С в режиме совместимости с версией 8.3. (и старше) эффективно будет выполнение запроса:

Копировать в буфер обмена
SELECT

session_id , elapsed_time_seconds as duration_seconds, *

FROM sys .dm_tran_active_snapshot_database_transactions

ORDER BY duration_seconds DESC;

Первые две колонки - номер сессии с СУБД и длительность транзакции.

Если длительность транзакции значительная, то транзакция, скорее всего, та, которую мы искали.

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

В этом запросе вы не получите объем места, использованный транзакцией, но по длительности транзакции (косвенный признак) получается идентифицировать виновника в 99% случаев.

Запоминаем номер session_id

Если проблема совсем критичная, а пользователи не могут больше работать, то нужно будет на СУБД выполнить kill 123, где 123 - номер session_idНо это на совсем крайний случай. В этом случае в технологическом журнале будет зафиксировано исключение и событие EXCP. Такая ситуация, например, выглядит так (пример искусственный, но всё же)

Копировать в буфер обмена
37:46.857000-0,EXCP,7,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Exception=DataBaseException,Descr='Соединение 
с сервером баз данных разорвано администратором

dbpid 109, Microsoft SQL Server Native Client 11.0: TCP Provider: An existing 
connection was forcibly closed by the remote host.


HRESULT=80004005, HRESULT=80004005, SQLSrvr: SQLSTATE=08S01, state=1, 
Severity=10, native=10054, line=0

',Context='Форма.Вызов : 
Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

Обработка.Обработка1.Форма.Форма.Форма : 16 : НЗ.Записать();'

37:46.857001-0,EXCPCNTX,0,ClientComputerName=Server1C,ServerComputerName=Server1C,UserName=DefUser,ConnectString='Srvr="Server1C";Ref="test169";',Context='Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

Обработка.Обработка1.Форма.Форма.Форма : 16 : НЗ.Записать();'

37:46.857002-46998,EXCPCNTX,6,SrcName=DBMSSQL,OSThread=13232,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=1,dbpid=109,Sql='DELETE 
FROM T1

FROM dbo._InfoRg10 T1',Context='Форма.Вызов : 
Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

Обработка.Обработка1.Форма.Форма.Форма : 16 : НЗ.Записать();'

37:46.857003-63003,EXCPCNTX,5,SrcName=SDBL,OSThread=13232,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=1,Sdbl=DELETE 
FROM InfoRg10,Context='Форма.Вызов : 
Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

Обработка.Обработка1.Форма.Форма.Форма : 16 : НЗ.Записать();'

37:46.857004-468727999,EXCPCNTX,4,SrcName=SDBL,OSThread=13232,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=0,Func=Transaction,Context='Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

Обработка.Обработка1.Форма.Форма.Форма : 16 : НЗ.Записать();'

37:46.857005-468728001,EXCPCNTX,3,SrcName=SDBL,OSThread=13232,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=0,Func=HoldConnection,Context='Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

Обработка.Обработка1.Форма.Форма.Форма : 16 : НЗ.Записать();'

37:46.857006-468760005,EXCPCNTX,2,SrcName=CALL,OSThread=13232,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Context=Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере,Context='Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

Обработка.Обработка1.Форма.Форма.Форма : 16 : НЗ.Записать();'

37:46.857007-475280007,EXCPCNTX,2,SrcName=CONN,OSThread=13232,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,ClientID=39,Txt=Outgoing 
connection closed,Context='Форма.Вызов : 
Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

Обработка.Обработка1.Форма.Форма.Форма : 16 : НЗ.Записать();'

37:46.857008-475468007,EXCPCNTX,0,SrcName=CONN,OSThread=13232,process=rphost,t:clientID=38,Context='Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

Обработка.Обработка1.Форма.Форма.Форма : 16 : НЗ.Записать();'

37:46.903000-92996,DBMSSQL,6,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=1,dbpid=109,Sql='DELETE 
FROM T1

FROM dbo._InfoRg10 T1',Context='Форма.Вызов : 
Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

Обработка.Обработка1.Форма.Форма.Форма : 16 : НЗ.Записать();'

37:46.966001-1,SDBL,6,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=1,Func=setRollbackOnly,Context='Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

Обработка.Обработка1.Форма.Форма.Форма : 16 : НЗ.Записать();'

37:46.966002-172002,SDBL,5,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=1,Sdbl=DELETE 
FROM InfoRg10,Context='Форма.Вызов : 
Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

Обработка.Обработка1.Форма.Форма.Форма : 16 : НЗ.Записать();'

37:47.013001-0,EXCP,6,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Exception=DataBaseException,Descr='Соединение 
с сервером баз данных разорвано администратором

dbpid 109, Microsoft SQL Server Native Client 11.0: Communication link failure

HRESULT=80004005, ',Context=Форма.Вызов : 
Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

37:47.013002-0,EXCPCNTX,0,ClientComputerName=Server1C,ServerComputerName=Server1C,UserName=DefUser,ConnectString='Srvr="Server1C";Ref="test169";',Context=Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

37:47.013003-3,EXCPCNTX,5,SrcName=DBMSSQL,OSThread=13232,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=1,dbpid=109,Sql=SELECT 
@@TRANCOUNT,Context=Форма.Вызов : 
Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

37:47.013004-468883999,EXCPCNTX,4,SrcName=SDBL,OSThread=13232,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=0,Func=Transaction,Context=Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

37:47.013005-468884001,EXCPCNTX,3,SrcName=SDBL,OSThread=13232,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=0,Func=HoldConnection,Context=Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

37:47.013006-468916005,EXCPCNTX,2,SrcName=CALL,OSThread=13232,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Context=Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере,Context=Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

37:47.013007-475436007,EXCPCNTX,2,SrcName=CONN,OSThread=13232,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,ClientID=39,Txt=Outgoing 
connection closed,Context=Форма.Вызов : 
Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

37:47.013008-475624007,EXCPCNTX,0,SrcName=CONN,OSThread=13232,process=rphost,t:clientID=38,Context=Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

37:47.013009-9,DBMSSQL,5,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=1,dbpid=109,Sql=SELECT 
@@TRANCOUNT,Context=Форма.Вызов : 
Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

37:47.013010-468884005,SDBL,4,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=0,Func=Transaction,Func=RollbackTransaction,Context=Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

37:47.028002-1,DBMSSQL,4,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=0,dbpid=109,Func=disconnect,Context=Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

37:47.028003-468898999,SDBL,3,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=0,Func=HoldConnection,Context=Форма.Вызов 
: Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

37:47.028008-0,EXCP,3,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Exception=580392e6-ba49-4280-ac67-fcd6f2180121,Descr='src\VResourceInfoBaseImpl.cpp(986):

580392e6-ba49-4280-ac67-fcd6f2180121: Невосстановимая ошибка

Ошибка при выполнении запроса POST к ресурсу /e1cib/logForm:

dc31263e-ecbf-41bd-9b3a-7b55897d5fd6: Соединение с сервером баз данных разорвано 
администратором

dbpid 109, Microsoft SQL Server Native Client 11.0: TCP Provider: An existing 
connection was forcibly closed by the remote host.


HRESULT=80004005, HRESULT=80004005, SQLSrvr: SQLSTATE=08S01, state=1, 
Severity=10, native=10054, line=0

'

В этом примере можно увидеть искомую транзакцию

Копировать в буфер обмена
37:47.013010-468884005,SDBL,4,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=0,Func=Transaction,Func=RollbackTransaction,
Context=Форма.Вызов : Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере37:47.013010-468884005,SDBL,4,process=rphost,p:processName=test169,t:clientID=38,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=6,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=0,Func=Transaction,Func=RollbackTransaction,
Context=Форма.Вызов : Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

Есть более "полный" запрос, который также позволит получить нужный номер транзакции, особенно, если система работает в режиме совместимости с 8.2.

Однако, приведенный ниже запрос может выполняться несколько десятков секунд (будьте к этому готовы):  DECLARE @curr_date as DATETIME

Копировать в буфер обмена
DECLARE @curr_date as DATETIME

SET @curr_date = GETDATE()


select --SESSION_TRAN.*,

SESSION_TRAN.session_id AS connectID, -- "Соединение с СУБД" в консоли кластера 
1С

--TRAN_INFO.*,

TRAN_INFO.transaction_begin_time,

DateDiff(MINUTE, TRAN_INFO.transaction_begin_time, @curr_date) AS Duration, -- 
Длительность в минутах

TRAN_INFO.transaction_type, -- 1 = транзакция чтения-записи; 2 = транзакция 
только для чтения; 3 = системная транзакция; 4 = распределенная транзакция.

TRAN_INFO.transaction_state, -- 0 = Транзакция еще не была полностью 
инициализирована; 1 = Транзакция была инициализирована, но еще не началась; 2 = 
Транзакция активна; 3 = Транзакция закончилась. Используется для транзакций 
«только для чтения»; 4 = Фиксирующий процесс был инициализирован на 
распределенной транзакции. Предназначено только для распределенных транзакций. 
Распределенная транзакция все еще активна, но дальнейшая обработка не может 
иметь место; 5 = Транзакция находится в готовом состоянии и ожидает разрешения; 
6 = Транзакция зафиксирована; 7 = Производится откат транзакции; 8 = откат 
транзакции был выполнен.

--CONN_INFO.*,

CONN_INFO.connect_time,

CONN_INFO.num_reads,

CONN_INFO.num_writes,

CONN_INFO.last_read,

CONN_INFO.last_write,

CONN_INFO.client_net_address,

CONN_INFO.most_recent_sql_handle,

--SQL_TEXT.*,

SQL_TEXT.dbid,

db_name(SQL_TEXT.dbid) AS IB_NAME,

SQL_TEXT.text,

--QUERIES_INFO.*,

QUERIES_INFO.start_time,

QUERIES_INFO.status,

QUERIES_INFO.command,

QUERIES_INFO.wait_type,

QUERIES_INFO.wait_time,

PLAN_INFO.query_plan


FROM sys.dm_tran_session_transactions AS SESSION_TRAN

JOIN sys.dm_tran_active_transactions AS TRAN_INFO

ON SESSION_TRAN.transaction_id = TRAN_INFO.transaction_id

LEFT JOIN sys.dm_exec_connections AS CONN_INFO

ON SESSION_TRAN.session_id = CONN_INFO.session_id

CROSS APPLY sys.dm_exec_sql_text(CONN_INFO.most_recent_sql_handle) AS SQL_TEXT

LEFT JOIN sys.dm_exec_requests AS QUERIES_INFO

ON SESSION_TRAN.session_id = QUERIES_INFO.session_id

LEFT JOIN (

SELECT VL_SESSION_TRAN.session_id AS session_id,

VL_PLAN_INFO.query_plan AS query_plan

FROM sys.dm_tran_session_transactions AS VL_SESSION_TRAN

INNER JOIN sys.dm_exec_requests AS VL_QUERIES_INFO

ON VL_SESSION_TRAN.session_id = VL_QUERIES_INFO.session_id

CROSS APPLY sys.dm_exec_text_query_plan(VL_QUERIES_INFO.plan_handle, 
VL_QUERIES_INFO.statement_start_offset, VL_QUERIES_INFO.statement_end_offset) AS 
VL_PLAN_INFO) AS PLAN_INFO

ON SESSION_TRAN.session_id = PLAN_INFO.session_id


ORDER BY transaction_begin_time ASC 

Если вы не стали рисковать и отменять транзакцию (вдруг выполняется очень важная операция?), расследуем дальше.

   

3 - Находим код, выполнение которого привело к длительному выполнению в транзакции 

Открываем консоль администрирования кластера серверов.

Переходим на закладку сеансы.

Нас интересуют две колонки:

- Соединение с СУБД

- Номер сеанса

Запоминаем номер сеанса. 

Обратите внимание, что session_id = Соединение с СУБД.

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

В технологическом журнале это будет выглядеть так:  

Копировать в буфер обмена
54:56.171051-0,EXCP,4,process=rphost,p:processName=test169,t:clientID=73,t:applicationName=1CV8C,t:computerName=Server1C,t:connectID=8,SessionID=4,Usr=DefUser,AppID=1CV8C,Exception=60c686dc-798f-4d17-aadb-a90156a16eb8,Descr='src\RMngrCalls.cpp(441):

60c686dc-798f-4d17-aadb-a90156a16eb8: Сеанс отсутствует или удален

ID=c99e60a7-a706-487f-981b-54d250b9c20e, 
File=src\SeanceContextBasImpl.cpp(6867)',Context='Форма.Вызов : 
Обработка.Обработка1.Форма.Форма.Модуль.Команда1НаСервере

Обработка.Обработка1.Форма.Форма.Форма : 16 : НЗ.Записать();'

Но удаление сеанса - на крайний случай.

4 - Выясняем, что делает этот сеанс

Открываем журнал регистрации, отбираем по номеру сеанса, смотрим, что сеанс делает.

Если не понятно, что делает сеанс (а он ещё работает) быстро настраиваем технологический журнал по этому сеансу  

Копировать в буфер обмена
<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
<log location="C:\LOGS\SessionID" history="4">
<event>
<ne property="Name" value=""/>
<eq property="SessionID" value="321"/>
</event>
<property name="all"/>
</log>
</config>
Здесь 321 - это номер сеанса.  

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

5 - Воспроизводим и разбираем проблему

Необходимо повторять где-то на копии ровно эту операцию.

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

Для этого достаточно настроить журнал 

Копировать в буфер обмена
<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
<log location="C:\LOGS\SessionID" history="4">
<event>
<eq property="Name" value="DBMSSQL"/>
</event>
<property name="all"/>
</log>
<plansql/>
</config>

и пройти операцию один раз под отладкой, отслеживая объем в tempdb.

6 - Исправляем.

На этом шаге всё зависит от того, что именно у вас получится выяснить в процессе расследования.    

Обратите внимание