Мониторинг SQL Server с помощью Extended Events (и не только) для 1С. Как держать руку на пульсе?

Оригинальный скрипт находится здесь.

-- Анализ тяжелых запросов по CPU

CREATE EVENT SESSION [HeavyQueryByCPU] ON SERVER
-- Класс событий RPC:Completed указывает, что удаленный вызов процедуры завершен.
-- https://docs.microsoft.com/ru-ru/sql/relational-databases/event-classes/rpc-completed-event-class?view=sql-server-2017
ADD EVENT sqlserver.rpc_completed(
    ACTION(
        sqlserver.client_app_name,
        sqlserver.client_hostname,
        sqlserver.client_pid,
        sqlserver.database_id,
        sqlserver.nt_username,
        sqlserver.server_principal_name,
        sqlserver.session_id,
        sqlserver.sql_text,
        sqlserver.transaction_id,
        sqlserver.username)
    WHERE ([duration]>(5000000))),
-- Класс событий SQL:BatchCompleted указывает на завершение выполнения пакета языка Transact-SQL.
-- https://docs.microsoft.com/ru-ru/sql/relational-databases/event-classes/sql-batchcompleted-event-class?view=sql-server-2017
ADD EVENT sqlserver.sql_batch_completed(
    ACTION (
        sqlserver.client_app_name,
        sqlserver.client_hostname,
        sqlserver.client_pid,
        sqlserver.database_id,
        sqlserver.nt_username,
        sqlserver.server_principal_name,
        sqlserver.session_id,
        sqlserver.sql_text,
        sqlserver.transaction_id,
        sqlserver.username)
    WHERE ([duration]>(5000000)))
ADD TARGET package0.event_file(SET 
    -- Путь к файлу хранения логов. Если не указан, то используется путь к каталогу логов SQL Server
    filename=N'HeavyQueryByCPU.xel',
    -- Максимальный размер файла в мегабайтах
    max_file_size=(1024),
    -- Максимальное количество файлов, после чего начнется перезапись логов в более старых файлах.
    max_rollover_files=(5)                                                        
    metadatafile=N'HeavyQueryByCPU.xem')
WITH (
    MAX_MEMORY=4096 KB,
    EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,
    MAX_DISPATCH_LATENCY=15 SECONDS,
    MAX_EVENT_SIZE=0 KB,
    MEMORY_PARTITION_MODE=NONE,
    TRACK_CAUSALITY=OFF,
    STARTUP_STATE=OFF)

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

Оригинальный скрипт здесь.

-- Анализ тяжелых запросов по чтению данных

CREATE EVENT SESSION [HeavyQueryByReads] ON SERVER 
-- Класс событий RPC:Completed указывает, что удаленный вызов процедуры завершен.
-- https://docs.microsoft.com/ru-ru/sql/relational-databases/event-classes/rpc-completed-event-class?view=sql-server-2017
ADD EVENT sqlserver.rpc_completed(
    ACTION (
        sqlserver.client_app_name,
        sqlserver.client_hostname,
        sqlserver.client_pid,
        sqlserver.database_id,
        sqlserver.nt_username,
        sqlserver.query_hash,
        sqlserver.query_plan_hash,
        sqlserver.server_principal_name,
        sqlserver.session_id,
        sqlserver.sql_text,
        sqlserver.transaction_id,
        sqlserver.username)
    WHERE ([logical_reads]>(50000))),
-- Класс событий SQL:BatchCompleted указывает на завершение выполнения пакета языка Transact-SQL .
-- https://docs.microsoft.com/ru-ru/sql/relational-databases/event-classes/sql-batchcompleted-event-class?view=sql-server-2017
ADD EVENT sqlserver.sql_batch_completed(
    ACTION (
        sqlserver.client_app_name,
        sqlserver.client_hostname,
        sqlserver.client_pid,
        sqlserver.database_id,
        sqlserver.nt_username,
        sqlserver.query_hash,
        sqlserver.query_plan_hash,
        sqlserver.server_principal_name,
        sqlserver.session_id,
        sqlserver.sql_text,
        sqlserver.transaction_id,
        sqlserver.username)
    WHERE ([logical_reads]>(50000)))
ADD TARGET package0.event_file(SET 
    -- Путь к файлу хранения логов. Если не указан, то используется путь к каталогу логов SQL Server
    filename=N'HeavyQueryByReads.xel',
    -- Максимальный размер файла в мегабайтах
    max_file_size=(1024),
    -- Максимальное количество файлов, после чего начнется перезапись логов в более старых файлах.
    max_rollover_files=(5),
    metadatafile=N'HeavyQueryByReads.xem')
