An XEvent a Day (9 of 31) – Targets Week – pair_matching

Yesterday’s post, Targets Week – synchronous_event_counter, looked at the counter Target in Extended Events and how it could be used to determine the number of Events a Event Session will generate without actually incurring the cost to collect and store the Events.  Today’s post is coming late, I know, but sometimes that’s just how the ball rolls.  My original planned demo’s for today’s post turned out to only work based on a fluke, though they were very consistent at working as expected, and as a result I had to rework a lot of this post this evening instead of letting it auto-post in the morning.  Today’s post will cover the pair_matching Target, which can be used to find Events that didn’t have a corresponding matching Event based on the Targets configuration.

What is the pair_matching Target?

The pair_matching Target works by matching a Begin Event with an End Event based on the specified match Columns and Actions, and drops the matched pairs of Events from the Target so that only unmatched Events remain.   However, life would be grand if it was only that simple to use.  The Books Online example How to: Determine Which Queries Are Holding Locks, uses the pair_matching Target with the sqlserver.lock_acquired and sqlserver.lock_released events for matching, to try and show how to find queries that haven’t released their Locks.  The problem is, there is not a 1:1 relationship between lock_acquired and lock_released Events.  Lock escalation can kick in and multiple granular locks are acquired but the escalation to a less granular Lock only requires a single lock_released Event to fire. 

In the Using SQL Server 2008 Extended Events whitepaper I wrote, I showed how to track down orphaned transactions using the sqlserver.database_transaction_begin and sqlserver.database_transaction_end Events and matching on the sqlserver.session_id Action.  The reason that this example works is that only one explicit transaction can be open for an session_id, even if you issue multiple BEGIN TRANSACTION commands, a single ROLLBACK undoes every operation performed since the first BEGIN TRANSACTION.  Yes this is a tangent, but fear not, I am coming back to why this matters to the pair_matching Target.  It matters to the pair_matching target because the begin and end Events must uniquely match each other in a manner that is 1:1 or the pair_matching Target is not going to work as you expect it to, as in the “Which Queries Are Holding Locks” example in the BOL.

Like the ring_buffer, bucketizer, and the synchronous_event_counter, the pair_matching Target is a memory resident Target that holds event data in memory while the Event Session is active on the SQL Server.  When the Event Session is stopped, the memory buffers allocated to the target are freed and any information contained in the target is lost.

Configuration Options

There are seven configuration options for the pair_matching Target, with two of them being mandatory.  The pair_matching Target requires that the begin_event and end_event for matching be specified for the Target.  In addition to specifying the events, it is also possible to restrict the match criteria by specifying an ordered comma separated list of column names for the begin_matching_columns and end_matching_columns configuration options.  If the matching requires the use of Actions, an ordered comma separated list of Action names in the format of <package_name.action_name> can be specified for the begin_matching_actions and end_matching_actions configuration options.  The final configuration option respond_to_memory_pressure determines whether or not the Target responds to memory pressure, and stops adding new orphaned events when there is memory pressure in the SQL Server.

-- Target Configurable Fields
SELECT 
   oc.name AS column_name,
   oc.column_id,
   oc.type_name,
   oc.capabilities_desc,
   oc.description
FROM sys.dm_xe_packages AS p
JOIN sys.dm_xe_objects AS o 
    ON p.guid = o.package_guid
JOIN sys.dm_xe_object_columns AS oc 
    ON o.name = oc.OBJECT_NAME 
   AND o.package_guid = oc.object_package_guid
WHERE(p.capabilities IS NULL OR p.capabilities & 1 = 0)
  AND (o.capabilities IS NULL OR o.capabilities & 1 = 0)
  AND o.object_type = 'target'
  AND o.name = 'pair_matching'

Understanding the Target Data Format

Like the other memory resident Targets, the pair_matching Target returns its information by querying the sys.dm_xe_session_targets DMV, and it returns the Target data in an XML format that is not schema bound, but that has a standardized format.  The pair_matching Target XML document, closely matches the output of the ring_buffer Target.  The root node of the XML is the <PairingTarget> node which has attributes for the number of truncated Events, the count of the current number of orphans held in the Target, the number of matched Event pairs that have been made by the Target, and the number of orphans that have been dropped due to memory pressure in SQL Server.  The <PairingTarget> node has child <event> nodes that match the XML document of the <event> nodes in the ring_buffer and asynchronous_file_target Targets.  A simplified representation of the XML output by the pair_matching Target is below:

<PairingTarget truncated="" orphanCount="" matchedCount="" memoryPressureDroppedCount="">
  <event name="" package="" id="" version="" timestamp="">
    <data name="">
      <type name="" package="" />
      <value />
      <text />
    </data>
    <action name="" package="">
      <type name="" package="" />
      <value />
      <text />
    </action>
  </event>
</PairingTarget>

Querying/Parsing the Target Data

