Using xEvents to capture an Actual Execution Plan

If you still are working with SQL Profiler/SQL trace, welcome to the world of Extended Events (also known as xEvents or XE). SQL Trace has been deprecated and shouldn’t be used anymore. Why? Since SQL Server 2012 we have xEvents for lower-impact troubleshooting and performance investigations, providing scalable insights into SQL Server behavior, and in the case we’re discussing here, query execution plans.

 

Query execution plans, otherwise known as actual execution plans or just Showplan, provide a map of all the required operations to get the query output, which includes runtime performance statistics.

These are available through Query Store (QS) for example, which is a valuable tool for troubleshooting workload *trends* via specific queries – this is because QS aggregates performance data on queries. However, sometimes we need to get the specific, singleton query execution plan to analyze and troubleshoot – this is where xEvents come in.

Since SQL Server 2012 we’ve had the query_post_execution_showplan xEvent for this. As the name suggests, it gets you the actual query plan – because it is *after* execution – when we have the runtime statistics available. However this xEvent is based on the standard query execution statistics profile infrastructure (quite a mouthful) – or standard profiling for short (read more about it here). This one has a very high overhead (75%+ with a TPC-C like workload), which is why its use needs to be seriously considered, and most likely not used unless in last resort.

 

In more recent releases we have other alternatives for these requirements to get the singleton actual execution plans, based on the lightweight query execution statistics profile infrastructure – or lightweight profiling for short (read more about it here). These xEvents are listed below, where we’ll see examples on how to use them.

 

query_thread_profile

This is available starting with SQL Server 2014 SP2 and SQL Server 2016.

This xEvent doesn’t really give you a consolidated showplan as other xEvents, however it is useful in the sense it outputs one event per each data access operator and each execution thread found in an actual query execution plan – it can get quite verbose but allows use at a scale that was not possible with any other event before. An example session looks like this:

 

CREATE EVENT SESSION [PerfStats_Node] ON SERVER

ADD EVENT sqlserver.query_thread_profile(

ACTION(sqlos.scheduler_id,sqlserver.database_id,sqlserver.is_system,sqlserver.plan_handle,sqlserver.query_hash_signed,sqlserver.query_plan_hash_signed,sqlserver.server_instance_name,sqlserver.session_id,sqlserver.session_nt_username,sqlserver.sql_text))

ADD TARGET package0.event_file(SET filename=N'C:\Temp\PerfStats_Node.xel',max_file_size=(50),max_rollover_files=(2))

WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)
GO

 

For this example, I ran the following query in the AdventureWorks2016 database:

 

SELECT COUNT(*)

FROM Sales.SalesOrderDetail AS sod

INNER JOIN Sales.SalesOrderHeader AS soh

ON soh.SalesOrderID = sod.SalesOrderID

GROUP BY soh.Status;

GO

 

So, let’s see the resulting session output:

 

query_thread_profile XE

The information found in each xEvent matches the RunTimeCountersPerThread showplan element that may include such information as elapsed time, CPU time, logical and physical reads (if applicable). Notice we have selected the last event generated, and the node_id is 4. Something I know now is this plan has 5 operators – nodes 0 through 4 – which can be searched in the graphical execution plan. Also notice that in each of these events you can find the plan_handle property. This can be used to get the graphical plan from cache, using the query below:

 

sys.dm_exec_query_plan

Clicking on the link in the results tab opens the graphical plan, and now it’s time to start mapping the XE session runtime information with the cached plan. To do this we’ll use a very useful feature in SSMS – Node Search – just right-click a blank area in the plan and you see it:

 

Find Node in SSMS

This feature allows me to search for any property in the plan – and so I search for NodeId 4 – and get immediately positioned in the plan operator that represents that node id 4.

 

Find Node - NodeId

And now comparing with the XE output, I can see the graphical plan and the actual and estimated rows that were read by that Index Scan:

 

query_thread_profile XE compare with Graphical Plan

