Investigating a Past Slowdown With the system_health Session

A past slowdown is not always lost. Even with no trace running, the system_health session has been quietly writing events to files. Read them before the files roll over and the evidence is gone.

What system_health already recorded

It is Monday, 9 AM. Someone says the application crawled on Saturday afternoon. You never started a trace. Is that the end of the story?

Not quite. SQL Server runs an Extended Events session called system_health from the moment it starts. Nobody has to turn it on. It keeps a short list of serious events, such as long waits, deadlocks and severe errors. First, ask the server what that list contains.

SELECT e.name AS EventName
FROM sys.server_event_sessions AS s
JOIN sys.server_event_session_events AS e ON e.event_session_id = s.event_session_id
WHERE s.name = N'system_health'
ORDER BY e.name;

On my test server the list has 21 events. It includes wait_info, xml_deadlock_report, error_reported and sp_server_diagnostics_component_result. Notice what is missing: ordinary slow queries. This session catches big trouble, not every sluggish moment.

Find the files and set your window

The events live in .xel files in the SQL Server log folder. Do not guess the folder. Ask the running session where its current file is, then turn that into a wildcard that matches all the rolled-over files.

Now the time trap. Extended Events stores times in UTC, but people report problems in local time. Write the complaint window in local time and convert it once. The window below is the last 14 days, wider than the files, so nothing gets cut off. Replace it with the real complaint times. The conversion uses today’s offset, so near a clock change, adjust by an hour.

DROP TABLE IF EXISTS #Source;

DECLARE @Path nvarchar(4000);
SELECT @Path = CAST(t.target_data AS xml).value('(EventFileTarget/File/@name)[1]', 'nvarchar(4000)')
FROM sys.dm_xe_sessions AS s
JOIN sys.dm_xe_session_targets AS t ON t.event_session_address = s.address
WHERE s.name = N'system_health' AND t.target_name = N'event_file';

DECLARE @FromLocal datetime2 = DATEADD(DAY, -14, SYSDATETIME());
DECLARE @ToLocal datetime2 = SYSDATETIME();
DECLARE @Offset int = DATEDIFF(MINUTE, SYSUTCDATETIME(), SYSDATETIME());

