When was sys.dm_os_wait_stats last cleared?

Posted by SQLOS Team on SQL Blog See other posts from SQL Blog or by SQLOS Team
Published on Sun, 13 Nov 2011 03:24:00 GMT Indexed on 2011/11/13 10:05 UTC
Read the original article Hit count: 294

Filed under:

The sys.dm_os_wait_stats DMV provides essential metrics for diagnosing SQL Server performance problems. Returning incrementally accumulating information about all the completed waits encountered by executing threads it is a useful way to identify bottlenecks such as IO latency issues or waits on locks. The counters are reset each time SQL server is restarted, or when the following command is run:

DBCC SQLPERF ('sys.dm_os_wait_stats', CLEAR);

To make sense out of these wait values you need to know how they change over time. Suppose you are asked to troubleshoot a system and you don't know when the wait stats were last zeroed. Is there any way to find the elapsed time since this happened?

If the wait stats were not cleared using the DBCC SQLPERF command then you can simply correlate the stats with the time SQL Server was started using the sqlserver_start_time column introduced in SQL Server 2008 R2:

SELECT sqlserver_start_time from sys.dm_os_sys_info

However how do you tell if someone has run DBCC SQLPERF ('sys.dm_os_wait_stats', CLEAR) since the server was started, and if they did, when? Without this information the initial, or historical, wait_stats have less value until you can measure deltas over time.

There is a way to at least estimate when the stats were last cleared, by using the wait stats themselves and choosing a thread that spends most of its time sleeping. A good candidate is the SQL Trace incremental flush task, which mostly sleeps (in 4 second intervals) and in between it attempts to flush (if there are new events – which is rare when only default trace is running) – so it pretty much sleeps all the time. Hence the time it has spent waiting is very close to the elapsed time since the counter was reset. Credit goes to Ivan Penkov in the SQLOS dev team for suggesting this.

Here's an example (excuse formatting):

144 seconds after the server was started:

select top 10 wait_type, wait_time_ms from sys.dm_os_wait_stats order by wait_time_ms desc

wait_type                                                               wait_time_ms
---------------------------------------------------------------------------------------------------------------

XE_DISPATCHER_WAIT                                      242273
LAZYWRITER_SLEEP                                          146010
LOGMGR_QUEUE                                                145412
DIRTY_PAGE_POLL                                             145411
XE_TIMER_EVENT                                               145216
REQUEST_FOR_DEADLOCK_SEARCH             145194
SQLTRACE_INCREMENTAL_FLUSH_SLEEP    144325
SLEEP_TASK                                                        73359
BROKER_TO_FLUSH                                           73113
PREEMPTIVE_OS_AUTHENTICATIONOPS       143

(10 rows affected)


Reset:

DBCC SQLPERF('sys.dm_os_wait_stats', CLEAR)"

DBCC execution completed. If DBCC printed error messages, contact your system administrator.

After 8 seconds:

select top 10 wait_type, wait_time_ms from sys.dm_os_wait_stats order by wait_time_ms desc

wait_type                                                                 wait_time_ms
---------------------------------------------------------------------------------------------------------------------

REQUEST_FOR_DEADLOCK_SEARCH              10013
LAZYWRITER_SLEEP                                           8124
SQLTRACE_INCREMENTAL_FLUSH_SLEEP     8017
LOGMGR_QUEUE                                                 7579
DIRTY_PAGE_POLL                                              7532
XE_TIMER_EVENT                                                5007
BROKER_TO_FLUSH                                            4118
SLEEP_TASK                                                         3089
PREEMPTIVE_OS_AUTHENTICATIONOPS        28
SOS_SCHEDULER_YIELD                                   27

(10 rows affected)

 

After 12 seconds:

select top 10 wait_type, wait_time_ms from sys.dm_os_wait_stats order by wait_time_ms desc

wait_type                                                                  wait_time_ms
------------------------------------------------------------------------------------------------------

REQUEST_FOR_DEADLOCK_SEARCH               15020
LAZYWRITER_SLEEP                                            14206
LOGMGR_QUEUE                                                  14036
DIRTY_PAGE_POLL                                               13973
SQLTRACE_INCREMENTAL_FLUSH_SLEEP      12026
XE_TIMER_EVENT                                                 10014
SLEEP_TASK                                                          7207
BROKER_TO_FLUSH                                             7207
PREEMPTIVE_OS_AUTHENTICATIONOPS         57
SOS_SCHEDULER_YIELD                                     28

(10 rows affected)

It may not be accurate to the millisecond, but it can provide a useful data point, and give an indication whether the wait stats were manually cleared after startup, and if so approximately when.

- Guy

 


 

Originally posted at http://blogs.msdn.com/b/sqlosteam/

© SQL Blog or respective owner