5 Extended Events Sessions Your SQL Server Instance Cannot Live Without

SQL Server Extend Events is a general event-handling system. It correlates data from SQL Server and, to a limited degree, the operating system. Extended Events are an optimized replacement for SQL Trace. In most cases, Extended Events are much lighter weight and they are always the preferred method for trace events. In addition, there are thousands more Extended Events than SQL Trace events. The list of Extended Events is growing with every major version of SQL Server.

Proactive placement

Extended Events are the all-around smart choice. They take a little bit of time to get used to, however. With thousands of new events and data points, it can be difficult to create an event session in a pinch. That is why it is important to have event sessions pre-scripted or pre-implemented on your SQL Server instances. A little bit of up-front work can save you a lot of time when you need information on the spot. Having them pre-scripted also prevents you from jumping back to Profiler, which has a much heavier footprint on your server.

When I create Extended Event sessions, I tend to use the SQL Server Management Studio wizard to find the events and actions (additional fields) that I want. Then, I will script it out and save it for later.

Below are five Extended Events sessions that I have found particularly useful and recommend you add to your toolbox.

Most of these extended event sessions are configured with the ring buffer target because the intention of these sessions is for ad hoc performance analysis. Each could easily be converted to an event file target for historical tracking, alerting, or trend analysis. Read here for more information on targets.

1. Long running queries

Session

This event session tracks long running ad hoc queries and stored procedures. It returns useful fields for identifying what executed the query, such as, the client_app_name and client_hostname. This session uses the ring buffer which is an in-memory target designed for short-term use.

CREATE EVENT SESSION [LongRunningQueries] ON SERVER
ADD EVENT sqlserver.sp_statement_completed
(
ACTION
(
package0.collect_system_time
,sqlserver.client_app_name
,sqlserver.client_hostname
,sqlserver.database_name
,sqlserver.plan_handle
,sqlserver.query_hash
,sqlserver.session_id
)
WHERE duration > 5000000 -- longer than 5 seconds
),
ADD EVENT sqlserver.sql_statement_completed
(
ACTION
(
package0.collect_system_time
,sqlserver.client_app_name
,sqlserver.client_hostname
,sqlserver.database_name
,sqlserver.plan_handle
,sqlserver.query_hash
,sqlserver.session_id
)
WHERE duration > 5000000 -- longer than 5 seconds
)
ADD TARGET package0.ring_buffer(SET max_events_limit=(0 /*unlimited*/),max_memory=(1048576 /*1 GB*/))
WITH (STARTUP_STATE=OFF,MAX_DISPATCH_LATENCY = 5SECONDS)

Query

Querying the extended events data requires a little bit of work with XML. Jes Borland describes it well, here. Below is the query written for this session specifically. Commented out, near the bottom, I included a couple of useful filters and sort orders.

--/* Comment this part out after you run it once, unless you want to refresh the temp table.

IF OBJECT_ID('tempdb..#capture_waits_data') IS NOT NULL
DROP TABLE #capture_waits_data

SELECT CAST(target_data as xml) AS targetdata
INTO #capture_waits_data
FROM sys.dm_xe_session_targets xet
JOIN sys.dm_xe_sessions xes
ON xes.address = xet.event_session_address
WHERE xes.name = 'LongRunningQueries'
AND xet.target_name = 'ring_buffer';

--*/

/**********************************************************/

