Performance Tuning / SQL Server DBA / sqlLAB

Querying Wait Statistics – Head to Head

In this blog post, I have modified Paul Randal’s Wait Stats query and compare the relative efficiency of the two versions. It is a little unthinkable to go head-to-head with Paul Randal, who is a legend in the SQL Server community. However, when I ran Randal’s query I was surprised by how long it took. So I began to dissect the query, eliminating the most expensive operations to develop a useful, cut-back version.

Before beginning, I would like to establish my respect and awe of Paul Randal’s knowledge of the inner workings of SQL Server. He is a MVP, blogs prolifically, tours the world to instruct and share… Many of us could work a lifetime in this industry and still not hold a sensible conversation in his presence. But recently, we have been discussing the importance of understanding your tool-sets and not blindly trusting that someone else’s script will do as you expect. So when I first ran Randal’s wait stats script, I was surprised to find myself waiting… I decided to search for the bottlenecks.

The script I grabbed was from SQLSkills,  Tell Me Where is Hurts (Paul Randall, Dec 2010). If you’re thinking about beginning with wait stats, this is a sensational blog to get you started and gives you a feel for the depth of knowledge that Randall possesses. And here it is, the original script which we will call Version 1.0:

WITH [Waits] AS
(SELECT
    [wait_type],
    [wait_time_ms] / 1000.0 AS [Wait Time (sec)],
    ([wait_time_ms] - [signal_wait_time_ms]) / 1000.0 AS [Resource (sec)],
    [signal_wait_time_ms] / 1000.0 AS [Signal (sec)],
    [waiting_tasks_count] AS [WaitCount],
    100.0 * [wait_time_ms] / SUM ([wait_time_ms]) OVER() AS [Percentage],
    ROW_NUMBER() OVER(ORDER BY [wait_time_ms] DESC) AS [RowNum]
FROM sys.dm_os_wait_stats
WHERE [wait_type] NOT IN (
    N'BROKER_EVENTHANDLER',          N'BROKER_RECEIVE_WAITFOR',
    N'BROKER_TASK_STOP',             N'BROKER_TO_FLUSH',
    N'BROKER_TRANSMITTER',           N'CHECKPOINT_QUEUE',
    N'CHKPT',                        N'CLR_AUTO_EVENT',
    N'CLR_MANUAL_EVENT',             N'CLR_SEMAPHORE',
    N'DBMIRROR_DBM_EVENT',           N'DBMIRROR_EVENTS_QUEUE',
    N'DBMIRROR_WORKER_QUEUE',        N'DBMIRRORING_CMD',
    N'DIRTY_PAGE_POLL',              N'DISPATCHER_QUEUE_SEMAPHORE',
    N'EXECSYNC',                     N'FSAGENT',
    N'FT_IFTS_SCHEDULER_IDLE_WAIT',  N'FT_IFTSHC_MUTEX',
    N'HADR_CLUSAPI_CALL',            N'HADR_FILESTREAM_IOMGR_IOCOMPLETION',
    N'HADR_LOGCAPTURE_WAIT',         N'HADR_NOTIFICATION_DEQUEUE',
    N'HADR_TIMER_TASK',              N'HADR_WORK_QUEUE',
    N'KSOURCE_WAKEUP',               N'LAZYWRITER_SLEEP',
    N'LOGMGR_QUEUE',                 N'ONDEMAND_TASK_QUEUE',
    N'PWAIT_ALL_COMPONENTS_INITIALIZED',
    N'QDS_PERSIST_TASK_MAIN_LOOP_SLEEP',
    N'QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP',
    N'REQUEST_FOR_DEADLOCK_SEARCH',  N'RESOURCE_QUEUE',
    N'SERVER_IDLE_CHECK',            N'SLEEP_BPOOL_FLUSH',
    N'SLEEP_DBSTARTUP',              N'SLEEP_DCOMSTARTUP',
    N'SLEEP_MASTERDBREADY',          N'SLEEP_MASTERMDREADY',
    N'SLEEP_MASTERUPGRADED',         N'SLEEP_MSDBSTARTUP',
    N'SLEEP_SYSTEMTASK',             N'SLEEP_TASK',
    N'SLEEP_TEMPDBSTARTUP',          N'SNI_HTTP_ACCEPT',
    N'SP_SERVER_DIAGNOSTICS_SLEEP',  N'SQLTRACE_BUFFER_FLUSH',
    N'SQLTRACE_INCREMENTAL_FLUSH_SLEEP',
    N'SQLTRACE_WAIT_ENTRIES',        N'WAIT_FOR_RESULTS',
    N'WAITFOR',                      N'WAITFOR_TASKSHUTDOWN',
    N'WAIT_XTP_HOST_WAIT',           N'WAIT_XTP_OFFLINE_CKPT_NEW_LOG',
    N'WAIT_XTP_CKPT_CLOSE',          N'XE_DISPATCHER_JOIN',
    N'XE_DISPATCHER_WAIT',           N'XE_TIMER_EVENT')
)
SELECT
    [W1].[wait_type] AS [WaitType],
    [W1].[Wait Time (sec)],
    [W1].[Resource (sec)],
    [W1].[Signal (sec)],
    [W1].[WaitCount],
    [W1].[Percentage],
    [W1].[Wait Time (sec)] / [W1].[WaitCount] as [Mean Wait Time (sec)],
    [W1].[Resource (sec)] / [W1].[WaitCount] as [Mean Resource Wait (sec)],
    [W1].[Signal (sec)] / [W1].[WaitCount] as [Mean Signal Wait (sec)]
