There’s a Bug in sys.dm_exec_query_plan_stats.
When you turn on last actual plans in SQL Server 2019 and newer:
|
1 |
ALTER DATABASE SCOPED CONFIGURATION SET LAST_QUERY_PLAN_STATS = ON; |
The system function sys.dm_exec_query_plan_stats is supposed to show you the last actual query plan for a query. I’ve had really hit-or-miss luck with this thing, but my latest struggle with it is that two of the numbers are flat out wrong. It mixes up CPU time and elapsed time.
Here’s a simple query to prove it:
|
1 2 3 4 5 6 7 |
SET STATISTICS TIME ON; SELECT TOP 101 value FROM GENERATE_SERIES(-10000000, 10000000) ORDER BY 1 DESC; SET STATISTICS TIME OFF; |
That query goes parallel, burns a lot of CPU, and finishes in a few seconds:
|
1 2 |
SQL Server Execution Times: CPU time = 7467 ms, elapsed time = 3106 ms. |
CPU time is higher than elapsed time, indicating that the query went parallel across multiple cores. The SET STATISTICS TIME numbers are correct, as are the time numbers in the actual query plan.
But if you check the last “actual” query plan in sys.dm_exec_query_plan_stats:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 |
WITH XMLNAMESPACES (DEFAULT 'http://schemas.microsoft.com/sqlserver/2004/07/showplan') SELECT stmt_text = SUBSTRING(st.text, (qs.statement_start_offset/2) + 1, ((CASE qs.statement_end_offset WHEN -1 THEN DATALENGTH(st.text) ELSE qs.statement_end_offset END - qs.statement_start_offset)/2) + 1), truth_cpu_ms = qs.last_worker_time / 1000, truth_elapsed_ms = qs.last_elapsed_time / 1000, plan_xml_CpuTime = qps.query_plan.value('(//QueryTimeStats/@CpuTime)[1]', 'bigint'), plan_xml_ElapsedTime = qps.query_plan.value('(//QueryTimeStats/@ElapsedTime)[1]', 'bigint'), plan_xml = qps.query_plan FROM sys.dm_exec_query_stats qs CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) st CROSS APPLY sys.dm_exec_query_plan_stats(qs.plan_handle) qps WHERE st.text LIKE '%GENERATE_SERIES(-10000000, 10000000)%' AND st.text NOT LIKE '%dm_exec_query_plan_stats%'; |
The numbers are exactly backwards:
The last “actual” plan says the query took 8 seconds (it didn’t) and that it burned less CPU time than elapsed time. The numbers are just transposed.
I’ve filed a bug about this, but this is where it gets tricky as a script author. Sure, for now, I can simply reverse the numbers in my First Responder Kit scripts, fixing Microsoft’s error, but … now I gotta watch every upcoming set of Cumulative Update notes, reading to see if they fixed the bug, then go back to any relevant scripts, put in build number checking, and flip the math for the corrected builds.
Free, 3× a week
Get my new posts by email
Three posts a week, plus a Monday roundup of the best database news from around the web.
Thanks for taking the time to document and report this bug!
“…but … now I gotta watch every upcoming set of Cumulative Update notes…”
And imagine if they take as long to address this, as they did to address the singularly unhelpful “String or binary data would be truncated” error message. Twenty something years wasn’t it?
Marketing boss: “Is fixing this the most profitable use of our time? Does it bring in new customers?”
Dev team: “Well, not directly, but there’s such a thing as attention to deta…”
Marketing boss: “The hell are you talking about?!?!?! Are we going to have to have that ‘workplace attitudes’ discussion again?”
Dev team: “So back to planning the new name, skin and relaunch for Fabric 2.0?”
Marketing boss: “That’s the way, team! Go get ’em!”
[…] Brent Ozar finds a bug: […]
Thanks for letting us mere mortals know!
Can elapsed time ever be bigger than cputime?
If not, you can add a check ‘if elapsedtime > cputime: we’re in bugland; else: they finally fixed the bloody thing’.
Yep, it usually is. Blocking, for example, or waiting on storage.
I don’t suppose you’ve noticed sys.dm_exec_query_stats leaving out statements that have clearly run (i.e. output and Include Actual Execution Plan show it happen)? I’ve seen this happen a couple of times now in SQL Server 2025 using this query…
select top 100
object_name( txt.objectid, txt.[dbid] ) as ObjectName, t1.Execution_Count,
(t1.Total_Physical_Reads / t1.Execution_Count) as AvgPhysReads, (t1.Total_Logical_Reads / t1.Execution_Count) as AvgLogReads,
(t1.Total_Logical_Writes / t1.Execution_Count) as AvgWrites, (t1.Total_Spills / t1.Execution_Count) as AvgSpills,
(t1.Total_Worker_Time / (t1.Execution_Count * 1000.0)) as AvgCPU, (t1.Total_Elapsed_Time / (t1.Execution_Count * 1000.0)) as AvgDuration,
replace( replace( substring( txt.[text], (t1.statement_start_offset / 2) + 1, 250 ), char (13), ‘ ‘ ), char (10), ‘ ‘ ) as SQL_Statement
from sys.dm_exec_query_stats as t1
cross apply sys.dm_exec_sql_text( t1.[sql_handle] ) as txt
where (object_name( txt.objectid, txt.[dbid] ) = ‘[stored proc name]’)
order by ObjectName asc, t1.statement_start_offset asc;
I can’t diagnose that query quickly, but whenever you notice it happen, your best bet is to gather screenshot evidence, and then try to reverse engineer what’s causing it so that you can build a standalone demo to reproduce it. I know it’s a lot of work, for sure – whenever I deal with one of these, it’s hours worth of work – but it’s the only way you can get attention to the bug.