Jonathan Kehayias

Predicate Order Matters in Extended Events

June 19, 2014 by in Extended Events | No Comments
Database smarter with deeper insights for Microsoft SQL
SentryOne eBooks

In these books, you will find useful, hand-picked articles that will help give insight into some of your most vexing performance problems. These articles were written by several of the SQL Server industry’s leading experts, including Paul White, Paul Randal, Jonathan Kehayias, Erin Stellato, Glenn Berry, Aaron Bertrand, and Joe Sack.

Free Download →

Featured Author

Paul Randal, CEO of SQLskills, writes about knee-jerk performance tuning, DBCC, and SQL Server internals.

Paul’s Posts →

In every presentation I give on Extended Events, I try and explain one of the biggest differences between filtering in Extended Events and filtering in Trace; the fact that predicate order matters in Extended Events. Most of the time I am talking about short-circuiting of predicate evaluation in Extended Events, and trying to make the event predicate fail logical evaluation as quickly as possible to return control to the executing task. I recently was working with one of my example event sessions that I use in presentations that demonstrates another important aspect of predicate order in Extended Events.

Within Extended Events there are textual predicate comparators that allow for more complex definitions of the filtering criteria for an event. A few of these actually maintain an internal state while the event session is started on the server, for example the package0.greater_than_max_uint64 and package0.less_than_min_uint64 comparators. There is also a predicate source element, package0.counter, that also maintains an internal state when the event session is started. For the state maintaining predicates in Extended Events, one of the most important considerations is that the internal state changes whenever the state maintaining predicate is evaluated, not when the event fully fires. To demonstrate this, let's take a look at an example usage of the package0.greater_than_max_uint64 textual predicate comparator. First we'll need to create a stored procedure that we can control the execution duration of:

USE AdventureWorks2012
GO
IF OBJECT_ID(N'StoredProcedureExceedsDuration') IS NOT NULL
       DROP PROCEDURE dbo.StoredProcedureExceedsDuration;
GO
CREATE PROCEDURE dbo.StoredProcedureExceedsDuration
( @WaitForValue varchar(12) = '00:00:00:050')
AS
       WAITFOR DELAY @WaitForValue;      
GO

Then we will need to create an event session to track the executions of the stored procedure using the sqlserver.module_end event, and filters the executions on the object_id and source_database_id columns provided by the event. We will also define a filter using the package0.greater_than_max_uint64 textual comparator against the duration column, which is in microseconds in Extended Events, with an initial state of 1000000 or one second. With this addition to the predicate, the event will only fire when the duration exceeds the initial value of 1000000 microseconds, and then the predicate will store the new state value internally, so that the event doesn't fire fully again until the duration exceeds the new internal state value. Once we create the event session, which in this case uses Dynamic SQL since we can't use parameterization in DDL statements in SQL Server, it will be started on the server and we can run our sample stored procedure and control the execution duration multiple times to look at how the event fired with our predicate.

IF EXISTS(SELECT * 
         FROM sys.server_event_sessions 
         WHERE name='StatementExceedsLastDuration') 
    DROP EVENT SESSION [StatementExceedsLastDuration] ON SERVER; 
GO
-- Build the event session using dynamic SQL to concatenate the database_id 
-- and object_id in the DDL, parameterization is not allowed in DDL!
DECLARE @ObjectID    NVARCHAR(10)  = OBJECT_ID('StoredProcedureExceedsDuration'),
              @DatabaseID NVARCHAR(10)   = DB_ID('AdventureWorks2012');
DECLARE @SqlCmd            NVARCHAR(MAX) ='
CREATE EVENT SESSION [StatementExceedsLastDuration] ON SERVER
ADD EVENT sqlserver.module_end(
       SET collect_statement = 1
       WHERE  (object_id = ' + @ObjectID + ' AND 
                      source_database_id = ' + @DatabaseID + ' AND
                     package0.greater_than_max_uint64(duration, 1000000)))
ADD TARGET package0.ring_buffer(SET max_events_limit=10);'

EXECUTE(@SqlCmd)

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

EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration;
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration '00:00:01.000';
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration;
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration '00:00:02.000';
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration;
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration '00:00:01.000';
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration;

