Parsing Matched Events

I just covered the topic of matching events from definition on down through highlighting a common use for this type of target. With that in mind, it is now time to dive into how to extract the data from the session.

If you need a recap of what exactly a pair_matching target is, or even how to configure it, you can read the article here.

Parsing Matched Events

In fact, it is a good idea to revisit that article and go over the topics presented. Of particular interest should be the script that shows how to find all of the configurable settings for the target.

The other really important take-away from that article is the demo script. That script is repeated here for ease of access.

USE master;
GO
-- Create the Event Session
IF EXISTS ( SELECT *
FROM sys.server_event_sessions
WHERE name = 'Timeout2' )
DROP EVENT SESSION Timeout2 
    ON SERVER;
GO
CREATE EVENT SESSION [Timeout2] ON SERVER
ADD EVENT sqlserver.sql_statement_completed (
ACTION ( sqlserver.database_name, sqlserver.nt_username,
sqlserver.session_id, sqlserver.sql_text, sqlserver.tsql_stack ) ),
ADD EVENT sqlserver.sql_statement_starting (
ACTION ( sqlserver.database_name, sqlserver.nt_username,
sqlserver.session_id, sqlserver.sql_text, sqlserver.tsql_stack ) )
ADD TARGET package0.pair_matching (  SET begin_event = N'sqlserver.sql_statement_starting'
, begin_matching_columns = 'offset,offset_end'
, begin_matching_actions = N'sqlserver.session_id, sqlserver.tsql_stack'
, end_event = N'sqlserver.sql_statement_completed'
, end_matching_columns = 'offset,offset_end'
, end_matching_actions = N'sqlserver.session_id, sqlserver.tsql_stack' )
WITH (  MAX_DISPATCH_LATENCY = 3 SECONDS
, TRACK_CAUSALITY = ON
, STARTUP_STATE = ON );
GO

With that session running on the test server, I can run the following query to explore the structure of the target of the session data. Exploring the structure is a fruitful exercise because one can learn some interesting facts.

SELECT name
, target_name
, CAST(target_data AS XML) AS TargetData
FROM sys.dm_xe_sessions s
INNER JOIN sys.dm_xe_session_targets t
ON s.address = t.event_session_address
WHERE s.name = 'Timeout2';

The first thing I want to point out is at the end of each event node. There is an action (actually two of them) attached to the session that was not specified in either of the events added to this session. This is shown in the following image:

The area of interest is highlighted in green. By enabling Track_causality on this target type, both of these private activities have been attached to all events in the session automatically. Disabling track_causality will remove both of these activities from the session. Of interesting note, is that in sessions with different target types, track_causality will only enable the attach_activity_id action for the session.

Looking back near the beginning of the session data, the following can be seen:

The interesting difference between this target data structure and the ring_buffer (or even file_target) target is in the properties of the target. This target has a few extra data points called truncated, orphanCount, matchedCount, and droppedCount. These are basically target statistics to give a high level overview of what is happening with the session and how the target configurations may have affected the session data.

The next really big ticket item is that the data in this target will only show the event defined for the begin_event configuration setting. Since sql_statement_starting is the event defined as the begin_event in this particular session, it will be the only event to show up in the target. The events have been paired together where possible and the event of record will be the begin_event. One can surmise that this would be due to the potential for the end_event to never fire.

Being aware of the data structure within the pair_matching target is essential to parsing the data from the target. Fortunately, most of the structure is the same with the major differences being in the root node name and then the statistics available via that root node.

So, how does one query the session data? I will resort back to the following building block query for starters:

SELECT CAST ([target_data] AS XML) AS target_data
FROM sys.dm_xe_session_targets AS xt
INNER JOIN sys.dm_xe_sessions AS xs
ON xs.address = xt.event_session_address
WHERE xs.name = N'Timeout2'
AND xt.target_name = N'pair_matching'
;

Nothing fancy with this query and it should be fairly common place at this point. If I take that query to the next level and dump the target data into a temp table, I can query the target more quickly and avoid the cost of re-querying the target each time I wish to change between gathering stats and gathering event details. In the following example, I show just how to do this:

SELECT CAST ([target_data] AS XML) AS target_data
INTO #xmlpreprocess
FROM sys.dm_xe_session_targets AS xt
INNER JOIN sys.dm_xe_sessions AS xs
ON xs.address = xt.event_session_address
WHERE xs.name = N'Timeout2'
AND xt.target_name = N'pair_matching'
;
SELECT 
    target_data.value('(PairingTarget/@orphanCount)[1]', 'int') AS orphanCount,
    target_data.value('(PairingTarget/@matchedCount)[1]', 'int') AS matchedCount,
    target_data.value('(PairingTarget/@droppedCount)[1]', 'int') AS memoryPressureDroppedCount,
target_data.value('(PairingTarget/@truncated)[1]', 'int') AS memoryPressureDroppedCount
FROM #xmlpreprocess

In the second segment of that script, I have queried the properties of the target PairingTarget root node. By doing this, I can validate how well my session is performing. This will produce the following results in my test case:

If I start to see an increase in orphans, or if I see any at all, then I can query further into the session data to figure out what is happening.

SELECT event_data.value('(@name)[1]', 'varchar(50)') AS event_name
, event_data.value('(@package)[1]', 'varchar(50)') AS package_name
, DATEADD(hh, DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP),
event_data.value('(@timestamp)[1]', 'datetime2')) AS [timestamp]
, event_data.value('(data[@name="source_database_id"]/value)[1]', 'int') AS [source_database_id]
, event_data.value('(data[@name="object_id"]/value)[1]', 'int') AS [object_id]
, event_data.value('(data[@name="object_type"]/value)[1]', 'varchar(60)') AS [object_type]
, event_data.value('(data[@name="state"]/text)[1]', 'varchar(50)') AS [state]
, event_data.value('(data[@name="offset"]/value)[1]', 'int') AS [offset]
, event_data.value('(data[@name="offset_end"]/value)[1]', 'int') AS [offset_end]
, event_data.value('(data[@name="nest_level"]/value)[1]', 'int') AS [nest_level]
, CONVERT(XML,event_data.value('(action[@name="sql_text"]/value)[1]', 'varchar(max)')) AS sqlstatement
, event_data.value('(action[@name="session_id"]/value)[1]', 'int') AS session_id
, event_data.value('(action[@name="database_name"]/value)[1]', 'varchar(64)') AS DBName
, event_data.value('(action[@name="nt_username"]/value)[1]', 'varchar(64)')AS nt_username
, event_data.value('(action[@name="tsql_stack"]/value/frames/frame/@handle)[1]','varchar(max)') AS stackhandle
, event_data.value('(action[@name="tsql_stack"]/value/frames/frame/@offsetStart)[1]','varchar(max)') AS stackoffset
, event_data.value('(action[@name="tsql_stack"]/value/frames/frame/@offsetEnd)[1]','varchar(max)') AS stackoffsetend
, event_data.value('(action[@name="attach_activity_id"]/value)[1]','varchar(50)') AS activity_id
FROM #xmlpreprocess x
CROSS APPLY x.target_data.nodes('PairingTarget/event') AS XEventData ( event_data )
ORDER BY session_id
, activity_id;
GO

And looking at a snip of the results, I would see something like the following:

From these results, I can see the query(ies) that seem to be having problems. I can also investigate the TSQL stack. An interesting note about the TSQL stack is that I can retrieve the beginning offset and the ending offset for the query(ies) involved. Since I am testing with the sql_statement* events, this is a bit of redundant data but it is there nonetheless and can be useful. In addition I can see which database is the source of the query timeouts and I can see the user/logon that executed the query. Both of these would be helpful in determining where to focus the attention and effort first. Who knows, maybe it is an end user that needs a little more training.

I have just shown how to parse the data a couple of different ways for the pair_matching target. With a little effort, this target can be configured to work very well and be a great asset in your troubleshooting efforts.

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.