Using xEvents to capture an Actual Execution Plan
Published Apr 01 2019 01:39 PM 19K Views
Microsoft

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 XEquery_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_plansys.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 SSMSFind 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 - NodeIdFind 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 Planquery_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 XEquery_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.

 

image013.png

 

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 XEquery_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.

 

image013.png

 

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

 

Pedro Lopes ( @SQLPedro ) – Senior Program Manager

13 Comments
Copper Contributor

Thanks for the post! How is the new query_post_execution_plan_profile different from query_plan_profile? And does it still require the usage of the QUERY_PLAN_PROFILE hint?

Copper Contributor

This is fabulous. I'm excited to see that we continue to move toward a lower impact way of getting actual plans and runtime stats.  Hoping to see wait stats in these plan , too. Cheers. 

Brass Contributor

[sqlserver.query_thread_profile] event is really cool stuff for dbas.

 

but this event only returns greater-than-zero value of [total_time_us] on SOME condition which I haven't figure out yet,.

can you specify the condition?

I try to use this data column as [sqlserver.query_thread_profile] for events so my event session won't flood by plan nodes event data

 

"okay, I want to collect all that plan nodes that exceed total_time_us greater than 10000 microseconds)"

Microsoft

Not sure I understand what condition you're referring to. You can filter on cpu_time or duration with the filter you want.

Brass Contributor

i’m sorry I made a little bit of confusion.

 

I would like to make a filter on [total_time_us] data column of [sqlserver.query_thread_profile] event. but they barely return non-zero value.

 

Also, aren't [cpu time] and [duration] columns of the [rpc completed] event?

Brass Contributor

* column description of sqlserver.query_thread_profile.[total_time_us] is following..

 -- Cumulative time in microseconds, including waits

* and this is a query of my event session

create event session [somesession] on server
add event [sqlserver.query_thread_profile
( action (
  sqlserver.database_id,
  sqlserver.is_system,
  sqlserver.plan_handle,
  sqlserver.query_hash_signed,
  sqlserver.query_plan_hash_signed,
  sqlserver.sql_text)
 where sqlserver.database_id > 4  -- all plan nodes from user database
 and sqlserver.is_system = 0  -- non system queries
 and [total_time_us] > 100000 -- all plans exceeding 100 milliseconds, I tried 10, 100, 5.
) add target package0.ring_buffer(SET max_memory=(4096))

and even I ran a stored procedure (simple select query) which took longer that 5 seconds, but data greater than 0 barely had been collected.

also sql version I tested is 'Microsoft SQL Server 2017 (RTM-CU17)'

 

Brass Contributor

forget about previous comment. I should have read BOL carefully. 

 

It seems it is not enable to show detailed information (ex)cpu cost, total_tims_us.,) without using standard profiling infrastructure.

I would like to collect any resource information using light weight profiling, but not it is not easy to collect without additional work. (like adding set statistics profile on every stored procedure..)

 

can It be more easier? any plan for updating?

Brass Contributor

Because, In production env. there is no signal for slow query will be executing any time. that is why I need to be prepare, collecting any queries and any query execution plans to capture that slow query. 


also it looks almost impossible to ask to devs that "hey guys can you add hint QUERY_PLAN_PROFILE on every queries for query monitoring?"

it sounds more like an impossible options to use in real life..

 

Microsoft

The XE we've been talking about is a troubleshooting XE, if I understood you, you want to run it 24x7 to detect "slow queries"? I suggest you use the Query Store for that purpose.

If that wasn't your scenario, then please explain your scenario carefully, and enter a feedback item at https://aka.ms/sqlfeedback.

Brass Contributor

@Pedro Lopes  
yes, that is our scenario. 24x7 to detect "slow queries"?


we use XE as local profiler that always drops events if there is any pressure on server. and this let us to analyze workload when problem appears.

wait completed and rpc completed events and a few more events are helpful but event for plans are expensive events for a profiler.

so I found light weight profiling and was thinking maybe I could use it for analyzing slow queries.

 

now I am thinking "Query store" feature that you suggested for detecting and analyzing slow queries in real-time.

 

Thank you.

Brass Contributor

query_post_execution_plan_profile

I Think this event is very useful also powerful, we don't need to use HINT or SET command and also using light weight profiling structure so that has less overhead of performance. following this article it is only about 2%(Developers Choice: Query progress - anytime, anywhere | Microsoft Docs)

 

I would rather use this one than QueryStore and the reason is that I can specify the condition I want to monitor. (ie, duration greater that 100 millisecond, cpu time greater than 100000 microsecond)

 

I can do query monitoring 24X7 only with 2% deal with performance. how fantastic it is!

Brass Contributor

For the engineers those who got a bit confused like me.

 

There are 3 version of lightweight profiling(https://docs.microsoft.com/en-us/sql/relational-databases/performance/query-profiling-infrastructure...)

 

and some resources might not be collected due to selection of lightweight profiling version.

Please make sure to confirm which version you are using.

 

"Unlike standard profiling, lightweight profiling does not collect CPU runtime information. However, lightweight profiling still collects row count and I/O usage information......" - LightWeight Profiling v1

 

Copper Contributor

nice example for me.

i'm using this Events :

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) Where database_id = 19)
ADD TARGET package0.event_file(SET filename=N'T:\XE\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 capturing and forcing a good plan in SQL2014

Version history
Last update:
‎Apr 02 2019 08:37 AM
Updated by: