Execution Plans in Extended Events

Extended Events is a wonderful tool. Execution Plans are also some wonderful things – or are a wonderful tool as well. Both of these tools are fantastic for troubleshooting. Combined, they can potentially be even better.

Or, they could just cause some hair loss and be a fairly complicated pain in your butt. Hopefully the combination of the two will be more useful than painful for you. And today, I will discuss one of the pains that could be an issue when combining these two tools. I will also discuss some options for getting around this pain point between XE and Execution Plans.

Let’s start by taking a quick look at two Extended Events events that can expose execution plans for you. These two events are query_pre_execution_showplan and query_post_execution_showplan. Here are a couple sample sessions set to trap these events.

IF EXISTS(SELECT * 
          FROM sys.server_event_sessions 
          WHERE name='TrapEstExecPlans')
    DROP EVENT SESSION TrapEstExecPlans 
    ON SERVER;
GO
CREATE EVENT SESSION TrapEstExecPlans
ON SERVER
--+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
--+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
/* The pre_execution_showplan event will trap estimated plan */--ADD EVENT sqlserver.query_pre_execution_showplan,
--+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
--+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
ADD EVENT sqlserver.query_pre_execution_showplan(
    ACTION (sqlserver.database_name,sqlserver.client_hostname,sqlserver.client_app_name,
            sqlserver.plan_handle,
            sqlserver.sql_text,
            sqlserver.tsql_stack,
            package0.callstack,
sqlserver.query_hash,
sqlserver.session_id,
            sqlserver.request_id)
 
--Change this to match the AdventureWorks, 
--AdventureWorks2008 or AdventureWorks2012 DB_ID()
WHERE sqlserver.database_id=9
AND sqlserver.client_app_name <> 'Microsoft SQL Server Management Studio - Transact-SQL IntelliSense'
)
ADD TARGET package0.event_file(SET filename=N'C:DatabaseXETrapEstExecPlans.xel',max_file_size=(5),max_rollover_files=(4)),
ADD TARGET package0.ring_buffer
WITH (MAX_DISPATCH_LATENCY=5SECONDS, TRACK_CAUSALITY=ON)
GO

And…

IF EXISTS(SELECT * 
          FROM sys.server_event_sessions 
          WHERE name='TrapExecPlans')
    DROP EVENT SESSION TrapExecPlans 
    ON SERVER;
GO
CREATE EVENT SESSION TrapExecPlans
ON SERVER
--+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
--+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
/* The pre_execution_showplan event will trap estimated plan */--ADD EVENT sqlserver.query_pre_execution_showplan,
--+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
--+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
ADD EVENT sqlserver.query_post_execution_showplan(
    ACTION (sqlserver.database_name,sqlserver.client_hostname,sqlserver.client_app_name,
            sqlserver.plan_handle,
            sqlserver.sql_text,
            sqlserver.tsql_stack,
            package0.callstack,
sqlserver.query_hash,
sqlserver.session_id,
            sqlserver.request_id)
 
--Change this to match the AdventureWorks, 
--AdventureWorks2008 or AdventureWorks2012 DB_ID()
WHERE sqlserver.database_id=9
AND sqlserver.client_app_name <> 'Microsoft SQL Server Management Studio - Transact-SQL IntelliSense'
)
ADD TARGET package0.event_file(SET filename=N'C:DatabaseXETrapExecPlans.xel',max_file_size=(5),max_rollover_files=(4)),
ADD TARGET package0.ring_buffer
WITH (MAX_DISPATCH_LATENCY=5SECONDS, TRACK_CAUSALITY=ON)
GO

With these sample sessions ready, we need a quick description of what is happening. I have built the sessions (at least the TrapEstExecPlans session) to go to both a file and the ringbuffer targets. This was done to test the behavior on both targets to ensure consistency in behavior between the different targets.

Also, I added a bunch of actions that are available to query, but the sample queries shown later will not use the data for those actions. This is only due to the examples I have chosen to share.

With those sessions created, go ahead and start them, then run a query like the following:

USE AdventureWorks2012; --whatever your database id 9 is
GO
SELECT *
FROM sys.allocation_units;

After  having executed this query, I can start taking a look at the data captured. I will only query the TrapEstExecPlans session in this post because the behavior between the two sessions and events is consistent.

SELECT
    event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
    CAST(event_data.value('(event/action[@name="plan_handle"]/value)[1]', 'varchar(max)') AS XML) as plan_handle,
    event_data.value('(event/action[@name="sql_text"]/value)[1]', 'varchar(max)') AS sql_text
--,CAST(REPLACE(REPLACE(CAST(planxml.query('.') AS VARCHAR(MAX)),'<value>',''),'</value>','') AS XML) AS plan_xml
,planxml.query('.') AS plan_xml
FROM(    SELECT evnt.query('.') AS event_data,xmlplan.query('.') AS event_plan
        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 = 'TrapEstExecPlans'
              AND t.target_name = 'ring_buffer'
        ) AS tab
        CROSS APPLY TargetData.nodes ('RingBufferTarget/event') AS split(evnt) 
CROSS APPLY evnt.nodes('(data[@name="showplan_xml"]/value)[last()]/*') AS showplan(xmlplan)
    ) AS evts(event_data,planxml)
;

Keep in mind that I talked about having both a ringbuffer and a file target for this session. I am only going to share the query from the ringbuffer target because the behavior from the memory target and the filetarget is the same.

If I take a look at the execution plans shared from the results of that query, I might see something like this:

If I look at the execution plan at runtime for that same query, I would see something like this:

Between the two plans, I have color coded the various attributes of the plan to pair the matching attributes and make it easier to spot the differences. In this case, the differences are in the first two nodes. The plan from Extended Events does not have the connection properties, but is also missing a few other important things like the StatementType and StatementText. Looking at the plan from XE in the gui, you would see something like this:

Instead of this:

Those minor differences in the XML of the execution plans can lead to somewhat of a pain. Alas, there is a fix for that. And the fix comes down to doing one of a few things already available to us in the XE session data. We can either lookup the plan_handle that was trapped by the action, or we can lookup the QueryPlanHash that is available in the XML from the execution plan data that has been trapped. With that information, one can likely retrieve the stored execution plan and catch the rest of the missing components of that execution plan.

There is one other option and that is the action that traps the sql_text. The sql_text that is captured can lead us to understand what kind of plan (select, update, delete, etc) we are looking at from the XE session data.

So, while it is a bit of a nuisance that the two sources of execution plans does not produce the same plan, it is not the end of the world. There is still adequate information available from the XE session data to figure out the missing pieces of the execution plan.