WITH (
    MAX_MEMORY=4096 KB,
    EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,
    MAX_DISPATCH_LATENCY=15 SECONDS,
    MAX_EVENT_SIZE=0 KB,
    MEMORY_PARTITION_MODE=NONE,
    TRACK_CAUSALITY=OFF,
    STARTUP_STATE=OFF)

При необходимости измените настройки под себя.

Создаем сессию сбора информации обо всех возникших блокировках в системе, их отмене и таймаутах. При этом информацию записываем в файл, но с ограничением максимального размера в 1 ГБ. Максимальное количество файлов установим в 3. Выбранные события для сессии это: Lock:Acquired (возникновение блокировки), Lock:Cancel (отмена блокировки), Lock:Timeout (таймаут на блокировке). Еще дополнительно можно собирать данные по событию Lock:Escalation (эскалация блокировки), но это по необходимости.

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

-- Анализ блокировок

CREATE EVENT SESSION [LockAnalyze] ON SERVER
-- Класс событий Lock:Acquired указывает, что была получена блокировка для ресурса
-- https://docs.microsoft.com/ru-ru/sql/relational-databases/event-classes/lock-acquired-event-class?view=sql-server-2017
ADD EVENT sqlserver.lock_acquired(
    ACTION (
        sqlserver.client_app_name,
        sqlserver.client_hostname,
        sqlserver.client_pid,
        sqlserver.database_id,
        sqlserver.nt_username,
        sqlserver.server_principal_name,
        sqlserver.session_id,
        sqlserver.sql_text,
        sqlserver.transaction_id,
        sqlserver.username
        )
    ),
-- Класс событий Lock:Cancel сигнализирует, что получение блокировки на ресурс было отменено
-- https://docs.microsoft.com/ru-ru/sql/relational-databases/event-classes/lock-cancel-event-class?view=sql-server-2017
ADD EVENT sqlserver.lock_cancel(
    ACTION (
        sqlserver.client_app_name,
        sqlserver.client_hostname,
        sqlserver.client_pid,
        sqlserver.database_id,
        sqlserver.nt_username,
        sqlserver.server_principal_name,
        sqlserver.session_id,
        sqlserver.sql_text,
        sqlserver.transaction_id,
        sqlserver.username
        )
    ),
-- Класс событий Lock:Timeout указывает на то, что запрос на захват некоторого ресурса превысил время ожидания
-- https://docs.microsoft.com/ru-ru/sql/relational-databases/event-classes/lock-timeout-event-class?view=sql-server-2017
ADD EVENT sqlserver.lock_timeout(
    WHERE ([duration]>(1) AND [resource_0]<>(0)))
ADD TARGET package0.event_file(SET 
    -- Путь к файлу хранения логов. Если не указан, то используется путь к каталогу логов SQL Server
    filename=N'LockAnalyze.xel',
    -- Максимальный размер файла в мегабайтах
    max_file_size=(1024),
    -- Максимальное количество файлов, после чего начнется перезапись логов в более старых файлах.
    max_rollover_files=(5),
    metadatafile=N'LockAnalyze.xem')
WITH (
    MAX_MEMORY=4096 KB,
    EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,
    MAX_DISPATCH_LATENCY=15 SECONDS,
    MAX_EVENT_SIZE=0 KB,
    MEMORY_PARTITION_MODE=NONE,
    TRACK_CAUSALITY=OFF,
    STARTUP_STATE=OFF
)

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

Также есть другой способ для оперативного анализа кто и что блокирует. Для этого создадим сессию с доп. событием SQL:LockReleased, которое показывает снятие блокировки с ресурса. Вот так будут выглядеть скрипты оперативного анализа блокировок.

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name='LockAnalyze_Operational')  
    DROP EVENT SESSION LockAnalyze_Operational ON SERVER  
GO  

DECLARE @dbid int  
-- Для фильтра по базе данных
SELECT @dbid = db_id('<ИмяБазыДанных>')  
IF @dbid IS NULL  
BEGIN  
    RETURN  
END  