FROM [Waits] AS [W1]
INNER JOIN [Waits] AS [W2]
    ON [W2].[RowNum] <= [W1].[RowNum]
GROUP BY [W1].[RowNum], [W1].[wait_type], [W1].[Wait Time (sec)],
         [W1].[Resource (sec)], [W1].[Signal (sec)], [W1].[WaitCount], [W1].[Percentage]
HAVING SUM ([W2].[Percentage]) - [W1].[Percentage] < 95; -- percentage threshold
GO

Very very briefly, this script looks into sys.dm_os_wait_stats and returns the top 95 % of wait types (excluding the long list of uninteresting wait types). When I ran this on my test system, I was surprised by how long it took as shown in Figure 1 below:

Fig. 1: Version 1.0 Execution Statistics. With the statistics for IO and Time enabled, we can see that Version 1.0 took nearly 7 seconds and 6667 logical reads to execute.

with the statistics for IO and Time enabled, we can see that Version 1.0 took nearly 7 seconds and 6667 logical reads to execute.

Having decided to figure out what was taking so long, I began to inspect the query more carefully. Looking over the query there are some operations that standout as being potentially greedy, in particular the INNER JOIN and GROUP BY statements. Indeed if you look at the profile statistics, we can see that the INNER JOIN features highly, along with the aggregate GROUP BY,  some expensive sort operations, some spooling and the filter on the WHERE clause:

Fig. 2: Profile Statistics for Version 1.0 The profile statistics of Version 1.0 support the hypothesis that the INNER JOIN and GROUP BY clause are particularly expensive. Also highlighted are the CPU costs of the sort operations and the filter in the WHERE clause.

Fig. 2: Profile Statistics for Version 1.0
The profile statistics of Version 1.0 support the hypothesis that the INNER JOIN and GROUP BY clause are particularly expensive. Also highlighted are the CPU costs of the sort operations and the filter in the WHERE clause.

 

We can also see this information in the query plan, which clearly shows the relative costs of the sort and filter operations and the complexity of the plan (branching and table spools) reflect the use of the join and aggregate operations. The plan is surprisingly complicated, so unfortunately I haven’t included it in this post.

