Short Circuit Events

I introduced the importance about predicate order previously. I recommend either reading that article for the first time or reading it again if you have already read it. You can find that article – here.

The predicate order is critical. Having the wrong order can result in not trapping the desired events. I cover the critical nature of predicates in the aforementioned article. At least in principle. Today, I want to reinforce the topic through the use of examples.

Housekeeping: For the examples, I will use two different Extended Event sessions. The only difference between the sessions will be the order of the predicates that I will use.

Setting the stage: I have a specific set of queries that are executing within the Adventureworks2014 database. I want to capture just the second query to be executed from that database. Since I want to capture just the second query to be executed, I will be using the package0.counter predicate.

This is an extremely simple scenario for a reason. The simple scenario helps to simplify the creation of the session. And of course, it also makes it much easier to demonstrate the effects of the predicate order.

Before getting into the weeds with the session, here are the basic query statements that will be used across the trials.

/* open two query windows - one for each database connection 
then run these statements in order - alternating between database connections
*//* Trial 1 */SELECT 'Trial 1: count - first statement'
FROM AdventureWorks2014.sys.databases
WHERE name = 'AdventureWorks2014';
GO
SELECT 'Trial 1: count - second statement'
FROM tempdb.sys.databases
WHERE name = 'tempdb';
GO
SELECT 'Trial 1: count - third statement'
FROM AdventureWorks2014.sys.databases
WHERE name = 'AdventureWorks2014';
GO
SELECT 'Trial 1: count - fourth statement'
FROM tempdb.sys.databases
WHERE name = 'tempdb';
GO
SELECT 'Trial 1: db - first statement'
FROM AdventureWorks2014.sys.databases
WHERE name = 'AdventureWorks2014';
GO
SELECT 'Trial 1: db - second statement'
FROM tempdb.sys.databases
WHERE name = 'tempdb';
GO
SELECT 'Trial 1: db - third statement'
FROM AdventureWorks2014.sys.databases
WHERE name = 'AdventureWorks2014';
GO
SELECT 'Trial 1: db - fourth statement'
FROM tempdb.sys.databases
WHERE name = 'tempdb';
GO

As you can see, I will be running the same set of queries multiple times with just the slightest of variation. I will run the first four for the first XEvent session I create which will have the counter listed first in the predicate. Then I will run the second four statements for the session configured with the database filter first in the predicate order.

Without further ado, here are the definitions of the two XEvent sessions:

USE master;
GO
-- Create the Event Session
IF EXISTS ( SELECT *
FROM sys.server_event_sessions
WHERE name = 'pred_ordercountfirst' )
DROP EVENT SESSION pred_ordercountfirst 
    ON SERVER;
GO
EXECUTE xp_create_subdir 'C:\Database\XE';
GO
USE master
GO
CREATE EVENT SESSION pred_ordercountfirst ON SERVER
ADD EVENT sqlserver.sql_statement_completed
    (ACTION (sqlserver.sql_text)
    WHERE package0.counter = 2
AND sqlserver.database_name = 'AdventureWorks2014')
ADD TARGET package0.event_file ( SET filename = N'C:\Database\XE\pred_ordercountfirst.xel' )
WITH (MAX_DISPATCH_LATENCY = 1 SECONDS)
ALTER EVENT SESSION pred_ordercountfirst
ON SERVER
STATE = START;
GO
USE master;
GO
-- Create the Event Session
IF EXISTS ( SELECT *
FROM sys.server_event_sessions
WHERE name = 'pred_orderdbfirst' )
DROP EVENT SESSION pred_orderdbfirst 
    ON SERVER;
GO
EXECUTE xp_create_subdir 'C:\Database\XE';
GO
USE master
GO
CREATE EVENT SESSION pred_orderdbfirst ON SERVER
ADD EVENT sqlserver.sql_statement_completed
    (ACTION (sqlserver.sql_text)
    WHERE sqlserver.database_name = 'AdventureWorks2014'
AND package0.counter = 2
)
ADD TARGET package0.event_file ( SET filename = N'C:\Database\XE\pred_orderdbfirst.xel' )
WITH (MAX_DISPATCH_LATENCY = 1 SECONDS)
ALTER EVENT SESSION pred_orderdbfirst
ON SERVER
STATE = START;
GO

With these sessions, I will only have one turned on at a time. Running both at the same time can result in invalid results. The process is simple: from separate connections, alternate through the list of queries and then check the session data to find the result. The queries are written to help indicate which query window each should be run. For the results to be valid, I will be sticking to that pattern. In this test case, the pattern will alternate between two connections where one is connected to the tempdb database and the other is connected to the AdventureWorks2014 database.