Like the other memory resident Targets in Extended Events, the pair_matching Target data is only exposed by querying the sys.dm_xe_session_targets DMV.  Mike Wachal at Microsoft, traded emails with me, and dug into the source code for the pair_matching target yesterday trying to help me with some questions for this post, especially as they related to the legitimacy of the demo’s being planned for this post.  In the end Mike sent me a demo and permission to post it here in lieu of the questionable ones that I had been trading emails with him about.  It is with much appreciation to Mike and the Extended Events Development team for their assistance with this blog post and the consistent back and forth with emails that they provided yesterday.

Mike provided an example that I will show in its entirety for this weeks wrap up post on Saturday, but I am going to show a shorter sample of the demo to show how to use the pair_matching Target and query the Target data from it.  When SQL Server executes a statements, generally the sqlserver.sql_statement_starting Event is fired when the statement begins executing and the sqlserver.sql_statement_completed Event is fired when the statement completes.  However, when the client sets an execution time, also known as a CommandTimeout in .NET, if the execution duration exceeds that timeout, the statement never completes inside of SQL Server.  I have run into problems with the default timeout of 30 seconds in .NET more times than I ever care to think about in my career. 

To demonstrate a execution time out using SQL Server Management Studio, you can open a New Query window, and in the connection dialog click on the Connection Properties tab and change the Execution time-out option from 0 (zero) to a positive integer value.  For the purposes of this blog post example, I am going to use 5 seconds as the execution timeout for one query window that will generate the unmatched event.

The first thing we need to do is setup our Event Session to capture our Events and Actions, and configure our pair_matching Target.

-- Create the Event Session
CREATE EVENT SESSION FindAttentionEvents
ON SERVER
ADD EVENT sqlserver.sql_statement_starting
(    ACTION(sqlserver.session_id, sqlserver.tsql_stack)
),
ADD EVENT sqlserver.sql_statement_completed
(    ACTION(sqlserver.session_id, 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)

-- Start the Event Session
ALTER EVENT SESSION FindAttentionEvents
ON SERVER
STATE=START
GO

Now in the New Query window that had the connection option for execution timeout set to 5 seconds, run the following commands:

SELECT TOP 100 *
FROM sys.objects
GO

SELECT TOP 100 *
FROM sys.columns
GO

WAITFOR DELAY '00:00:10'
GO

In my test system the output for this is:

If we flip back to a normal Query window and query the Target data, we will see multiple matched Events and one orphaned Event, for the above failure.

-- 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 = 'FindAttentionEvents'
  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,
    @target_data.value('(PairingTarget/@memoryPressureDroppedCount)[1]', 'int') AS memoryPressureDroppedCount

-- Query the XML variable 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,
    n.value('(event/@id)[1]', 'int') AS id,
    n.value('(event/@version)[1]', 'int') AS version,
    DATEADD(hh, 
            DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
            n.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
    n.value('(event/data[@name="source_database_id"]/value)[1]', 'int') as [source_database_id],
    n.value('(event/data[@name="object_id"]/value)[1]', 'int') as [object_id],
    n.value('(event/data[@name="object_type"]/value)[1]', 'varchar(60)') as [object_type],
    n.value('(event/data[@name="state"]/text)[1]', 'varchar(50)') as [state],
    n.value('(event/data[@name="offset"]/value)[1]', 'int') as [offset],
    n.value('(event/data[@name="offset_end"]/value)[1]', 'int') as [offset_end],
    n.value('(event/data[@name="nest_level"]/value)[1]', 'int') as [nest_level],
    n.value('(event/action[@name="session_id"]/value)[1]', 'int') as session_id,
    n.value('(event/action[@name="tsql_stack"]/value)[1]', 'varchar(max)') as tsql_stack,    
    n.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)') as activity_id    
FROM
(    SELECT td.query('.') as n
FROM @target_data.nodes('PairingTarget/event') AS q(td)
) as tab
ORDER BY session_id, activity_id
GO

If you pay close attention to the above XQuery of the Target data, you should catch that there is a difference between the above and previous examples.  I have a prize for the first person that is not Adam Machanic (sorry dude, but you told me about it so that would be unfair) to comment with what that difference is and why it is important to take note of.  The output of the above query on my test system after running the demo is:

Now with this Demo, it is important that you reset the environment that you tested it in if you followed the instructions and changed the execution timeout in SQL Server Management Studio.  If you don’t change it back, you will try and run a query that takes longer than 5 seconds and it will timeout on you.  Also don’t forget to cleanup the Event Session by dropping it from the catalog.

-- Cleanup from the demonstration
DROP EVENT SESSION FindAttentionEvents 
ON SERVER

Considerations for Usage

The pair_matching Target can be a very useful tool in finding unmatched Events, but as previously pointed out in this blog post, you have to be very careful what you are providing for match criteria, and the Events have to have a 1:1 correlation for the begin_event and end_event or the target will produce incorrect results.

What’s next?

Now that we have looked at the ring_buffer, asynchronous_file_target, bucketizers, synchronous_event_counter, and the pair_matching Targets, in the next post we’ll look at the last Target available for use in Extended Events, the etw_classic_sync_target, which can be used to track Events firing in SQL Server out into the Windows OS Kernel and back into SQL Server to see end to end what occurred inside the Server.