-- Создаем сессию для анализа блокировок
DECLARE @sql nvarchar(1024)  
SET @sql = '  
CREATE EVENT SESSION LockAnalyze_Operational ON SERVER  
ADD EVENT sqlserver.lock_acquired   
    (action   
        ( sqlserver.sql_text, sqlserver.database_id, sqlserver.tsql_stack,  
         sqlserver.plan_handle, sqlserver.session_id)  
    WHERE ( database_id=' + cast(@dbid as nvarchar) + ' AND resource_0!=0)   
    ),  
ADD EVENT sqlserver.lock_released   
    (WHERE ( database_id=' + cast(@dbid as nvarchar) + ' AND resource_0!=0 ))  
ADD TARGET package0.pair_matching   
    ( SET begin_event=''sqlserver.lock_acquired'',   
            begin_matching_columns=''database_id, resource_0, resource_1, resource_2, transaction_id, mode'',   
            end_event=''sqlserver.lock_released'',   
            end_matching_columns=''database_id, resource_0, resource_1, resource_2, transaction_id, mode'',  
    respond_to_memory_pressure=1)  
WITH (max_dispatch_latency = 1 seconds)'  
EXEC (@sql)  

ALTER EVENT SESSION LockAnalyze_Operational ON SERVER  
STATE = START  

Ждем выполнения проблемной нагрузки.

-- Сохраняем данные сессии во временную таблицу для последующего анализа
SELECT   
	objlocks.value('(action[@name="session_id"]/value)[1]', 'int')  
        AS session_id,  
    objlocks.value('(data[@name="database_id"]/value)[1]', 'int')   
        AS database_id,  
    objlocks.value('(data[@name="resource_type"]/text)[1]', 'nvarchar(50)' )   
        AS resource_type,  
    objlocks.value('(data[@name="resource_0"]/value)[1]', 'bigint')   
        AS resource_0,  
    objlocks.value('(data[@name="resource_1"]/value)[1]', 'bigint')   
        AS resource_1,  
    objlocks.value('(data[@name="resource_2"]/value)[1]', 'bigint')   
        AS resource_2,  
    objlocks.value('(data[@name="mode"]/text)[1]', 'nvarchar(50)')   
        AS mode,  
    objlocks.value('(action[@name="sql_text"]/value)[1]', 'varchar(MAX)')   
        AS sql_text,  
    CAST(objlocks.value('(action[@name="plan_handle"]/value)[1]', 'varchar(MAX)') AS xml)   
        AS plan_handle,      
    CAST(objlocks.value('(action[@name="tsql_stack"]/value)[1]', 'varchar(MAX)') AS xml)   
        AS tsql_stack  
INTO #unmatched_locks  
FROM (  
    SELECT CAST(xest.target_data as xml)   
        lockinfo  
    FROM sys.dm_xe_session_targets xest  
    JOIN sys.dm_xe_sessions xes ON xes.address = xest.event_session_address  
    WHERE xest.target_name = 'pair_matching' AND xes.name = 'LockAnalyze_Operational'  
) heldlocks  
CROSS APPLY lockinfo.nodes('//event[@name="lock_acquired"]') AS T(objlocks)


-- Получаем результаты анализа
SELECT 
	ul.session_id [Сессия]
	,ul.[database_id] AS [ID базы данных]
	,ul.resource_type AS [Тип ресурса]
	,ul.resource_0 AS [Ресурс0]
	,ul.resource_1 AS [Ресурс1]
	,ul.resource_2 AS [Ресурс2]
	,ul.mode AS [Режим блокировки]
	,ul.sql_text AS [Текст запроса]
	,ul.plan_handle AS [Идентификатор плана запроса]
FROM #unmatched_locks ul  
    INNER JOIN sys.dm_tran_locks tl ON ul.database_id = tl.resource_database_id AND ul.resource_type = tl.resource_type  
    WHERE resource_0 IS NOT NULL  
    AND session_id IN   
        (SELECT blocking_session_id FROM sys.dm_exec_requests WHERE blocking_session_id != 0)  
    AND tl.request_status='wait'  
    AND REPLACE(ul.mode, 'LCK_M_', '' ) = tl.request_mode  

-- Удаляем временную таблицу и сессию расширенных событий
DROP TABLE #unmatched_locks  
DROP EVENT SESSION FindBlockers ON SERVER  

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

Оригинальный скрипт здесь.

-- Анализ взаимоблокировок