Running through the trials for the pred_ordercountfirst session, I will receive the following results:

I have cycled through each of the four scripts with the pred_ordercountfirst session in the running state. Notice that I have no event_data? This is because no event has been trapped. When the counter reaches a value of two, the second predicate condition fires. The second query to have been executed was actually run from the tempdb database. Because the second condition fails the check, no data will be captured for this first session. Recapping each iteration would look like the following:

Each query executed caused the counter value to increment as shown by the green box. In the red box is the second iteration which was performed against a connection to tempdb. And in the yellow box, I show that no statements have been trapped in this session.

Here is a query to help validate the session results.

SELECT CAST ([t2].[event_data] AS XML) AS event_data, t2.file_offset,t2.file_name, cte1.predicate
FROM ( SELECT REPLACE(CONVERT(NVARCHAR(128),sesf.value),'.xel','*.xel') AS targetvalue, sese.predicate
FROM sys.server_event_sessions ses
INNER JOIN sys.server_event_session_fields sesf
ON ses.event_session_id = sesf.event_session_id
INNER JOIN sys.server_event_session_events sese
ON ses.event_session_id = sese.event_session_id
WHERE sesf.name = 'filename'
AND ses.name = 'pred_ordercountfirst'
) cte1
OUTER APPLY sys.fn_xe_file_target_read_file(cte1.targetvalue,NULL, NULL, NULL) t2
;

I have not included a means to parse into the session data because there is nothing to parse. That will change with the next trial. I will drop the pred_ordercountfirst and then create the pred_orderdbfirst session. Then I will run the trial in the same fashion as I did for the pred_ordercountfirst session.

It’s a bit small, but the data is there. Looking down into the data a little closer, I will see the following:

From the session data, I can see that the overall third query to execute was the query trapped by the session. This is the correct result based on the order of executions and the requirements defined in the beginning. See the big difference between the configurations of the predicates in these two sessions? Predicate order is important and critical to a proper running event session.

To recap the results by iteration, I have the following:

Similar to the previous session, I have used green to highlight the counter value after each iteration. Since the first query executed was against the Adventureworks2014 database, the counter value incremented to 1. In the next iteration, it remained at one because the source database was tempdb and not AdventureWorks2014. Finally, the counter incremented to two on the next iteration when the source database was AdventureWorks2014. At this point, since both criteria were met, an event was recorded and sent to the event_file target (recall the event processing steps shown here).

To parse all of this data, I used the following statements:

SELECT CAST ([t2].[event_data] AS XML) AS event_data, t2.file_offset,t2.file_name, cte1.predicate
INTO #xmlprocess
FROM ( SELECT REPLACE(CONVERT(NVARCHAR(128),sesf.value),'.xel','*.xel') AS targetvalue, sese.predicate
FROM sys.server_event_sessions ses
INNER JOIN sys.server_event_session_fields sesf
ON ses.event_session_id = sesf.event_session_id
INNER JOIN sys.server_event_session_events sese
ON ses.event_session_id = sese.event_session_id
WHERE sesf.name = 'filename'
AND ses.name = 'pred_orderdbfirst'
) cte1
OUTER APPLY sys.fn_xe_file_target_read_file(cte1.targetvalue,NULL, NULL, NULL) t2
;
SELECT x.event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name
, x.event_data.value('(event/action[@name="sql_text"]/value)[1]','varchar(max)') AS sql_text
, x.file_offset,x.predicate--,x.file_name
FROM #xmlprocess x

In this article I have just shown how the configuration of predicates for each event will affect the events that are trapped. In TSQL both of these predicates would produce the same results. In Extended Events, the order of the predicates can cause a significant difference in the event that is captured and what is expected to be captured. Furthermore, this processing order can correlate to a difference in observer overhead since more (or less) events may be captured than what is expected. The more data that has to flow throw all levels of filters, the more impact that will be caused by the configuration of the event session and predicates.

This has been another article in the 60 Days of XE series. If you have missed any of the articles, or just want a refresher, check out the TOC.

Database Settings Changes – Red Handed July 8, 2015
Better Practices for Reading Event_file Targets October 15, 2015
Database Drops in SQL 2012 July 1, 2015
Audit who Dropped the Database April 7, 2015
Trapping Online Index Operations January 29, 2015

Short Circuit Events