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.
