When working with SQL Trace, one of my biggest frustrations has been the limitations that exist in filtering. Using sp_trace_setfilter to establish the filter criteria is a non-trivial task, and it falls short of being able to deliver complex filtering that is sometimes needed to simplify analysis. Filtering of trace data was performed globally and applied to the trace affecting all of the events being collected. Extended Events introduces a much better system of filtering using Predicates that are applied at the individual Event level, allow for short circuiting of evaluation, and provide the ability to create complex groups of independent criteria, ensuring only Events of interest are captured by the Event Session.
In yesterdays post, The system_health Session, I talked about the default system_health session that is running on every SQL Server 2008/2008R2 and Denali CTP1 instance out of the box. The Predicate definition for the sqlos.wait_info event in the system_health session is a good example to follow for complex, short-circuiting Predicate definition in Extended Events.
ADD EVENT sqlos.wait_info ( ACTION (package0.callstack, sqlserver.session_id, sqlserver.sql_text) WHERE (duration > 15000 AND ( (wait_type > 31 -- Waits for latches and important wait resources (not locks) -- that have exceeded 15 seconds. AND ( (wait_type > 47 AND wait_type < 54) OR wait_type < 38 OR (wait_type > 63 AND wait_type < 70) OR (wait_type > 96 AND wait_type < 100) OR (wait_type = 107) OR (wait_type = 113) OR (wait_type > 174 AND wait_type < 179) OR (wait_type = 186) OR (wait_type = 207) OR (wait_type = 269) OR (wait_type = 283) OR (wait_type = 284) ) ) OR (duration > 30000 -- Waits for locks that have exceeded 30 secs. AND wait_type < 22 ) ) ) ),
Since Predicates perform short-circuit evaluation, where the criteria groups are evaluated in order and the first failure in the criteria causes the Predicate evaluation to stop and preventing the Event from being fired in the engine, the order of the criteria can directly impact the performance of an Event Session. If we look at the definition for the sqlos.wait_info Event, the first Predicate criteria specifies that the duration of the wait has to be greater than 15 seconds. Since the majority of waits in SQL Server generally occur with durations less than 15 seconds, the Predicate evaluations shortcut immediately and the Event does not fire. If the wait exceeds the 15 second duration, the evaluation continues and checks that the wait_type matches one of defined values. How do we know what these values are?
When looking at an Event, all of the columns have a type_name associated with them that can be found in the sys.dm_xe_object_columns DMV as previously discussed in this series. If we take a look at the type_name for the wait_info Event wait_type column, we’ll see that it has a type of wait_types.
When a column has a non-standard type_name like this, it corresponds to a Map that has been loaded in Extended Events. We can find a list of the wait_types that the Event will fire for by querying the sys.dm_xe_map_values DMV for the map_keys defined in the Event Session:
SELECT map_key, map_value FROM sys.dm_xe_map_values WHERE name = 'wait_types' AND (map_key > 31 -- Waits for latches and important wait resources (not locks) -- that have exceeded 15 seconds. AND ( (map_key > 47 AND map_key < 54) OR map_key < 38 OR (map_key > 63 AND map_key < 70) OR (map_key > 96 AND map_key < 100) OR (map_key = 107) OR (map_key = 113) OR (map_key > 174 AND map_key < 179) OR (map_key = 186) OR (map_key = 207) OR (map_key = 269) OR (map_key = 283) OR (map_key = 284) ) )
The wait_types that correspond to the first complex grouping are:
map_key map_value 32 LATCH_NL 33 LATCH_KP 34 LATCH_SH 35 LATCH_UP 36 LATCH_EX 37 LATCH_DT 48 PAGELATCH_NL 49 PAGELATCH_KP 50 PAGELATCH_SH 51 PAGELATCH_UP 52 PAGELATCH_EX 53 PAGELATCH_DT 64 PAGEIOLATCH_NL 65 PAGEIOLATCH_KP 66 PAGEIOLATCH_SH 67 PAGEIOLATCH_UP
map_key map_value 68 PAGEIOLATCH_EX 69 PAGEIOLATCH_DT 97 IO_COMPLETION 98 ASYNC_IO_COMPLETION 99 NETWORK_IO 107 RESOURCE_SEMAPHORE 113 SOS_WORKER 175 FCB_REPLICA_WRITE 176 FCB_REPLICA_READ 177 HOLDER11 178 WRITELOG 186 CMEMTHREAD 207 TRACEWRITE 269 RESOURCE_SEMAPHORE_MUTEX 283 RESOURCE_SEMAPHORE_QUERY_COMPILE 284 RESOURCE_SEMAPHORE_SMALL_QUERY
If you look at the way the Predicate is defined, it is much closer to how you’d write a WHERE clause with complex filtering criteria, allowing groups of specific criteria to be defined within sets of parenthesis’s that are evaluated together, something that was impossible with SQL Trace.
In addition to being able to define Predicates based on the Event columns returned by an Event, it is possible to also define Predicates on the global state data available in the Extended Events Engine. If you’ll recall, the global state predicates are available in the sys.dm_xe_objects DMV as pred_source object_type’s.
Two of the predicate sources are special, the package0.counter and package0.partitioned_counter, and can be used to restrict the number of occurrences of an Events that are captured by an Event Session. The following demonstration creates an Event Session that captures the first five occurrences of the sqlserver.sql_statement_completed Event, and then executes six statements in sequence. When the target_data is queried the last statement SELECT @@SPID is not included in the results.
CREATE EVENT SESSION CounterPredicateDemo ON SERVER ADD EVENT sqlserver.sql_statement_completed ( ACTION (sqlserver.sql_text) WHERE (package0.counter <=5)) ADD TARGET package0.ring_buffer WITH (MAX_DISPATCH_LATENCY = 1 SECONDS) GO ALTER EVENT SESSION CounterPredicateDemo ON SERVER STATE = START GO SELECT @@VERSION GO SELECT @@SERVERNAME GO SELECT @@SPID GO SELECT @@VERSION GO SELECT @@SERVERNAME GO SELECT @@SPID GO ALTER EVENT SESSION CounterPredicateDemo ON SERVER DROP EVENT sqlserver.sql_statement_completed GO -- Wait in a delay for Events to Buffer WAITFOR DELAY '00:00:05' GO -- Query the XML to get the Target Data SELECT n.value('(event/@name)[1]', 'varchar(50)') AS event_name, n.value('(event/@package)[1]', 'varchar(50)') AS package_name, DATEADD(hh, DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), n.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp], n.value('(event/data[@name="object_id"]/value)[1]', 'int') AS [object_id], n.value('(event/data[@name="object_type"]/value)[1]', 'nvarchar(128)') AS [object_type], n.value('(event/data[@name="duration"]/value)[1]', 'int') AS [duration], n.value('(event/data[@name="cpu"]/value)[1]', 'int') AS [cpu], n.value('(event/data[@name="reads"]/value)[1]', 'int') AS [reads], n.value('(event/data[@name="writes"]/value)[1]', 'int') AS [writes], n.value('(event/action[@name="sql_text"]/value)[1]', 'nvarchar(max)') AS [sql_text] FROM ( SELECT td.query('.') as n FROM ( SELECT CAST(target_data AS XML) as target_data 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 = 'CounterPredicateDemo' AND t.target_name = 'ring_buffer' ) AS sub CROSS APPLY target_data.nodes('RingBufferTarget/event') AS q(td) ) as tab GO -- Drop the Event Session DROP EVENT SESSION CounterPredicateDemo ON SERVER
This capabilities behind Predicate definition in Extended Events makes it much more flexible, and powerful for troubleshooting than SQL Trace. It also makes Extended Events much more performant than Trace by preempting Event firing for Events that are not of interest.