SELECT xed.event_data.value('(@timestamp)[1]', 'datetime2') AS datetime_utc,
CONVERT(datetime2,SWITCHOFFSET(CONVERT(datetimeoffset,xed.event_data.value('(@timestamp)[1]', 'datetime2')),DATENAME(TzOffset, SYSDATETIMEOFFSET()))) AS datetime_local,
xed.event_data.value('(@name)[1]', 'varchar(50)') AS event_type,
xed.event_data.value('(data[@name="statement"]/value)[1]', 'varchar(max)') AS statement,
xed.event_data.value('(data[@name="duration"]/value)[1]', 'bigint')/1000 AS duration_ms,
xed.event_data.value('(data[@name="cpu_time"]/value)[1]', 'bigint')/1000 AS cpu_time_ms,
xed.event_data.value('(data[@name="physical_reads"]/value)[1]', 'bigint') AS physical_reads,
xed.event_data.value('(data[@name="logical_reads"]/value)[1]', 'bigint') AS logical_reads,
xed.event_data.value('(data[@name="writes"]/value)[1]', 'bigint') AS writes,
xed.event_data.value('(data[@name="row_count"]/value)[1]', 'bigint') AS row_count,
xed.event_data.value('(action[@name="database_name"]/value)[1]', 'varchar(255)') AS database_name,
xed.event_data.value('(action[@name="client_hostname"]/value)[1]', 'varchar(255)') AS client_hostname,
xed.event_data.value('(action[@name="client_app_name"]/value)[1]', 'varchar(255)') AS client_app_name
FROM #capture_waits_data
CROSS APPLY targetdata.nodes('//RingBufferTarget/event') AS xed (event_data)
WHERE 1=1
/* refine your search further than the XE session's filter
AND xed.event_data.value('(data[@name="statement"]/value)[1]', 'varchar(max)') = 'EXEC spDemoSproc'
--*/
/* find queries within a time range
AND xed.event_data.value('(@timestamp)[1]', 'datetime2') > CAST('20170925 09:57 AM' AS datetime2) AT TIME ZONE 'Eastern Standard Time'
--*/
/* Find highest resource consumption
ORDER BY
xed.event_data.value('(data[@name="duration"]/value)[1]', 'bigint') DESC
--xed.event_data.value('(data[@name="cpu_time"]/value)[1]', 'bigint') DESC
--xed.event_data.value('(data[@name="physical_reads"]/value)[1]', 'bigint') DESC
--xed.event_data.value('(data[@name="logical_reads"]/value)[1]', 'bigint') DESC
--xed.event_data.value('(data[@name="writes"]/value)[1]', 'bigint') DESC
--xed.event_data.value('(data[@name="row_count"]/value)[1]', 'bigint') DESC
--*/

2. Query timeouts

Session

This next query is designed to track connections which are interrupted or aborted, often caused by execution timeouts. Unlike the last session, this one uses the pair matching target. The pair matching target is also an in-memory target but correlates matched pairs and reports on unmatched events. This works by detecting a sqlserver.sql_statement_started event without a matching sqlserver.sql_statement_completed event.

CREATE EVENT SESSION [QueryTimeouts] ON SERVER
ADD EVENT sqlserver.sql_statement_completed
(
ACTION
(
sqlserver.session_id
,sqlserver.query_hash
,sqlserver.tsql_stack
)
),
ADD EVENT sqlserver.sql_statement_starting
(
ACTION
(
sqlserver.session_id
,sqlserver.query_hash
,sqlserver.tsql_stack
)
)
ADD TARGET package0.pair_matching
(
SET
begin_event = 'sqlserver.sql_statement_starting',
begin_matching_actions = 'sqlserver.session_id, sqlserver.tsql_stack',
end_event = 'sqlserver.sql_statement_completed',
end_matching_actions = 'sqlserver.session_id, sqlserver.tsql_stack',
respond_to_memory_pressure = 0
)
WITH (MAX_DISPATCH_LATENCY=5 SECONDS, TRACK_CAUSALITY=ON, STARTUP_STATE=OFF)

Query

The below query aggregates the matched count which were successfully completed queries, the unmatched counts which represent the timeouts, and then it will display the detailed information for the queries that timed out.

-- Create XML variable to hold Target Data
DECLARE @target_data XML
SELECT @target_data =
CAST(target_data AS XML)
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 = 'QueryTimeouts'
AND t.target_name = 'pair_matching'

-- Query XML variable to get Target Execution information
SELECT
@target_data.value('(PairingTarget/@orphanCount)[1]', 'int') AS orphanCount,
@target_data.value('(PairingTarget/@matchedCount)[1]', 'int') AS matchedCount,
COALESCE(@target_data.value('(PairingTarget/@memoryPressureDroppedCount)[1]', 'int'),0) AS memoryPressureDroppedCount

-- Query the XML variable to get the Target Data
SELECT
n.value('(event/action[@name="session_id"]/value)[1]', 'int') as session_id,
n.value('(event/@name)[1]', 'varchar(50)') AS event_name,
n.value('(event/data[@name="statement"]/value)[1]', 'varchar(8000)') as statement,
NULLIF(n.value('(event/action[@name="query_hash"]/value)[1]', 'numeric(20)'),0) as query_hash_numeric,
n.value('(event/@timestamp)[1]', 'datetime2') AS datetime_utc,
DATEADD(hh,DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP),n.value('(event/@timestamp)[1]', 'datetime2')) AS datetime_local,
n.value('(event/action[@name="tsql_stack"]/text)[1]', 'varchar(max)') as tsql_stack
FROM
(
SELECT td.query('.') as n
FROM @target_data.nodes('PairingTarget/event') AS q(td)
) as tab
--Excluding this currently running query.
WHERE n.value('(event/action[@name="session_id"]/value)[1]', 'int') <> @@SPID
ORDER BY session_id