CREATE EVENT SESSION [DeadlockAnalyze] ON SERVER 
-- Класс событий Lock:Deadlock предназначен для отслеживания возникновения взаимоблокировок и объектов, которые в них участвуют.
-- https://docs.microsoft.com/ru-ru/sql/relational-databases/event-classes/lock-deadlock-event-class?view=sql-server-2017
ADD EVENT sqlserver.lock_deadlock(
    ACTION(
            sqlserver.client_app_name,
            sqlserver.client_hostname,
            sqlserver.client_pid,sqlserver.database_id,
            sqlserver.nt_username,
            sqlserver.server_principal_name,
            sqlserver.session_id,
            sqlserver.sql_text,
            sqlserver.transaction_id,
            sqlserver.username
        )
    ),
-- Класс событий Lock:Deadlock Chain используется для регистрации условий возникновения взаимоблокировок.
-- https://docs.microsoft.com/ru-ru/sql/relational-databases/event-classes/lock-deadlock-chain-event-class?view=sql-server-2017
ADD EVENT sqlserver.lock_deadlock_chain(
    ACTION(
            sqlserver.client_app_name,
            sqlserver.client_hostname,
            sqlserver.client_pid,
            sqlserver.database_id,
            sqlserver.nt_username,
            sqlserver.server_principal_name,
            sqlserver.session_id,
            sqlserver.sql_text,
            sqlserver.transaction_id,
            sqlserver.username
        )
    ),
-- Создает отчет о событии взаимоблокировки в формате XML
ADD EVENT sqlserver.xml_deadlock_report(
    ACTION(
        sqlserver.client_app_name,
        sqlserver.client_hostname,
        sqlserver.client_pid,
        sqlserver.database_id,
        sqlserver.nt_username,
        sqlserver.server_principal_name,
        sqlserver.session_id,
        sqlserver.sql_text,
        sqlserver.transaction_id,
        sqlserver.username
        )
    )
ADD TARGET package0.event_file(SET
        -- Путь к файлу хранения логов. Если не указан, то используется путь к каталогу логов SQL Server
        filename=N'DeadlockAnalyze.xel',
        -- Максимальный размер файла в мегабайтах
        max_file_size=(10),
        -- Максимальное количество файлов, после чего начнется перезапись логов в более старых файлах.
        max_rollover_files=(5),
        metadatafile=N'DeadlockAnalyze.xem'
    )
WITH (
        MAX_MEMORY=4096 KB,
        EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,
        MAX_DISPATCH_LATENCY=15 SECONDS,
        MAX_EVENT_SIZE=0 KB,
        MEMORY_PARTITION_MODE=NONE,
        TRACK_CAUSALITY=OFF,
        STARTUP_STATE=OFF
    )

Обычно взаимоблокировки достаточно редкое явление, но мониторить их нужно в любом случае. Чтобы получить файл графа взаимоблокировки (*.xdl) из XML расширенного события необходимо скопировать вот этот значение в отдельный файл с расширением "xdl".

После этого файл графа можно открывать в SQL Server Managment Studio.

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

Желаю Вам отсутствия взаимоблокировок!

Оригинальный скрипт здесь.

-- Анализ ошибок

CREATE EVENT SESSION [Errors] ON SERVER 
ADD EVENT sqlserver.error_reported(
    ACTION (
        sqlserver.client_app_name,
        sqlserver.client_hostname,
        sqlserver.client_pid,
        sqlserver.database_id,
        sqlserver.is_system,
        sqlserver.nt_username,
        sqlserver.server_principal_name,
        sqlserver.session_id,
        sqlserver.sql_text,
        sqlserver.transaction_id,
        sqlserver.transaction_sequence,
        sqlserver.username)
    WHERE ([severity]>(10)))
ADD TARGET package0.event_file(SET 
    -- Путь к файлу хранения логов. Если не указан, то используется путь к каталогу логов SQL Server
    filename=N'Errors.xel',
    -- Максимальный размер файла в мегабайтах
    max_file_size=(10),
    -- Максимальное количество файлов, после чего начнется перезапись логов в более старых файлах.
    max_rollover_files=(5),
    metadatafile=N'Errors.xem')
WITH (
    MAX_MEMORY=4096 KB,
    EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,
    MAX_DISPATCH_LATENCY=15 SECONDS,
    MAX_EVENT_SIZE=0 KB,
    MEMORY_PARTITION_MODE=NONE,
    TRACK_CAUSALITY=OFF,
    STARTUP_STATE=OFF)

Будут записаны все возможные ошибки уровня СУБД.

Сделать это можно либо через интерфейс.

Либо через TSQL.

ALTER EVENT SESSION <ИмяСессии> ON SERVER  
STATE = STOP;  -- START для запуска

