THE SQL Server Blog Spot on the Web

Welcome to SQLblog.com - The SQL Server blog spot on the web Sign in | |
in Search

SQLOS Team

A blog for members of the SQL Server SQLOS team to share information and get your feedback.

When was sys.dm_os_wait_stats last cleared?

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/
Published Saturday, November 12, 2011 8:24 PM by SQLOS Team

Comment Notification

If you would like to receive an email when updates are made to this post, please register here

Subscribe to this post's comments using RSS

Comments

 

GrumpyOldDBA said:

Neat!

November 14, 2011 6:39 AM
 

Neil Hambly said:

I put together a Query I used for determine elapsed time the stats have been running for, I demo'd this @ my Waits session during @ SQLPASS 2011

it shows quickly the runtime of the SQL instance, Stats elapsed time and the cleared time

Waitfor time '21:50:00'

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

Waitfor time '22:00:00' -- run code below

So we are looking @ a 10 minute window of time for stats to accumulate

using 'LAZYWRITER_SLEEP' as my ticker (it's about right)

Stats_Refresh 0 Days : 0 Hours :  9 Minutes : 59 Seconds

SQL_Elapsed 5 Days : 1 Hours : 45 Minutes : 47 Seconds

Duration_no stats 5 Days : 1 Hours : 35 Minutes : 48 Seconds

with 'SQLTRACE_INCREMENTAL_FLUSH_SLEEP' as you have suggested

in the article for my ticker I don't get the expected results

?? this isn't right... or I have some issue with my test server

Stats_Refresh       0 Days : 0 Hours :  2 Minutes : 30 Seconds  

SQL_Elapsed 5 Days : 1 Hours : 45 Minutes : 47 Seconds

Duration_no stats   5 Days : 1 Hours : 43 Minutes : 17 Seconds

code

Waitfor time '21:50:00'

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

Waitfor time '21:52:00'

declare

@Days int, @Days2 int, @Days3 int,

@Date datetime, @Date2 datetime, @Date3 datetime,

@Seconds int, @Seconds2 int, @seconds3 int

SELECT @Date2 = CRDATE

FROM sysdatabases

WHERE NAME='tempdb'

SELECT

@Seconds = waiting_tasks_count

,@Date = dateadd(ss, @Seconds, '01/01/1900')

,@Days = datediff(dd, '01/01/1900', dateadd(ss, @Seconds, '01/01/1900'))

FROM sys.dm_os_wait_stats

WHERE wait_type = 'LAZYWRITER_SLEEP';

SELECT

@Seconds2 = datediff(SS, CRDATE,GETDATE())

,@Date2 = dateadd(ss, @Seconds2, '01/01/1900')

,@Days2 = datediff(dd, '01/01/1900', dateadd(ss, @Seconds2, '01/01/1900'))

FROM sysdatabases

WHERE NAME='tempdb'

SELECT

@Seconds3 = @Seconds2 - @Seconds

,@Date3 = dateadd(ss, @Seconds3, '01/01/1900')

,@Days3 = datediff(dd, '01/01/1900', dateadd(ss, @Seconds3, '01/01/1900'))

select

 ltrim(str(@Days)) + ' Days : '

+ ltrim(str(datepart(hh, @Date)))  + ' Hours : '

+ ltrim(str(datepart(mi, @Date)))  + ' Minutes : '

+ ltrim(str(datepart(ss, @Date)))  + ' Seconds' AS [Stats_Refresh]

, ltrim(str(@Days2)) + ' Days : '

+ ltrim(str(datepart(hh, @Date2)))  + ' Hours : '

+ ltrim(str(datepart(mi, @Date2)))  + ' Minutes : '

+ ltrim(str(datepart(ss, @Date2)))  + ' Seconds' AS [SQL_Elapsed]

, ltrim(str(@Days3)) + ' Days : '

+ ltrim(str(datepart(hh, @Date3)))  + ' Hours : '

+ ltrim(str(datepart(mi, @Date3)))  + ' Minutes : '

+ ltrim(str(datepart(ss, @Date3)))  + ' Seconds' AS [Duration_no stats]

GO

------------------------------------------------------------------------------

declare

@Days int, @Days2 int, @Days3 int,

@Date datetime, @Date2 datetime, @Date3 datetime,

@Seconds int, @Seconds2 int, @seconds3 int

SELECT @Date2 = CRDATE

FROM sysdatabases

WHERE NAME='tempdb'

SELECT

@Seconds = waiting_tasks_count

,@Date = dateadd(ss, @Seconds, '01/01/1900')

,@Days = datediff(dd, '01/01/1900', dateadd(ss, @Seconds, '01/01/1900'))

FROM sys.dm_os_wait_stats

WHERE wait_type = 'SQLTRACE_INCREMENTAL_FLUSH_SLEEP';

SELECT

@Seconds2 = datediff(SS, CRDATE,GETDATE())

,@Date2 = dateadd(ss, @Seconds2, '01/01/1900')

,@Days2 = datediff(dd, '01/01/1900', dateadd(ss, @Seconds2, '01/01/1900'))

FROM sysdatabases

WHERE NAME='tempdb'

SELECT

@Seconds3 = @Seconds2 - @Seconds

,@Date3 = dateadd(ss, @Seconds3, '01/01/1900')

,@Days3 = datediff(dd, '01/01/1900', dateadd(ss, @Seconds3, '01/01/1900'))

select

 ltrim(str(@Days)) + ' Days : '

+ ltrim(str(datepart(hh, @Date)))  + ' Hours : '

+ ltrim(str(datepart(mi, @Date)))  + ' Minutes : '

+ ltrim(str(datepart(ss, @Date)))  + ' Seconds' AS [Stats_Refresh]

, ltrim(str(@Days2)) + ' Days : '

+ ltrim(str(datepart(hh, @Date2)))  + ' Hours : '

+ ltrim(str(datepart(mi, @Date2)))  + ' Minutes : '

+ ltrim(str(datepart(ss, @Date2)))  + ' Seconds' AS [SQL_Elapsed]

, ltrim(str(@Days3)) + ' Days : '

+ ltrim(str(datepart(hh, @Date3)))  + ' Hours : '

+ ltrim(str(datepart(mi, @Date3)))  + ' Minutes : '

+ ltrim(str(datepart(ss, @Date3)))  + ' Seconds' AS [Duration_no stats]

November 15, 2011 5:05 PM
 

Neil Hambly said:

As this ''SQLTRACE_INCREMENTAL_FLUSH_SLEEP' is in 4 second intervals the 2:30 would equate to 10 minutes if value is *4  .. but is the 'LAZYWRITER_SLEEP' not a valid ticker for this.. we are only getting estimates after all

November 15, 2011 5:26 PM
 

SQLOS Team said:

Hi Neil. We chose SQLTRACE_INCREMENTAL_FLUSH_SLEEP because there's only one of them, so it should always be quite close to the elapsed time. I think if there's a lazy writer per NUMA node there may be cases where there's more than one of them.

Regarding sleeping for 4 second intervals, I mean that every 4 secs the wait time increases by approx 4 secs.

- Guy

November 15, 2011 5:57 PM

Leave a Comment

(required) 
(required) 
Submit
Powered by Community Server (Commercial Edition), by Telligent Systems
  Privacy Statement