If you read my blog on SQLskills.com, you probably know that I am not a big fan of using the ring_buffer target in Extended Events for a number of reasons. For this limited data collection, and the fact that the event session limits it to a maximum of ten events, it is an easy target to demonstrate the behavior of the event predicate order, but we still need to shred the XML for the events manually to see the results.

-- Shred events out of the target
SELECT
    event_data.value('(@name)[1]', 'nvarchar(50)') AS event_name,
    event_data.value('(@timestamp)[1]', 'datetime2') AS [timestamp],
    event_data.value('(data[@name="duration"]/value)[1]', 'bigint') as duration,
    event_data.value('(data[@name="statement"]/value)[1]', 'varchar(max)') as [statement]
FROM (  SELECT CAST(target_data AS xml) AS TargetData
        FROM sys.dm_xe_sessions AS s
        INNER JOIN sys.dm_xe_session_targets AS t
            ON s.address = t.event_session_address
        WHERE s.name = N'StatementExceedsLastDuration'
          AND t.target_name = N'ring_buffer' ) AS tab
CROSS APPLY TargetData.nodes (N'RingBufferTarget/event') AS evts(event_data);

Running the code above will result in just 2 events, one for the one second, and then the other for the two seconds executions. The other executions of the stored procedure are shorter than the initial one second duration filter specified in microseconds in the predicate, and then the last one second execution is shorter in duration than the stored state value of two seconds by the comparator. This is the expected behavior of the event collection, but if we change the predicate order so that the package0.greater_than_max_uint64(duration, 1000000) filter occurs first in the predicate order, and create a second stored procedure that we execute with a duration of three seconds first, we won’t get any events at all.

USE AdventureWorks2012
GO
IF OBJECT_ID(N'StoredProcedureExceedsDuration') IS NOT NULL
       DROP PROCEDURE dbo.StoredProcedureExceedsDuration;
GO
CREATE PROCEDURE dbo.StoredProcedureExceedsDuration
( @WaitForValue varchar(12) = '00:00:00:050')
AS
       WAITFOR DELAY @WaitForValue;      
GO
IF OBJECT_ID(N'StoredProcedureExceedsDuration2') IS NOT NULL
       DROP PROCEDURE dbo.StoredProcedureExceedsDuration2;
GO
CREATE PROCEDURE dbo.StoredProcedureExceedsDuration2
( @WaitForValue varchar(12) = '00:00:00:050')
AS
       WAITFOR DELAY @WaitForValue;      
GO
IF EXISTS(SELECT * 
         FROM sys.server_event_sessions 
         WHERE name='StatementExceedsLastDuration') 
    DROP EVENT SESSION [StatementExceedsLastDuration] ON SERVER; 
GO
-- Build the event session using dynamic SQL to concatenate the database_id 
-- and object_id in the DDL, parameterization is not allowed in DDL!
DECLARE @ObjectID    NVARCHAR(10)  = OBJECT_ID('StoredProcedureExceedsDuration'),
              @DatabaseID NVARCHAR(10)   = DB_ID('AdventureWorks2012');
DECLARE @SqlCmd            NVARCHAR(MAX) ='
CREATE EVENT SESSION [StatementExceedsLastDuration] ON SERVER
ADD EVENT sqlserver.module_end(
       SET collect_statement = 1
       WHERE  (package0.greater_than_max_uint64(duration, 1000000) AND
                     object_id = ' + @ObjectID + ' AND 
                      source_database_id = ' + @DatabaseID + '))
ADD TARGET package0.ring_buffer(SET max_events_limit=10);'

EXECUTE(@SqlCmd)

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

EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration;
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration2 '00:00:03.050';
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration '00:00:01.050';
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration;
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration '00:00:02.050';
EXECUTE AdventureWorks2012.dbo.StoredProcedureExceedsDuration;

In this case, because the state maintaining comparator occurs first in the predicate order, its internal value is incremented by the three second execution of the second stored procedure even though the event later fails the object_id filter of the predicate and doesn't fully fire. This behavior happens with every one of the state maintaining predicates in Extended Events. I had previously discovered this behavior with the package0.counter predicate source column, but didn't realized that the behavior occurs for any part of the predicate that maintains a state. The internal state will change as soon as that portion of the predicate is evaluated. For this reason, any predicate filter that changes or maintains state should be the absolute last part of the predicate definition to ensure it only modifies the state internally when all the predicate conditions have passed evaluation.