1

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?

migrated from stackoverflow.com Oct 27 '11 at 0:45

This question came from our site for professional and enthusiast programmers.

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

  • yep I'm using SQL 2005. Glad to see this is a bug that was resolved. – Equixor Dec 25 '11 at 20:09

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.