SELECT LEFT(@Path, LEN(@Path) - CHARINDEX(N'\', REVERSE(@Path)) + 1) + N'system_health*.xel' AS Pattern,
       DATEADD(MINUTE, -@Offset, @FromLocal) AS FromUtc,
       DATEADD(MINUTE, -@Offset, @ToLocal) AS ToUtc,
       @Offset AS OffsetMinutes
INTO #Source;

SELECT FromUtc, ToUtc, OffsetMinutes FROM #Source;

Check how far back the files go

Before you hunt, find out how much history exists. The files rotate, and old ones are deleted. A busy server may keep only a few hours.

On my test server the session kept 10 files. The oldest event was about eight days old. If your complaint is older than your oldest event, stop here. Nothing in these files can tell you about it. The files cannot prove the server was healthy either.

DECLARE @Pattern nvarchar(4000) = (SELECT Pattern FROM #Source);

SELECT COUNT(DISTINCT file_name) AS files_read,
       COUNT(*) AS events_read,
       MIN(timestamp_utc) AS oldest_utc,
       MAX(timestamp_utc) AS newest_utc
FROM sys.fn_xe_file_target_read_file(@Pattern, NULL, NULL, NULL);

Look for long waits

The wait_info event records waits that lasted a long time. It is the best first clue for a slowdown. The query filters on the timestamp_utc column first and only then opens the XML. That is much cheaper than parsing every event.

On my test server the long waits were all LCK_M_X, which means sessions waiting for an exclusive lock. Four lasted about a minute and one about 30 seconds. That is the shape of a blocking problem. The session_id column tells you who was waiting.

DECLARE @Pattern nvarchar(4000), @FromUtc datetime2, @ToUtc datetime2;
SELECT @Pattern = Pattern, @FromUtc = FromUtc, @ToUtc = ToUtc FROM #Source;

SELECT TOP (5) timestamp_utc,
       CAST(event_data AS xml).value('(event/data[@name="wait_type"]/text)[1]', 'nvarchar(60)') AS wait_type,
       CAST(event_data AS xml).value('(event/data[@name="duration"]/value)[1]', 'bigint') AS duration_ms,
       CAST(event_data AS xml).value('(event/action[@name="session_id"]/value)[1]', 'int') AS session_id
FROM sys.fn_xe_file_target_read_file(@Pattern, NULL, NULL, NULL)
WHERE object_name = N'wait_info'
  AND timestamp_utc >= @FromUtc AND timestamp_utc < @ToUtc
ORDER BY timestamp_utc DESC, file_offset DESC;

Check deadlocks and server health

Deadlocks are recorded as xml_deadlock_report. Each row below carries the full deadlock graph. In SSMS, click the XML, save it with an .xdl extension, and open it to see the picture.

The second query counts the health readings that sp_server_diagnostics reports for each component, regularly. CLEAN is normal. WARNING means that component looked unhappy at that moment. Take the time of a warning and look for waits near it.

DECLARE @Pattern nvarchar(4000), @FromUtc datetime2, @ToUtc datetime2;
SELECT @Pattern = Pattern, @FromUtc = FromUtc, @ToUtc = ToUtc FROM #Source;

SELECT TOP (5) timestamp_utc,
       CAST(event_data AS xml).value('(event/data[@name="xml_report"]/value/deadlock/victim-list/victimProcess/@id)[1]', 'nvarchar(100)') AS victim_process,
       CAST(event_data AS xml).query('(event/data[@name="xml_report"]/value/deadlock)[1]') AS deadlock_graph
FROM sys.fn_xe_file_target_read_file(@Pattern, NULL, NULL, NULL)
WHERE object_name = N'xml_deadlock_report'
  AND timestamp_utc >= @FromUtc AND timestamp_utc < @ToUtc
ORDER BY timestamp_utc DESC, file_offset DESC;

WITH Readings AS
(
    SELECT CAST(event_data AS xml).value('(event/data[@name="component"]/text)[1]', 'nvarchar(50)') AS component,
           CAST(event_data AS xml).value('(event/data[@name="state"]/text)[1]', 'nvarchar(50)') AS state
    FROM sys.fn_xe_file_target_read_file(@Pattern, NULL, NULL, NULL)
    WHERE object_name = N'sp_server_diagnostics_component_result'
      AND timestamp_utc >= @FromUtc AND timestamp_utc < @ToUtc
)
SELECT component, state, COUNT(*) AS readings
FROM Readings
GROUP BY component, state
ORDER BY component, state;

Save the evidence before it rolls over

Once you find something useful, copy it out. Rollover does not wait for your investigation. The block below saves the interesting events from your window into a small table, together with the full XML. Also copy the .xel files themselves somewhere safe.

The demo creates one table, dbo.SlowdownEvidence, and a temp table. The last block removes both.

DECLARE @Pattern nvarchar(4000), @FromUtc datetime2, @ToUtc datetime2;
SELECT @Pattern = Pattern, @FromUtc = FromUtc, @ToUtc = ToUtc FROM #Source;

DROP TABLE IF EXISTS dbo.SlowdownEvidence;

SELECT object_name, timestamp_utc, CAST(event_data AS xml) AS event_xml
INTO dbo.SlowdownEvidence
FROM sys.fn_xe_file_target_read_file(@Pattern, NULL, NULL, NULL)
WHERE object_name IN (N'wait_info', N'xml_deadlock_report', N'error_reported', N'sql_exit_invoked')
  AND timestamp_utc >= @FromUtc AND timestamp_utc < @ToUtc;

SELECT object_name, COUNT(*) AS saved_events
FROM dbo.SlowdownEvidence
GROUP BY object_name
ORDER BY object_name;

One honest warning. No events in your window does not mean nothing happened. It may mean the problem was too small for system_health to notice. Then you know what to capture next time, with a session of your own.

DROP TABLE IF EXISTS dbo.SlowdownEvidence;
DROP TABLE IF EXISTS #Source;

Next time somebody says it was slow last night, check the files before the files check out.

The system_health session is not a complete history, it is evidence that survived the rollover.

Published by Pinal Dave on SQLAuthority. More of my work at pinaldave.com.