Given this information, what do we tackle? The WHERE clause is required and actually significantly reduces the overall workload, so I am not going to touch this. And I am not convinced that the sort operations are really at fault. I still feel that the plan is being made unnecessarily complicated by the join, so this will be my first target. Let’s simply remove it:

Fig. 3: Version 1.1 Removal of INNER JOIN resulted in a divide by zero error.

Fig. 3: Version 1.1
Removal of INNER JOIN resulted in a divide by zero error.

 

This is a shame, it seems that by removing the join the averaged values ([Mean Wait Time (sec)], [Mean Resource Wait (sec)], [Mean Signal Wait (sec)]) encounter a divide by zero error. We can remove this by commenting out the averaged values, but this results in 600 rows returned instead of the 50 rows from Version 1.0. So it seems there is more to the join than I first thought.

At first, I wasn’t entirely sure what the INNER JOIN achieved. However, a closer look shows that Randall is only interested in wait types that make up the top 95 % of waits and the INNER JOIN facilitates this. Let’s be a little more cut-throat with this. It seems unlikely that we will run this query on a system where users are not complaining of performance problems – and if we did, well it wouldn’t really matter. So let’s assume that we are on a system and investigating performance bottlenecks. It is also probable that there will be specific wait types that are problematic, and that these will dominate the wait stats. With this in mind, here is Version 1.2 which returns the top 24 wait types on the system:

Fig. 4: Version 1.2 Return the top 24 wait types.

Fig. 4: Version 1.2
Return the top 24 wait types.

This is better, the top(24) and the order by clause return results effectively the same as the original Version 1.0, although we have lost the summary averages. If we turn on the time and io statistics, we can see a massive improvement in each:

Fig 5: Version 1.2 Execution Statistics Version 1.2 shows a dramatic improvement over the original Version 1.0 with a small cost in the information returned.

Fig 5: Version 1.2 Execution Statistics
Version 1.2 shows a dramatic improvement over the original Version 1.0 with a small cost in the information returned.

And further, the execution plan is now much simpler:

Fig. 6: Version 1.2 Execution Plan. By removing the inner join, the execution plan is much simpler.

Fig. 6: Version 1.2 Execution Plan.
By removing the inner join, the execution plan is much simpler.

However, we have introduced a new sort operation which is now 40 % of the overall execution cost, and we have lost some information by removing the averages. All-in-all though, I think these are a small price to pay compared to the overall performance improvement. We have removed the expensive join and aggregate, reduced the total number of sort operations and improved the table spooling. The profile statistics for Version 1.2 are below:

Fig 7: Version 1.2 Profile Statistics. The total number of operations have reduced fro 38 to 13, and the overall balance of this operations is far more even.

Fig 7: Version 1.2 Profile Statistics.
The total number of operations have reduced fro 38 to 13, and the overall balance of this operations is far more even.

Finally, to tidy up this query there are some more elements that we can trim out. Removing the join makes the GROUP BY redundant. Although a matter of personal style, I find ranking functions particularly contrived and now that we have removed the join there is no need for it. Finally, let’s include the averaged columns back into our query by filtering the CTE on wait types where the wait time is greater than 1 second. Our final query, Version 2.0 is shown below:


with [waits] as
( 
    select
        [wait_type],
        [wait_time_ms] / 1000.0 as [Wait Time (sec)],
        ([wait_time_ms] - [signal_wait_time_ms]) / 1000.0 as [Resource (sec)],
        [signal_wait_time_ms] / 1000.0 as [Signal (sec)],
        [waiting_tasks_count] as [WaitCount],
        100.0 * [wait_time_ms] / sum ([wait_time_ms]) over() as [Percentage]
    from sys.dm_os_wait_stats
    where [wait_type] NOT IN (
        N'BROKER_EVENTHANDLER',             N'BROKER_RECEIVE_WAITFOR',
        N'BROKER_TASK_STOP',                N'BROKER_TO_FLUSH',
        N'BROKER_TRANSMITTER',              N'CHECKPOINT_QUEUE',
        N'CHKPT',                           N'CLR_AUTO_EVENT',
        N'CLR_MANUAL_EVENT',                N'CLR_SEMAPHORE',
        N'DBMIRROR_DBM_EVENT',              N'DBMIRROR_EVENTS_QUEUE',
        N'DBMIRROR_WORKER_QUEUE',           N'DBMIRRORING_CMD',
        N'DIRTY_PAGE_POLL',                 N'DISPATCHER_QUEUE_SEMAPHORE',
        N'EXECSYNC',                        N'FSAGENT',
        N'FT_IFTS_SCHEDULER_IDLE_WAIT',     N'FT_IFTSHC_MUTEX',
        N'HADR_CLUSAPI_CALL',               N'HADR_FILESTREAM_IOMGR_IOCOMPLETION',
        N'HADR_LOGCAPTURE_WAIT',            N'HADR_NOTIFICATION_DEQUEUE',
        N'HADR_TIMER_TASK',                 N'HADR_WORK_QUEUE',
        N'KSOURCE_WAKEUP',                  N'LAZYWRITER_SLEEP',
        N'LOGMGR_QUEUE',                    N'ONDEMAND_TASK_QUEUE',
        N'PWAIT_ALL_COMPONENTS_INITIALIZED',N'QDS_PERSIST_TASK_MAIN_LOOP_SLEEP',
        N'QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP',
        N'REQUEST_FOR_DEADLOCK_SEARCH',     N'RESOURCE_QUEUE',
        N'SERVER_IDLE_CHECK',               N'SLEEP_BPOOL_FLUSH',
        N'SLEEP_DBSTARTUP',                 N'SLEEP_DCOMSTARTUP',
        N'SLEEP_MASTERDBREADY',             N'SLEEP_MASTERMDREADY',
        N'SLEEP_MASTERUPGRADED',            N'SLEEP_MSDBSTARTUP',
        N'SLEEP_SYSTEMTASK',                N'SLEEP_TASK',
        N'SLEEP_TEMPDBSTARTUP',             N'SNI_HTTP_ACCEPT',
        N'SP_SERVER_DIAGNOSTICS_SLEEP',     N'SQLTRACE_BUFFER_FLUSH',
        N'SQLTRACE_INCREMENTAL_FLUSH_SLEEP',
        N'SQLTRACE_WAIT_ENTRIES',           N'WAIT_FOR_RESULTS',
        N'WAITFOR',                         N'WAITFOR_TASKSHUTDOWN',
        N'WAIT_XTP_HOST_WAIT',              N'WAIT_XTP_OFFLINE_CKPT_NEW_LOG',
        N'WAIT_XTP_CKPT_CLOSE',             N'XE_DISPATCHER_JOIN',
        N'XE_DISPATCHER_WAIT',              N'XE_TIMER_EVENT')
    and [wait_time_ms] > 1000
)
select
    [wait_type],
    [Wait Time (sec)],
    [Resource (sec)],
    [Signal (sec)],
    [WaitCount],
    [Percentage],
    [Wait Time (sec)] / [WaitCount] as [Mean Wait Time (sec)],
    [Resource (sec)] / [WaitCount] as [Mean Resource Wait (sec)],
    [Signal (sec)] / [WaitCount] as [Mean Signal Wait (sec)]
from [Waits]
where [Percentage] > 5
order by [Percentage] desc;
go

Turning the time and io statistics on, we can see that Version 2.0 delivers at a fraction of the cost of Version 1.0:

Fig 8: Version 2.0 Execution Statistics. Version 2.0 performs significantly better than Version 1.0 and still retains effectively the same information.

Fig 8: Version 2.0 Execution Statistics.
Version 2.0 performs significantly better than Version 1.0 and still retains effectively the same information.

Overall, we have improved performance and retained the intent of the original query. Version 2.0 suffices to begin an investigation into the source of wait times in SQL Server.

 

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s