It can be an arduous task to do the above, but for collecting runtime plan data at scale and then zero in on some specific plan, it is useful.

 

query_plan_profile

This is available starting with SQL Server 2016 SP2 CU3 and SQL Server 2017 CU11. This xEvent outputs the equivalent of a query execution plan similar to the query_post_execution_showplan xEvent, but only for the query or queries that are using the USE HINT ('QUERY_PLAN_PROFILE'). An example session looks like this:

 

CREATE EVENT SESSION [PerfStats_LWP_Plan_Single] ON SERVER
ADD EVENT sqlserver.query_plan_profile(
ACTION(sqlos.scheduler_id,sqlserver.database_id,sqlserver.is_system,sqlserver.plan_handle,sqlserver.query_hash_signed,sqlserver.query_plan_hash_signed,sqlserver.server_instance_name,sqlserver.session_id,sqlserver.session_nt_username,sqlserver.sql_text))
ADD TARGET package0.event_file(SET filename=N'C:\Temp\PerfStats_LWP_Plan_Single.xel',max_file_size=(50),max_rollover_files=(2))
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)
GO

 

This allows a very targeted plan collection that doesn’t require filtering of any sort in the XE session. If a query you want to track is generated by an application and you can’t change the query at its origin, then you can use a plan guide to add the hint, as in the example below created for a stored procedure named Sales.CountSalesOrderByStatus:

 

EXEC sp_create_plan_guide  

@name = N'Guide1',

@stmt = 'SELECT COUNT(*)

FROM Sales.SalesOrderDetail AS sod

INNER JOIN Sales.SalesOrderHeader AS soh

       ON soh.SalesOrderID = sod.SalesOrderID

GROUP BY soh.STATUS;',

@type = N'OBJECT',

@module_or_batch = N'Sales.CountSalesOrderByStatus',

@params = NULL,

@hints = N'OPTION (USE HINT (''QUERY_PLAN_PROFILE''))';

 

So, let’s see the resulting session output where I can already see runtime data such as the query duration, the memory grant and used memory:

 

query_plan_profile XE

Clicking on the tab Query Plan shows me the actual execution plan. The immediate giveaway is that I see information on how many actual rows of estimated rows flowed through the operators.

 

 

Notice the query text is not shown. This is another way of keeping these events lightweight. The xEvent already captures the sql_text. And if needed and the plan is cached, you can always get the cached plan from sys.dm_exec_cached_plans using the plan_handle, and the query text is shown there.

 

query_post_execution_plan_profile

This is a new xEvent available starting with SQL Server 2017 CU14 and SQL Server 2019. Much like the query_post_execution_showplan xEvent, the new query_post_execution_plan_profile outputs the actual query execution plan with fundamental data that’ usually required to troubleshoot query performance, such as the row counts flowing through the plan operators. To keep it lightweight, the plan that’s output by this xEvent doesn’t contain the session wait types, CPU times nor I/O metrics. An example session looks like this:

 

CREATE EVENT SESSION [PerfStats_LWP_Plan_All] ON SERVER
ADD EVENT sqlserver.query_post_execution_plan_profile(
ACTION(sqlos.scheduler_id,sqlserver.database_id,sqlserver.is_system,sqlserver.plan_handle,sqlserver.query_hash_signed,sqlserver.query_plan_hash_signed,sqlserver.server_instance_name,sqlserver.session_id,sqlserver.session_nt_username,sqlserver.sql_text))
ADD TARGET package0.event_file(SET filename=N'C:\Temp\PerfStats_LWP_Plan_All.xel',max_file_size=(50),max_rollover_files=(2))
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)
GO

 

For this example, I ran the same query as in the query_thread_profile example. So, let’s see the resulting session output:

 

query_post_execution_plan_profile XE

Same as in the previous example, clicking on the tab Query Plan shows me the actual execution plan, where again I see information on how many actual rows of estimated rows flowed through the operators.

 

 

Same as in the previous example, the query text is not shown.

 

Pedro Lopes ( @SQLPedro ) – Senior Program Manager