Статистика ожиданий для одной операции

Автор: Paul Randal, Capturing wait stats for a single operation

Эта статья о настройке производительности, которая давно была в моём списке задач. Анализ статистики ожиданий — отличный способ изучить симптомы проблем с производительностью (см. мой каталог Wait Stats для получения дополнительной информации), но использование DMV sys.dm_os_wait_stats показывает всё, что происходит на сервере. Если вы хотите увидеть, какие ожидания возникают из-за одного запроса или операции в рабочей системе (например, влияние подсказок MAXDOP на количество и продолжительность ожиданий CXPACKET для запроса), то использование DMV обычно нецелесообразно — вам пришлось бы очистить статистику ожиданий и убедиться, что в системе не выполняется ничего, кроме исследуемого запроса/операции. Наиболее правильный способ сделать это — использовать расширенные события (Extended Events).

Всякий раз, когда состояние потока меняется на SUSPENDED из-за ожидания, событие wait_info из пакета sqlos срабатывает, отмечая начало ожидания. Когда поток снова получает процессор, событие wait_info срабатывает снова, фиксируя общее время ожидания и время ожидания сигнала (время, проведённое в очереди RUNNABLE). Как и в случае с DMV, нам нужно вычислить время ожидания ресурса (время, проведённое в состоянии SUSPENDED) самостоятельно.

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

-- Удалить сеанс, если он существует.
IF EXISTS (SELECT * FROM sys.server_event_sessions WHERE name = 'MonitorWaits')
    DROP EVENT SESSION MonitorWaits ON SERVER
GO

CREATE EVENT SESSION MonitorWaits ON SERVER
ADD EVENT sqlos.wait_info
    (WHERE sqlserver.session_id = 53 /* session_id подключаемого сеанса мониторинга */)
ADD TARGET package0.asynchronous_file_target
    (SET FILENAME = N'C:\SQLskills\EE_WaitStats.xel',
    METADATAFILE = N'C:\SQLskills\EE_WaitStats.xem')
WITH (max_dispatch_latency = 1 seconds);
GO

Вам нужно будет указать идентификатор сеанса SQL Server, в котором вы будете выполнять исследуемую операцию. Я создал тестовую рабочую базу данных с таблицей и данными, чтобы можно было отслеживать ожидания при перестроении её кластерного индекса.

Вы также можете отфильтровать любые типы ожиданий, которые вас не интересуют, добавив ещё один предикат к сеансу, фильтрующий по sqlos.wait_type. Вам нужно будет указать числа, а список соответствия между числами и понятными человеку типами ожиданий можно получить с помощью этого кода:

SELECT xmv.map_key, xmv.map_value
FROM sys.dm_xe_map_values xmv
JOIN sys.dm_xe_packages xp
    ON xmv.object_package_guid = xp.guid
WHERE xmv.name = 'wait_types'
    AND xp.name = 'sqlos';
GO

Теперь я включаю сеанс и выполняю перестроение.

-- Запуск сеанса
ALTER EVENT SESSION MonitorWaits ON SERVER STATE = START;
GO

-- Выполнить запрос

-- Остановка сеанса событий
ALTER EVENT SESSION MonitorWaits ON SERVER STATE = STOP;
GO

Затем я могу посмотреть, сколько событий было зафиксировано:

SELECT COUNT (*)
FROM sys.fn_xe_file_target_read_file
    ('C:\SQLskills\EE_WaitStats*.xel',
    'C:\SQLskills\EE_WaitStats*.xem', null, null);
GO

13324

А затем извлечь их во временную таблицу и агрегировать (существуют различные способы, я предпочитаю этот):

-- Создать промежуточную временную таблицу для необработанных данных событий
CREATE TABLE #RawEventData (
    Rowid  INT IDENTITY PRIMARY KEY,
    event_data XML);
 
GO

-- Считать данные из файла в промежуточную временную таблицу
INSERT INTO #RawEventData (event_data)
SELECT
    CAST (event_data AS XML) AS event_data
FROM sys.fn_xe_file_target_read_file (
    'C:\SQLskills\EE_WaitStats*.xel',
    'C:\SQLskills\EE_WaitStats*.xem', null, null);
GO

SELECT
    waits.[Wait Type],
    COUNT (*) AS [Wait Count],
    SUM (waits.[Duration]) AS [Total Wait Time (ms)],
    SUM (waits.[Duration]) - SUM (waits.[Signal Duration]) AS [Total Resource Wait Time (ms)],
    SUM (waits.[Signal Duration]) AS [Total Signal Wait Time (ms)]
FROM
    (SELECT
        event_data.value ('(/event/@timestamp)[1]', 'DATETIME') AS [Time],
        event_data.value ('(/event/data[@name=''wait_type'']/text)[1]', 'VARCHAR(100)') AS [Wait Type],
        event_data.value ('(/event/data[@name=''opcode'']/text)[1]', 'VARCHAR(100)') AS [Op],
        event_data.value ('(/event/data[@name=''duration'']/value)[1]', 'BIGINT') AS [Duration],
        event_data.value ('(/event/data[@name=''signal_duration'']/value)[1]', 'BIGINT') AS [Signal Duration]
     FROM #RawEventData
    ) AS waits
WHERE waits.[op] = 'End'
GROUP BY waits.[Wait Type]
ORDER BY [Total Wait Time (ms)] DESC;
GO

-- Очистка
DROP TABLE #RawEventData;
GO

Wait Type             Wait Count  Total Wait Time (ms) Total Resource Wait Time (ms) Total Signal Wait Time (ms)
------------------- ----------- -------------------- ----------------------------- ---------------------------
LATCH_EX              4919        15783                15693                         90
LATCH_SH              18          4399                 4398                          1
CXPACKET              16          3039                 3038                          1
PAGEIOLATCH_SH        813         468                  457                           11
PAGELATCH_SH          246         113                  109                           4
WRITELOG              99          71                   66                            5
PAGELATCH_UP          203         65                   63                            2
LOGBUFFER             123         58                   57                            1
WRITE_COMPLETION      82          55                   55                            0
PAGEIOLATCH_UP        35          27                   27                            0
IO_COMPLETION         80          25                   25                            0
SQLTRACE_LOCK         1           6                    6                             0
PAGEIOLATCH_EX        4           3                    3                             0
CMEMTHREAD            17          1                    0                             1
SOS_SCHEDULER_YIELD   6           0                    0                             0

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

Если вы заинтересованы в более глубоком изучении расширенных событий, ознакомьтесь с отличной серией статей Джонатана (Jonathan's excellent series).