Ничего сложного.

Исходим из того, что база данных для обработки логов уже создана. Нам лишь нужно эти логи туда загрузить. Для этого запустим SQL Server Managment Studio и перейдем в "Файл -> Открыть -> Объединить файлы расширенных событий....".

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

Вводим данные аутентификации, после чего необходимо выбрать базу данных, её схему (по умолчанию "dbo") и имя таблицы для загрузки данных.

Ожидаем завершение операции экспорта.

На этом все, SSMS создал таблицу и загрузил туда данные расширенных событий.

Чтение файлов XEL через T-SQL выполняется с помощью sys.fn_xe_file_target_read_file. Каждое событие хранится в виде XML и вся задача сводится к разбору этих данных для представления в виде таблицы с отдельными колонками.

select
	n.value('(action[@name="database_name"]/value)[1]', 'nvarchar(128)') as database_name,
    n.value('(@name)[1]', 'varchar(50)') as event_name,
    n.value('(@package)[1]', 'varchar(50)') AS package_name,
    n.value('(@timestamp)[1]', 'datetime2') AS [utc_timestamp],
    n.value('(data[@name="duration"]/value)[1]', 'int') as duration,
    n.value('(data[@name="cpu_time"]/value)[1]', 'int') as cpu,
    n.value('(data[@name="physical_reads"]/value)[1]', 'int') as physical_reads,
    n.value('(data[@name="logical_reads"]/value)[1]', 'int') as logical_reads,
    n.value('(data[@name="writes"]/value)[1]', 'int') as writes,
    n.value('(data[@name="row_count"]/value)[1]', 'int') as row_count,
    n.value('(data[@name="statement"]/value)[1]', 'nvarchar(max)') as statement
from (
	select cast(event_data as XML) as event_data
	from sys.fn_xe_file_target_read_file('Q:\SQLTraces\254-sp-sql6\QueryStatistics\QueryAnalysis*.xel', null, null, null)) ed
	cross apply ed.event_data.nodes('event') as q(n)

Если файлов XEL несколько, то есть возможность указать шаблон имени файла через "*", как это сделано в примере выше.

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

Есть множество способов сделать постобработку данных. От написания различных программ на C#, Pyton, 1С и так далее, до использования OneScript. Мы же сейчас пойдем другим путем и используем инструмент, который изначально есть на любом Win-сервере. Это PowerShell!

Оригинальный скрипт здесь.

# Строка подключения к базе
# Примеры:
#   - аутентификация средствами NTLM: "Server=<Имя сервера>;Database=<Имя базы>;Integrated Security=TRUE;"
#   - аутентификация средствами SQL Server: "Data Source=<Имя сервера>;user=<Имя пользователя>;password=<Пароль>;Initial Catalog=<Имя базы>"
$connectionString = "<Строка подключения>";
# Таблица с логами Extended Events
$tableWithLogName = "<Имя таблицы с логами>";
# Размер порции для обработки записей
$portion = 100;
# Таймаут подключения для команд
$sqlCmdTimeoutSeconds = 180;

