An XEvent a Day (14 of 31) – A Closer Look at Predicates

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.

SELECT 
    name, 
    type_name, 
    column_type
FROM sys.dm_xe_object_columns
WHERE object_name = 'wait_info'
  AND column_type <> 'readonly'
image

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.

SELECT 
    p.name AS package_name,
    o.name AS predicate_name,
    o.description
FROM sys.dm_xe_packages AS p
INNER JOIN sys.dm_xe_objects AS o
    ON p.guid = o.package_guid
WHERE (p.capabilities IS NULL OR p.capabilities & 1 = 0)
  AND o.object_type = 'pred_source'

  image

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

image

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.

Leave a Reply

Your email address will not be published. Required fields are marked *

Other articles

Imagine feeling confident enough to handle whatever your database throws at you.

With training and consulting from SQLskills, you’ll be able to solve big problems, elevate your team’s capacity, and take control of your data career.