Monitoring SQL Server with Extended Events Instead of Profiler

2020-11-16 · mssql, extended events, monitoring, troubleshooting

I once watched a Profiler trace make a busy server visibly slower, and that was the last time I used it in production. Profiler has been deprecated since SQL Server 2012, it captures far more than you asked for, and Extended Events does the job better. Filtering happens before the event is collected, it sees things Profiler never could (waits, spills, page splits, deadlock graphs), and since SSMS 17.3 the XEvent Profiler node gives you the familiar live-trace feel.

I'll build the session I actually need most: slow statements with their text and plan handle, written to files, then read back. You need SQL Server 2012 or later (examples use 2016 to 2019 syntax, SSMS 18.x for GUI parts), ALTER ANY EVENT SESSION or sysadmin, and a folder the service account can write to, e.g. E:\XEvents\.

Check the built-in sessions first

Two sessions are already running on every instance. system_health records deadlocks, long waits, errors of severity 20 and above and a few other things, keeping the last four 5 MB files. Before you build anything, check whether the answer is already there:

SELECT CAST(target_data AS xml) AS ring_buffer
FROM sys.dm_xe_session_targets t
JOIN sys.dm_xe_sessions s ON s.address = t.event_session_address
WHERE s.name = 'system_health' AND t.target_name = 'ring_buffer';

For deadlocks specifically, the xml_deadlock_report events in system_health are usually enough, and it saves running a dedicated trace.

A session for slow queries

The GUI (Management → Extended Events → Sessions → New Session) generates the same T-SQL, but I keep the script in version control instead:

CREATE EVENT SESSION [SlowQueries] ON SERVER
ADD EVENT sqlserver.rpc_completed (
    ACTION (sqlserver.client_app_name, sqlserver.client_hostname, sqlserver.database_name,
            sqlserver.username, sqlserver.sql_text, sqlserver.plan_handle, sqlserver.session_id)
    WHERE duration > 2000000 AND sqlserver.is_system = 0),
ADD EVENT sqlserver.sql_batch_completed (
    ACTION (sqlserver.client_app_name, sqlserver.client_hostname, sqlserver.database_name,
            sqlserver.username, sqlserver.sql_text, sqlserver.plan_handle, sqlserver.session_id)
    WHERE duration > 2000000 AND sqlserver.is_system = 0)
ADD TARGET package0.event_file (
    SET filename = N'E:\XEvents\SlowQueries.xel', max_file_size = 100, max_rollover_files = 10)
WITH (MAX_MEMORY = 8192 KB, EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS,
      MAX_DISPATCH_LATENCY = 5 SECONDS, STARTUP_STATE = ON);

Details worth knowing:

duration is in microseconds for these events, so 2000000 means two seconds. This is the most common mistake when converting Profiler filters (which used milliseconds), and I've made it myself.
rpc_completed catches stored procedure calls from applications; sql_batch_completed catches ad hoc batches. You usually want both.
The WHERE predicate is evaluated before the event is fully collected, which is the reason for the low overhead. Filter as aggressively as you can.
STARTUP_STATE = ON makes the session start with the instance, unlike a Profiler trace.
sql_text gives you the whole batch. For the exact statement in a procedure, use sp_statement_completed instead, filtered the same way; it is noisier but more precise.

Start it:

ALTER EVENT SESSION [SlowQueries] ON SERVER STATE = START;

Watching live

Right-click the session in SSMS → Watch Live Data. The grid updates as events arrive, and you can add columns from the Actions by right-clicking a header. For a general "what is happening right now" view, the XEvent Profiler → Standard session under the Extended Events node launches a pre-built live session with one double-click and stops it when you close the window. This is what to reach for instead of Profiler.exe.

Reading the files with T-SQL

Live data is for now; the files are for "what happened at 03:12". sys.fn_xe_file_target_read_file returns one row per event with the XML payload, which you shred:

WITH raw AS (
    SELECT CAST(event_data AS xml) AS x
    FROM sys.fn_xe_file_target_read_file('E:\XEvents\SlowQueries*.xel', NULL, NULL, NULL)
)
SELECT
    x.value('(event/@name)[1]', 'varchar(50)') AS event_name,
    x.value('(event/@timestamp)[1]', 'datetime2(3)') AS event_time_utc,
    x.value('(event/data[@name="duration"]/value)[1]', 'bigint') / 1000 AS duration_ms,
    x.value('(event/data[@name="cpu_time"]/value)[1]', 'bigint') / 1000 AS cpu_ms,
    x.value('(event/data[@name="logical_reads"]/value)[1]', 'bigint') AS logical_reads,
    x.value('(event/data[@name="row_count"]/value)[1]', 'bigint') AS row_count,
    x.value('(event/action[@name="database_name"]/value)[1]', 'sysname') AS database_name,
    x.value('(event/action[@name="client_app_name"]/value)[1]', 'nvarchar(256)') AS app_name,
    x.value('(event/action[@name="username"]/value)[1]', 'sysname') AS username,
    x.value('(event/action[@name="sql_text"]/value)[1]', 'nvarchar(max)') AS sql_text
FROM raw
ORDER BY event_time_utc DESC;

Timestamps are UTC. Shredding XML over a few hundred megabytes of files is slow; when I need to analyse a long period I insert the result into a table once and query that.

Managing the session

ALTER EVENT SESSION [SlowQueries] ON SERVER STATE = STOP;
ALTER EVENT SESSION [SlowQueries] ON SERVER ADD EVENT sqlserver.sort_warning;   -- add spills later
DROP EVENT SESSION [SlowQueries] ON SERVER;

Check what is running and how much memory each session uses:

SELECT s.name, s.create_time, t.target_name, t.execution_count, t.bytes_written
FROM sys.dm_xe_sessions s JOIN sys.dm_xe_session_targets t ON t.event_session_address = s.address;

Trigger a slow one

Run a deliberately slow batch and confirm it shows up in the file:

WAITFOR DELAY '00:00:03'; SELECT COUNT(*) FROM dbo.Orders;

Within MAX_DISPATCH_LATENCY seconds, the file-reading query above should show a sql_batch_completed event with duration_ms around 3000 and your login name.

When it doesn't work

"Msg 25602: The target, "5B2DA06D-898A-43C8-9309-39BBBE93EBBD.package0.event_file", encountered a configuration error during initialization. Object cannot be added to event session. The operating system returned error 3: 'The system cannot find the path specified.'" The folder in filename does not exist or the service account cannot write to it.
"Msg 25623: The event name, "sqlserver.sql_statement_completed", is invalid, or the object could not be found": typo in the event or package name. List valid events with SELECT name FROM sys.dm_xe_objects WHERE object_type = 'event' AND name LIKE '%completed%'.
The session captures nothing although queries are clearly slow. Check the units: a duration > 2000 filter means two milliseconds and would capture almost everything, duration > 2000000000 would capture nothing. Also confirm sqlserver.is_system = 0 is not filtering out the login you test with.
Reading the files returns "Msg 25718: The log file name "E:\XEvents\SlowQueries*.xel" is invalid. Verify that the file exists and the SQL Server service account has access to it." The wildcard pattern must match the actual file names, which have a numeric suffix appended (SlowQueries_0_132498....xel); SlowQueries*.xel covers it. Also check the account permission.

I leave one file-backed session running on every server now. Profiler stays closed.