try
{
    $sqlConnection = new-object system.data.SqlClient.SQLConnection($connectionString);
    $sqlConnection.Open();
    $sqlConnectionForUpdate = new-object system.data.SqlClient.SQLConnection($connectionString);
    $sqlConnectionForUpdate.Open();

    # Проверяем наличие колонок в логах
    $batch_text_exist = $false;
    $sql_text_exist = $false;
    $statement_exist = $false;
    $database_name_exist = $false;
    $sqlCmd = New-Object System.Data.SqlClient.SqlCommand
    $sqlCmd.Connection = $sqlConnection
    $sqlCmd.CommandTimeout = $sqlCmdTimeoutSeconds;
    $sqlCmd.CommandText = "
        SELECT 
	        cls.column_for_check AS [Name]
	        ,CASE WHEN cl_info.column_id IS NOT NULL THEN 1 ELSE 0 END AS [exist]
        FROM (
		        SELECT 'batch_text' column_for_check
		        UNION ALL
		        SELECT 'sql_text' column_for_check
		        UNION ALL
		        SELECT 'statement' column_for_check
		        UNION ALL
		        SELECT 'database_name' column_for_check
	        ) cls 
	        LEFT JOIN sys.columns cl_info
	        ON cls.column_for_check = cl_info.[name]
		        AND cl_info.[Object_ID] = Object_ID(N'dbo." + $tableWithLogName + "')";
    $reader = $sqlCmd.ExecuteReader()
    if($reader.HasRows -eq $true)
    {
        while ($reader.Read()) 
        {
            if($reader["Name"] -eq "batch_text")
            {
                if($reader["exist"] -eq 1)
                {
                    $batch_text_exist = $true;
                }
            } elseif($reader["Name"] -eq "sql_text")
            {
                if($reader["exist"] -eq 1)
                {
                    $sql_text_exist = $true;
                }
            } elseif($reader["Name"] -eq "statement")
            {
                if($reader["exist"] -eq 1)
                {
                    $statement_exist = $true;
                }
            } elseif($reader["Name"] -eq "database_name")
            {
                if($reader["exist"] -eq 1)
                {
                    $database_name_exist = $true;
                }
            }
        }
    }
    $reader.Close()  

    if($batch_text_exist -eq $false -and
        $sql_text_exist -eq $false -and
        $statement_exist -eq $false)
    {
        $sqlConnection.Close();
        $sqlConnectionForUpdate.Close();
        Write-Host "Таблица ""$tableWithLogName"" не содержит данных для обработки!";
        return;
    }

    $lastRowID = 0;
    $finish = $false;

    $fieldForJob = ($(if ($batch_text_exist) {"[batch_text],"} Else {""}) +  "
	              " + $(if ($sql_text_exist) {"[sql_text],"} Else {""}) +  "    
	              " + $(if ($statement_exist) {"[statement],"} Else {""})).Trim();
    $fieldForJob = $fieldForJob.Substring(0, $fieldForJob.Length - 1);

    $fieldsForUpdateLogRecord = ($(if ($batch_text_exist) {"     [batch_text] = @new_batch_text,"} Else {""}) +  "
	                " + $(if ($statement_exist) {"     [statement] = @new_statement,"} Else {""}) +  "    
	                " + $(if ($sql_text_exist) {"     [sql_text] = @new_sql_text,"} Else {""})).Trim();
    $fieldsForUpdateLogRecord = $fieldsForUpdateLogRecord.Substring(0, $fieldsForUpdateLogRecord.Length - 1);

    Do
    {    
        $sqlCmd = New-Object System.Data.SqlClient.SqlCommand
        $sqlCmd.Connection = $sqlConnection
        $sqlCmd.CommandTimeout = $sqlCmdTimeoutSeconds;
        $sqlCmd.CommandText = "
            SELECT TOP (" + $portion + ")
	              -- Ключевые поля
	              [ID]
                  " + $(if ($database_name_exist) {",[database_name]"} Else {""}) +  "	          
                  ,[timestamp (UTC)] AS [timestamp]
                  -- Поля для обработки
                  ," + $fieldForJob +  "       
              FROM [dbo].[" + $tableWithLogName + "]
              WHERE [ID] > @lastRowID
              ORDER BY
	              -- Сортировка по ключевым полям
	              [ID]
	              ,[timestamp (UTC)]";

        $paramLastRowId = $sqlCmd.Parameters.Add("@lastRowID", $lastRowID);
        $reader = $sqlCmd.ExecuteReader()
    
        if($reader.HasRows -eq $true)
        {
            while ($reader.Read()) 
            {
           
                $rowID = $reader["ID"];
                $DatabaseName =  $(if ($database_name_exist) { $reader["database_name"] } Else { "" });
                $timestamp = $reader["timestamp"];                       

                if($batch_text_exist -eq $true)
                {
                    $batch_text = $reader["batch_text"];
                    $batch_text = $batch_text -replace "#tt[\d]+", "ttN";
                    $batch_text = $batch_text -replace "@P[\d]+", "@PN";
                }

                if($sql_text_exist -eq $true)
                {
                    $sql_text = $reader["sql_text"];
                    $sql_text = $sql_text -replace "#tt[\d]+", "ttN";
                    $sql_text = $sql_text -replace "@P[\d]+", "@PN";
                }

                if($statement_exist -eq $true)
                {
                    $statement = $reader["statement"];
                    $statement = $statement -replace "#tt[\d]+", "ttN";
                    $statement = $statement -replace "@P[\d]+", "@PN";
                }

                # Обновляем данные в записи
                $sqlCmd_updateLogRecord = New-Object System.Data.SqlClient.SqlCommand
                $sqlCmd_updateLogRecord.Connection = $sqlConnectionForUpdate
                $sqlCmd_updateLogRecord.CommandTimeout = $sqlCmdTimeoutSeconds;
                $sqlCmd_updateLogRecord.CommandText = "
                    UPDATE [dbo].[" + $tableWithLogName + "] SET
                    " + $fieldsForUpdateLogRecord +  "       
                    WHERE [timestamp (UTC)] = @timestamp
                    " + $(if ($database_name_exist) {"AND [database_name] = @databaseName"} Else {""}) +  "	                
	                    AND [ID] = @RowID";
                $newParam = $sqlCmd_updateLogRecord.Parameters.Add("RowID", $rowID);
                if($database_name_exist)
                {
                    $newParam = $sqlCmd_updateLogRecord.Parameters.Add("databaseName", $DatabaseName);
                }
                $newParam = $sqlCmd_updateLogRecord.Parameters.Add("timestamp", $timestamp);
                if($batch_text_exist)
                {
                    $newParam = $sqlCmd_updateLogRecord.Parameters.Add("new_batch_text", $batch_text);
                }
                if($statement_exist)
                {
                    $newParam = $sqlCmd_updateLogRecord.Parameters.Add("new_statement", $statement);
                }
                if($sql_text_exist)
                {
                    $newParam = $sqlCmd_updateLogRecord.Parameters.Add("new_sql_text", $sql_text);
                }
                $resultExec = $sqlCmd_updateLogRecord.ExecuteNonQuery();

                $lastRowID = $rowID;          
            }
        } Else 
        {
            $finish = $true;
        } 
    
        $reader.Close();
        Write-Host "Последний обработанный идентификатор строки: " $rowID;

    } while($finish -ne $true)
}
catch 
{
    Write-Error $_.Exception.Message;
}
finally 
{
    $sqlConnection.Close();
    $sqlConnectionForUpdate.Close()
}

Можно этот скрипт значительно ускорить за счет операций BulkInsert, кэширования в памяти и других способов, но есть ли смысл?

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

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

SELECT TOP (10) 
	  DB_NAME([database_id]) AS [database_name]
	  ,[sql_text]
      ,SUM([cpu_time]) [cpu_time]
      ,SUM([duration]) [duration]
      ,SUM([physical_reads]) [physical_reads]
      ,SUM([logical_reads]) [logical_reads]
      ,SUM([writes]) [writes]
      ,SUM([row_count]) [row_count]
  FROM [dbo].[HeavyQueryByCPU]
  GROUP BY DB_NAME([database_id])
	  ,[sql_text]
  ORDER BY [cpu_time] DESC

В итоге, имеем 10 самых тяжелых запросов по использованию ресурсов CPU.

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

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

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

SELECT
		timeouts.[timestamp]
		,timeouts.[mode]
		,timeouts.[transaction_id]
		,timeouts.[database_id]
		,timeouts.[resource_0]
		,timeouts.[resource_1]
		,timeouts.[resource_2]
		-- Информация что было заблокировано
		,locks.sql_text
		,locks.[timestamp] AS [lock_timestamp]
		,locks.[transaction_id] AS [lock_transaction_id]
	FROM
	(SELECT 
		  [timestamp]
		  ,[mode]      
		  ,[transaction_id]
		  ,[database_id]  
		  -- Заблокированные ресурсы    
		  ,[resource_0]
		  ,[resource_1]
		  ,[resource_2]	  
	  FROM [dbo].[LockAnalyze]
	  WHERE [name] = 'lock_timeout') timeouts
		LEFT JOIN [dbo].[LockAnalyze] AS [locks]
		ON timeouts.[database_id] = locks.[database_id]
			AND timeouts.[resource_0] = locks.[resource_0]
			AND timeouts.[resource_1] = locks.[resource_1]
			AND timeouts.[resource_2] = locks.[resource_2]
			AND timeouts.[timestamp] > locks.[timestamp]
			AND locks.[name] = 'lock_acquired'

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

Конечно, такой анализ не даст точных результатов, а при большом объеме логов может показать множества лишней информации. В этом случае нужно будет усложнять запрос. Также может понадобиться добавить в сессию сбор событий Lock:Released.

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

Проанализируем самые частые ошибки на сервере СУБД и источники их возникновения.

SELECT TOP 10  
	  DB_NAME([database_id]) AS [database_name]
	  ,[client_hostname]
      ,[client_app_name]
      ,[message]
      ,[username]      
      ,[sql_text]
	  ,COUNT(*) AS [error_count]
  FROM [dbo].[Errors]
  GROUP BY 
	  DB_NAME([database_id])    
	  ,[client_hostname]
      ,[client_app_name]
      ,[message]
      ,[username]      
      ,[sql_text]
  ORDER BY [error_count] DESC

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

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

INSERT INTO #tt1 WITH(TABLOCK)
    (_Q_000_F_000, _Q_000_F_001, _Q_000_F_002, _Q_000_F_003)
SELECT
    T1.Q_001_F_000_,
    T1.Q_001_F_001_,
    0x01,
    @P1
FROM (
    SELECT
            1.0 AS Q_001_F_000_,
            @P2 AS Q_001_F_001_
    UNION ALL
        SELECT
            2.0,
            @P3
    UNION ALL
        SELECT
            3.0,
            @P4) T1

Как найти где именно он выполняется в конфигурации 1С? С помощью настройки ТЖ.

<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
    <dump create="false"/>
    <log location="<Путь к каталогу для сохранения логов>" history="48">
        <event>
            <eq property="name" value="dbmssql"/>
            <like property="Sql" value="%INSERT INTO%"/>
            <like property="Sql" value="%SELECT%"/>
            <like property="Sql" value="%0x01%"/>
            <like property="Sql" value="%FROM (%"/>
            <like property="Sql" value="%SELECT%"/>
            <like property="Sql" value="%1.0%"/>
            <like property="Sql" value="%UNION ALL%"/>
            <like property="Sql" value="%SELECT%"/>
            <like property="Sql" value="%2.0%"/>
            <like property="Sql" value="%UNION ALL%"/>
            <like property="Sql" value="%SELECT%"/>
            <like property="Sql" value="%3.0%"/>
        </event>
        <property name="all"/>
    </log>
</config>

В итоге, в одном из файлов логов мы получим модуль и строчку кода, откуда платформа генерирует этот запрос.

22:24.869011-1,DBMSSQL,6,process=rphost,p:processName=1C-Plus-MSOffice,OSThread=4760,t:clientID=12,t:applicationName=1CV8C,t:computerName=SRV-1C-MAIN,t:connectID=5,SessionID=2,Usr=DefUser,AppID=1CV8C,Trans=0,dbpid=59,Sql="INSERT INTO #tt1 WITH(TABLOCK) (_Q_000_F_000, _Q_000_F_001, _Q_000_F_002, _Q_000_F_003) SELECT
T1.Q_001_F_000_,
T1.Q_001_F_001_,
0x01,
?
FROM (SELECT
1.0 AS Q_001_F_000_,
? AS Q_001_F_001_
UNION ALL SELECT
2.0,
?
UNION ALL SELECT
3.0,
?) T1
p_0: 40181231000000
p_1: 'Тест 1'
p_2: 'Тест 2'
p_3: 'Тест 3'
",Rows=0,RowsAffected=3,Context='Форма.Вызов : Отчет.ВыгрузкаРезультатаКомпоновки.Форма.ФормаОтчета.Модуль.ВыгрузитьВAccessНаСервере
Отчет.ВыгрузкаРезультатаКомпоновки.Форма.ФормаОтчета.Форма : 43 : РаботаСAccessКлиентСервер.ПолучитьОграниченияВыгрузкиБазы(,2,)
	ОбщийМодуль.РаботаСAccessСервер.Модуль : 55 : Возврат ВыгрузитьИсточникВБазуДанных(
		ОбщийМодуль.РаботаСAccessСервер.Модуль : 123 : Стр = ПолучитьСледующуюЗапись(ИсточникДанных, НомерЗаписи);
			ОбщийМодуль.РаботаСAccessСервер.Модуль : 302 : СледующаяЗапись = ИсточникДанных.Следующий();'

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

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

<config xmlns="http://v8.1c.ru/v8/tech-log">
    <log location="<Путь к каталогу для сохранения логов>" history="168">
        <event>
            <eq property="Name" value="EXCP"/>
        </event>
        <event>
            <eq property="Name" value="EXCPCNTX"/>
        </event>
        <event>
            <eq property="Name" value="ADMIN"/>
        </event>
                <event>
            <eq property="Name" value="PROC"/>
        </event>
        <event>
            <eq property="Name" value="ATTN"/>
        </event>
        <event>
            <eq property="Name" value="QERR"/>
        </event>
        <event>
            <eq property="Name" value="SCOM"/>
        </event>
        <event>
            <eq property="Name" value="CONN"/>
        </event>
        <property name="all">
        </property>
    </log>
</config>

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