Set statistics time showing different elapsed_time than dm_exec_query_stats view

Question

When I exec a SQL statement after setting set statistics time on and running dbcc freeproccache and dbcc dropcleanbuffers I get the following output:

DBCC execution completed. If DBCC printed error messages, contact your system administrator.
DBCC execution completed. If DBCC printed error messages, contact your system administrator.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 17 ms.

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 1 ms.

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 1 ms.

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 1 ms.

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 1 ms.
SQL Server parse and compile time: 
   CPU time = 796 ms, elapsed time = 891 ms.

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 1 ms.

(0 row(s) affected)

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 9 ms.

SQL Server Execution Times:
   CPU time = 796 ms,  elapsed time = 900 ms.

SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 1 ms.

SQL Server Execution Times:
   CPU time = 796 ms,  elapsed time = 917 ms.

I then query the the sys.dm_exec_query_stats table using the following query:

select  
    OBJECT_NAME(q.objectid,q.dbid) AS ProcedureName,  
    highest_cpu_queries.creation_time,
    highest_cpu_queries.total_worker_time,
    highest_cpu_queries.total_elapsed_time,
    highest_cpu_queries.last_worker_time,
    BlockTime = highest_cpu_queries.total_elapsed_time - highest_cpu_queries.total_worker_time,
    highest_cpu_queries.execution_count,
    highest_cpu_queries.total_worker_time / highest_cpu_queries.execution_count AS avg_time,
    highest_cpu_queries.min_worker_time,
    highest_cpu_queries.max_worker_time,
    highest_cpu_queries.max_elapsed_time,
    DB_NAME(q.dbid),
    q.dbid,
    q.objectid, 
    q.number, 
    q.encrypted, 
    q.[text]
from  
    (select top 50  
        qs.plan_handle,  
        qs.creation_time,
        qs.total_worker_time, 
        qs.total_elapsed_time,
        qs.last_worker_time,
        qs.min_worker_time,
        qs.max_worker_time,
        qs.max_elapsed_time,
        qs.execution_count
    from  
        sys.dm_exec_query_stats qs 
    order by qs.total_worker_time desc) as highest_cpu_queries 
    cross apply sys.dm_exec_sql_text(plan_handle) as q 
order by highest_cpu_queries.total_worker_time desc

This returns 1 row as expected (since the dbcc commands reset the view). The total_elapsed_time column shows 8830 (946 total_worker_time + 7884 blocktime).

Total_elapsed_time according to msdn is in microseconds but only accurate to milliseconds.

So this should be 8-9ms. Set Statistics time above is showing 917ms.

My understanding was the dm_exec_query_stats view captures the same numbers as Set Statistics Time. Why are the elapsed times reported different?

Answer 1

What version of SQL Server are you using? This is/was a known issue and was fixed in SQL 2008 SP1 but wasn't ported back to SQL 2005.

http://connect.microsoft.com/SQLServer/feedback/details/487838/cpu-time-sys-dm-exec-query-stats-vs-set-statistics-time-on