I am trying to use the LAST_QUERY_PLAN_STATS property to save the QEP Actual of each executed statement in my repository, using DMV sys.dm_exec_query_plan_stats I am able to intercept it and save it without any problems. However, when I open one of them to check the elapsed timer in the properties tab, I find an elapsed times different from the ones found in statistics and in the QEP Actual requested at run time. Am I reading them wrong or it's an expected behavior? Do you have any ideas? I can reproduce it with a simple script: My script with statistics time The same script, but the tab with Execution plan requested run time Here is how I obtained the QEP from sys.dm_exec_query_plan_stats : select [qt].[text], [query_plan] = (SELECT TOP 1 [query_plan] FROM sys.dm_exec_query_plan_stats (a.[plan_handle])), [last_elapsed_time] = a.[last_elapsed_time] / 1000.0, a.[last_execution_time] from ( SELECT * FROM sys.dm_exec_query_stats qs WHERE creation_time > '2024-07-01 08:00:00') a CROSS APPLY (SELECT * FROM sys.dm_exec_sql_text(a.[plan_handle]) t ) qt WHERE qt.[text] LIKE '--My script%' order by 4 desc This is the QEP, with the strange Elapsed Time: This is the comparison, when we can see that the two QEP are identical so I don't get why they have different Elapsed Time

No need to fiddle with LAST_QUERY_PLAN_STATS. You can see this difference with just enabling actual execution plan and run the query. There is a very simple reason for the big difference you get. It is called SSMS. That is, it takes time to collect and render all those rows. And that time is included in the total execution time. However, the query execution ends much earlier. I would recommend that you try this with a more complex query that produces less output. Or for that matter, change the query to SELECT INTO. There will still be a difference, but not that radical

Hi @ Andrea D'Elia Refer to this doc: sys.dm_exec_query_plan_stats (Transact-SQL) When the query is simple enough, it is usually categorized as part of an OLTP workload. A simplified Showplan output is returned in the column of the returned table for: query_plansys.dm_exec_query_plan_stats Try some queries that are complex enough. Best regards, Cosmog Hong If the answer is the right solution, please click "Accept Answer" and kindly upvote it. If you have extra questions about this answer, please click "Comment".

Elapsed Time in QEP returned from sys.dm_exec_query_plan_stats is different from the one in Actual Execution Plan returned by SSMS

Accepted answer

Erland Sommarskog 106.6K Reputation points

2024-07-09T21:35:10.2733333+00:00

No need to fiddle with LAST_QUERY_PLAN_STATS. You can see this difference with just enabling actual execution plan and run the query.

There is a very simple reason for the big difference you get. It is called SSMS. That is, it takes time to collect and render all those rows. And that time is included in the total execution time. However, the query execution ends much earlier.

I would recommend that you try this with a more complex query that produces less output. Or for that matter, change the query to SELECT INTO. There will still be a difference, but not that radical
Please sign in to rate this answer.
Andrea D'Elia 20 Reputation points

2024-07-10T13:05:33.3733333+00:00

Thanks for the quick answer!
In my post I have tried to do an easy sample, to reproduce my problem.

In fact, I have a set of complex queries all with a template like "INSERT INTO xxx SELECT yyy FROM zzz" and all have a duration over 10 seconds and no output rows to render.

It seems to me that the Elapsed Time of sys.dm_exec_query_plan_stats is referring only to the SELECT node instead of the entire execution, do you think that this is possible?

I also have tried to change my sample using SELECT INTO like you suggested, but I got identical result; it's not happening in your enviroment?

Thanks for your collaboration

Erland Sommarskog 106.6K Reputation points

2024-07-10T13:08:39.3566667+00:00

I will have to check this out later.

Just to check: do you see any difference between Actual Execution Plan and using sys.dm_exec_query_plan_stats?

Andrea D'Elia 20 Reputation points

2024-07-10T13:29:10.1466667+00:00

QueryPlanStatsQEP.xml ActualQEP.xml

I have noticed differences in section QueryTimeStats and that WaitStats section doesn't appear in the QEP of sys.dm_exec_query_plan_stats.

You can see those differences in the attachments.

Erland Sommarskog 106.6K Reputation points

2024-07-10T18:13:16.4633333+00:00

OK, so that I understand correctly what your questions. We have three data points:

SET STATISTICS TIME ON

Actual query plan.

Plan retrieved with sys.dm_exec_query_plan_stats

And they all show different times for duration and CPU time.

When it comes to the first one vs. the other two, I see no cause for alarm. It is reasonable to assume that this time is somewhat higher, since it also it includes the time to start the execution. Occasionally, the difference can be more noticeable it if takes time to get the execution going. One reason for this might be that the query requires a memory grant, and that memory is not available. Or, as in your first example, it takes time for the client to consume the data.

When it comes to the other two, yes, there is all reason to expect them to be the same. I set up a query with some complexity and the execution and CPU time reported by sys.dm_exec_query_plan_stats was very low. I'm inclined to say that this is a bug.

When I compare the XML for #2 and #3 there are also other differences, like items coming in different order, and #3 does not include wait stats. These differences I can accept. But the numbers that reported should be the same in both cases.

Do you have anything you want to add here that I have missed?

Erland Sommarskog 106.6K Reputation points

2024-07-11T19:31:24.3366667+00:00

I got in touch with a contact at Microsoft, and I learnt that times we see in the QueryTimeStats are actually the time to compile and parse the query, not the time it took to execute it. So they match roughly what you see for "SQL Server parse and compile time" when you have SET STATISTICS TIME ON.

Quite surprising and not exactly intuitive, but apparently this is how it works. Note that the per-node times are the same for what you see in actual plan and the plan you retrieve with sys.dm_exec_query_plan_stats.

Andrea D'Elia 20 Reputation points

2024-07-12T09:47:30.9466667+00:00

Thanks you so much Erland for your support.

So, If I got it correctly, when I read QueryTimeStats from sys.dm_exec_query_plan_stats I'm reading the compile and parse time; I'll take the execution time from sys.dm_exec_query_stat.

Is it something that you think will be look after at Microsoft or will be a standard behaviour? I'm going to stay available for any improvements if it will be needed

Andrea D'Elia 20 Reputation points

2024-07-12T09:48:45.5333333+00:00

Thanks you so much Erland for your support.

So, If I got it correctly, when I read QueryTimeStats from sys.dm_exec_query_plan_stats I'm reading the compile and parse time; I'll take the execution time from sys.dm_exec_query_stat. Is it something that you think will be look after at Microsoft or will be a standard behaviour? I'm going to stay available for any improvements if it will be needed

Erland Sommarskog 106.6K Reputation points

2024-07-12T22:09:44.12+00:00

So, If I got it correctly, when I read QueryTimeStats from sys.dm_exec_query_plan_stats I'm reading the compile and parse time; I'll take the execution time from sys.dm_exec_query_stat.

Yes, you would need to look at last_worker_time and last_elapsed_time.

Is it something that you think will be look after at Microsoft or will be a standard behaviour? I'm going to stay available for any improvements if it will be needed

I don't want to make speculations about what they may change in the future. You can submit suggestions for improvements here: https://feedback.azure.com/d365community/forum/04fe6ee0-3b25-ec11-b6e6-000d3a4f0da0. Try to give a business case for why the change is needed, because this is something Microsoft finds important.
Sign in to comment

Share via

Elapsed Time in QEP returned from sys.dm_exec_query_plan_stats is different from the one in Actual Execution Plan returned by SSMS

1 additional answer