3. One bad query

Session

This session is used to track a specific query or stored procedure. It is great for capturing actual runtime data about a query that you know is a problem. It implements a wild card search on the sql_text by populating the @TextSearch variable with a snippet from your query.

DECLARE @TextSearch NVARCHAR(3998) = N'query text to search'

EXEC(N'
CREATE EVENT SESSION [Query_' + @TextSearch + '] ON SERVER
ADD EVENT sqlserver.sp_statement_completed
(
ACTION
(
package0.collect_system_time,
sqlserver.client_app_name,
sqlserver.client_hostname,
sqlserver.database_name
)
WHERE ([sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N''%' + @TextSearch + '%''))
),
ADD EVENT sqlserver.sql_statement_completed
(
ACTION
(
package0.collect_system_time,
sqlserver.client_app_name,
sqlserver.client_hostname,
sqlserver.database_name
)
WHERE ([sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N''%' + @TextSearch + '%''))
)
ADD TARGET package0.ring_buffer(SET max_events_limit=(0 /*unlimited*/),max_memory=(1048576 /*1 GB*/))
WITH (STARTUP_STATE=OFF,MAX_DISPATCH_LATENCY = 5SECONDS)
')

Query

--/* Comment this part out after you run it once, unless you want to refresh the temp table.

DECLARE @SessionName NVARCHAR(4000) = 'Query_demo'

IF OBJECT_ID('tempdb..#capture_waits_data') IS NOT NULL
DROP TABLE #capture_waits_data

SELECT CAST(target_data as xml) AS targetdata
INTO #capture_waits_data
FROM sys.dm_xe_session_targets xet
JOIN sys.dm_xe_sessions xes
ON xes.address = xet.event_session_address
WHERE xes.name = @SessionName
AND xet.target_name = 'ring_buffer';

--*/

/**********************************************************/

SELECT xed.event_data.value('(@timestamp)[1]', 'datetime2') AS datetime_utc,
DATEADD(hh,DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP),xed.event_data.value('(@timestamp)[1]', 'datetime2')) AS datetime_local,
xed.event_data.value('(@name)[1]', 'varchar(50)') AS event_type,
xed.event_data.value('(data[@name="statement"]/value)[1]', 'varchar(max)') AS statement,
xed.event_data.value('(data[@name="duration"]/value)[1]', 'bigint')/1000 AS duration_ms,
xed.event_data.value('(data[@name="cpu_time"]/value)[1]', 'bigint')/1000 AS cpu_time_ms,
xed.event_data.value('(data[@name="physical_reads"]/value)[1]', 'bigint') AS physical_reads,
xed.event_data.value('(data[@name="logical_reads"]/value)[1]', 'bigint') AS logical_reads,
xed.event_data.value('(data[@name="writes"]/value)[1]', 'bigint') AS writes,
xed.event_data.value('(data[@name="row_count"]/value)[1]', 'bigint') AS row_count,
xed.event_data.value('(action[@name="database_name"]/value)[1]', 'varchar(255)') AS database_name,
xed.event_data.value('(action[@name="client_hostname"]/value)[1]', 'varchar(255)') AS client_hostname,
xed.event_data.value('(action[@name="client_app_name"]/value)[1]', 'varchar(255)') AS client_app_name
FROM #capture_waits_data
CROSS APPLY targetdata.nodes('//RingBufferTarget/event') AS xed (event_data)
WHERE 1=1
/* refine your search further than the XE session's filter
AND xed.event_data.value('(data[@name="statement"]/value)[1]', 'varchar(max)') = 'EXEC spDemoSproc'
--*/
/* find queries within a time range
AND xed.event_data.value('(@timestamp)[1]', 'datetime2') > CAST('20170925 09:57 AM' AS datetime2) AT TIME ZONE 'Eastern Standard Time'
--*/
/* Find highest resource consumption
ORDER BY
xed.event_data.value('(data[@name="duration"]/value)[1]', 'bigint') DESC
--xed.event_data.value('(data[@name="cpu_time"]/value)[1]', 'bigint') DESC
--xed.event_data.value('(data[@name="physical_reads"]/value)[1]', 'bigint') DESC
--xed.event_data.value('(data[@name="logical_reads"]/value)[1]', 'bigint') DESC
--xed.event_data.value('(data[@name="writes"]/value)[1]', 'bigint') DESC
--xed.event_data.value('(data[@name="row_count"]/value)[1]', 'bigint') DESC
--*/

4. Why are there excessive recompilations?

Session

This session is useful for detecting excessive recompilations which cause queries to slow and CPU usage to spike. It uses the histogram target to capture the reasons for recompiles and how many of each reason occurred.

CREATE EVENT SESSION RecompileReasons ON SERVER
ADD EVENT sqlserver.sql_statement_recompile
ADD TARGET package0.histogram
(
SET filtering_event_name=N'sqlserver.sql_statement_recompile',
source=N'recompile_cause',
source_type=(0)
)
WITH (STARTUP_STATE=OFF, MAX_DISPATCH_LATENCY = 5SECONDS)

Query

SELECT sv.subclass_name as recompile_cause,
shredded.recompile_count
FROM sys.dm_xe_session_targets AS xet
JOIN sys.dm_xe_sessions AS xes ON (xe.address = xet.event_session_address)
CROSS APPLY ( SELECT CAST(xet.target_data as xml) ) as target_data_xml ([xml])
CROSS APPLY target_data_xml.[xml].nodes('/HistogramTarget/Slot') AS nodes (slot_data)
CROSS APPLY
(
SELECT nodes.slot_data.value('(value)[1]', 'int') AS recompile_cause,
nodes.slot_data.value('(@count)[1]', 'int') AS recompile_count
) as shredded
JOIN sys.trace_subclass_values AS sv ON shredded.recompile_cause = sv.subclass_value
WHERE xes.name = 'RecompileReasons'
AND sv.trace_event_id = 37 -- SP:Recompile

5. Memory grants

Session

This session captures queries where the memory grant is larger than the filter predicate, 2 MB in this example. It will output the granted memory, the actual used memory, degree of parallelism, and a few other useful data points.

CREATE EVENT SESSION [MemoryUsage] ON SERVER
ADD EVENT sqlserver.query_memory_grant_usage
(
ACTION
(
sqlserver.query_hash
,sqlserver.query_plan_hash
,sqlserver.sql_text
)
WHERE granted_memory_kb > 2048 --2 MB
)
ADD TARGET package0.ring_buffer(SET max_events_limit=(0 /*unlimited*/),max_memory=(1048576 /*1 GB*/))
WITH (STARTUP_STATE=OFF,MAX_DISPATCH_LATENCY = 5SECONDS)

Query

--/* Comment this part out after you run it once, unless you want to refresh the temp table.

IF OBJECT_ID('tempdb..#capture_waits_data') IS NOT NULL
DROP TABLE #capture_waits_data

SELECT CAST(target_data as xml) AS targetdata
INTO #capture_waits_data
FROM sys.dm_xe_session_targets xet
JOIN sys.dm_xe_sessions xes
ON xes.address = xet.event_session_address
WHERE xes.name = 'MemoryUsage'
AND xet.target_name = 'ring_buffer';

--*/

/**********************************************************/

SELECT xed.event_data.value('(@timestamp)[1]', 'datetime2') AS datetime_utc,
DATEADD(hh,DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP),xed.event_data.value('(@timestamp)[1]', 'datetime2')) AS datetime_local,
xed.event_data.value('(@name)[1]', 'varchar(50)') AS event_type,
xed.event_data.value('(data[@name="ideal_memory_kb"]/value)[1]', 'bigint') AS ideal_memory_kb,
xed.event_data.value('(data[@name="granted_memory_kb"]/value)[1]', 'bigint') AS granted_memory_kb,
xed.event_data.value('(data[@name="used_memory_kb"]/value)[1]', 'bigint') AS used_memory_kb,
xed.event_data.value('(data[@name="usage_percent"]/value)[1]', 'int') AS usage_percent,
xed.event_data.value('(data[@name="dop"]/value)[1]', 'int') AS dop,
xed.event_data.value('(data[@name="granted_percent"]/value)[1]', 'int') AS granted_percent,
xed.event_data.value('(action[@name="sql_text"]/value)[1]', 'varchar(max)') AS sql_text,
xed.event_data.value('(action[@name="query_plan_hash"]/value)[1]', 'numeric(20)') AS query_plan_hash,
xed.event_data.value('(action[@name="query_hash"]/value)[1]', 'numeric(20)') AS query_hash
FROM #capture_waits_data
CROSS APPLY targetdata.nodes('//RingBufferTarget/event') AS xed (event_data)
WHERE 1=1
--/* Search for large memory grants.
AND xed.event_data.value('(data[@name="used_memory_kb"]/value)[1]', 'bigint') > 5120 -- 5MB
--*/
--/* Search for grants too large for the actual used
AND xed.event_data.value('(data[@name="usage_percent"]/value)[1]', 'bigint') < 50
--*/

Scripts

Click here to download the full set of scripts.

Leave a Reply