Click here to monitor SSC
  • Av rating:
  • Total votes: 60
  • Total comments: 8
Mario Broodbakker

SQL Server Wait Events: Taking the Guesswork out of Performance Profiling

22 March 2007

Dude, Where's my Time?

Measuring what is actually happening is always the best course of action when investigating performance issues on databases, rather than relying on cache hit ratios, or best practices, or worst of all, guesswork.

In order to solve performance issues, you may take a gamble on buying a bigger box with the fastest CPUs, only to discover that it doesn't achieve anything. Understanding and measuring is the key to improving database performance. If, for example, you measure high log write times, then you know exactly what you should do: go look for ways to speed up your log drive(s), or take away the load on the log drives from other processes or queries.

This article introduces some techniques that will allow you to pinpoint exactly where the performance issues are in your system, so you'll know exactly where to spend your time (and money) in solving them.

The YAPP Method

A long time ago in a galaxy far, far away a Dutch guy named Anjo Kolk wrote a paper called YAPP: "Yet Another Performance Profiling Method". The idea behind YAPP is simple, but powerful:

Response time = service time + wait time

In other words, you either work or you wait for a resource to become available. Even 12 years ago, when Anjo first developed the method, this was not a new idea, since this is part of basic queuing theory that many of us should know. The other key idea behind YAPP is that, when optimizing, you should start with the largest time consumer – this principle is also based on an old (Amdahl) law. What was new was that Anjo showed how to apply this principle to working with databases (he originally developed the method for Oracle), using wait events and CPU statistics.

In the Oracle world, YAPP is now a generally accepted way of looking at performance, with many tools and products that use the ideas behind the method.

NOTE:
The YAPP paper can be found at: http://www.oraperf.com/logon.html?rpage=download.php/yapp_anjo_kolk.pdf. Be warned, though, that it deals exclusively with Oracle.

The good news is that the YAPP method can be used in the SQL Server world too. With SQL Server 2005, Microsoft now documents wait events, and provides access to wait event information, through the Dynamic Management Views (DMVs). Older versions of SQL Server do provide wait statistics through the undocumented dbcc sqlperf(waitstat) command. However, apart from two smart people in the MS SQL Customer Advisory Team who started to write and present on this subject a couple of years ago (see references), Microsoft never really took the trouble to document or to promote the use of this command. Interestingly enough, most of the articles I've seen so far use wait events almost exclusively for detecting and solving locking and blocking issues. I haven't come across a paper that used them for 'simple' response time or other performance analysis.

In SQL Server2005, wait events are exposed in the DMV, sys.dm_os_wait_stats. This DMV shows the names, counts, and wait times of wait events encountered by the SQL Server engine, or to be exact the SQLOS. The SQLOS is a layer within SQL Server that, among many other things, takes care of scheduling workloads on worker processes. In SQL Server 2000 and before, this was done via the UMS, the User Mode Scheduler. This is now an integrated part of the SQLOS (see references for SQLOS and UMS, Slava Oks and Ken Henderson).

One column of sys.dm_os_wait_stats needs a little extra explanation: signal wait time. This time represents the time that the actual wait event finished, and the time the task is scheduled to run on the scheduler again. On busy schedulers this signal wait time can be an indication of CPU pressure.

Unfortunately, SQL Server only maintains wait event data at the server level. Wait events are also exposed in the DMV, sys.dm_os_waiting_tasks, but only for the duration of the wait event, which is in many cases just milleseconds (unless you ran into severe locking problems). In addition, to using dm_os_wait_stats, alternative and interesting ways of looking at live systems, can be sampling of dm_os_waiting_tasks or joining against dm_exec_sql_text or dm_exec_sql_plan, using task_address, to get complete overviews of which queries and plans cause possible excessive waits.

Performance diagnosis in SQL 2005 with wait event and CPU data

Hopefully this example will demonstrate the power of wait events combined with CPU data. Two stored procedures are used to collect wait event and CPU data. You can access the scripts to create these procedures from the links below, or from the "Code Download" link at the top of this article. These stored procedures take snapshot copies of sys.dm_os_wait_stats and sys.dm_exec_sessions. At the beginning of a test workload you execute begin_waitstats, and after the test workload is finished you execute end_waitstats. The end_waitstats procedure outputs the difference between the starting and ending snapshots.

The code to generate the workload is as follows:

SET nocount ON
EXECUTE begin_waitstats
GO
BEGIN TRANSACTION
DECLARE @rows INT
DECLARE @row INT
DECLARE @count INT

SELECT @rows 100000
SELECT @row 0
SELECT @count 0
WHILE @row @rows
BEGIN
       INSERT INTO t100k
               
(
               
c2
               
)
               
VALUES
                       (
                       
REPLICATE('a',100)
                       )
       
SELECT @row @row 1
       
IF @count 100
    
BEGIN
        COMMIT WORK
        BEGIN TRANSACTION
        SELECT @count=0
    
END
    SELECT @count=@count+1
END
COMMIT WORK
GO
EXECUTE end_waitstats

This code comprises a simple loop that creates a table and inserts 100,000 rows into it, committing every 100 rows. Note that you end your test workload with a GO. I found that the data that feeds the sys.dm_exec_session view is updated only after the batch is finished.

While executing this loop, I have an IOMeter (see references) program running that is generating 8K random reads on the transaction log disk belonging to the database in which the t100k table lives. It is running at full speed, with no queue and no pause between reads. This generates about 150 reads/sec on an idle system. This is all run on the same single CPU box on which SQL Server is running, with one SQL Scheduler.

The output of this query looks as follows (for clarity, I omitted non-relevant data)

wait_type               waits                wait_time            signal_wait_time   

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

ASYNC_NETWORK_IO        589                  150                  10

WRITELOG                998                  18317                10

 

session_id cpu_time             tot_sched_time elapsed_time

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

53         2123                 2322           20669 

NOTE:You can use the documentation in Books Online, SQL Server Language Reference: http://msdn2.microsoft.com/en-us/library/ms188754.aspx to find out the meaning of the above wait types.

What you can see here is that this query had an elapsed time (response time) of 20669 milliseconds (all times are in milliseconds). It spends 2123 ms burning CPU cycles so, according to the R=S+W formula, for the rest of the time it must have been waiting.

As you can see, the majority of the wait time is consumed by a wait type called WRITELOG. This is the time spent waiting for log information to be written to the transaction log file. The count ('waits' column) is equal, more or less, to the number of rows we inserted in the loop.

The other wait, ASYNC_NETWORK_IO, is caused by the SQL Server client program dealing with commit feedback; SQL Server needs to wait for the client to accept the data. If you look at the wait time for this event, it's very small and insignificant for this demo.

Now if you add up the (CPU) service time of 2123 and the wait time of 18317+150, you end up with 20590 ms, which is pretty close to the 20669 response (elapsed) time, taken from sys.dm_os_exec_sessions.

The average wait time for the WRITELOG wait event is 18317/998= 18ms. This is good to know, and we will use that as a reference for the next example, where we will 'optimize' the transaction log write performance

In this example, we execute the same loop, with IOMeter running the same load of around 80 random 8K reads per second on the same disk transaction log disk, but this time every read is delayed for 10 ms. This gives more headroom for the Logwriter to do its job. This is what happens to the times:

wait_type               waits                wait_time            signal_wait_time

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

ASYNC_NETWORK_IO        586                  120                  0              

WRITELOG                998                  7841                 10             

 

session_id cpu_time             tot_sched_time elapsed_time

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

53         2453                 2288           10464

What you see here is that the wait time for the log is reduced to 7841 ms, and the CPU time is relatively unchanged at 2453 ms. The total elapsed time is 10464 ms.

You see that the times don't exactly match. This trouble is, on this x86 box, the precision of the Windows timing is 10 ms, so this introduces all kinds of measurement errors. But in most cases you will see that this is within the 10% range. Even here you can see that the time this session was on the scheduler doing work (2288 ms) is more than the CPU use time, which shouldn't happen.

Anyway, the average wait time is now back to almost 8 ms per WRITELOG, so we did a pretty good job optimizing. What counts for the end user is, of course, the response time, which we've reducded to 10 seconds, compared to 20 seconds previously.

If we take out the IOMeter load completely, this is what we see:

wait_type               waits                wait_time            signal_wait_time   

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

ASYNC_NETWORK_IO        598                  70                   0                  

WRITELOG                998                  160                  0                   

 

session_id cpu_time             tot_sched_time elapsed_time

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

53         2293                 2245           2584        

Hardly any wait time, mostly CPU and a response time of 2.5 second. So there's your time!

The great thing about these wait event statistics and CPU time measurements is that it takes the guessing out of the game. If you can measure what your application is doing with your system, then you can act accordingly.

For instance, if your SQL Server data is waiting for IO (which might be something like PAGEIOLATCHX waits) 90% of the time, and is only on the CPU 5% of the time, then buying a bigger box with the fastest CPUs won't achieve anything: you need to speed up IO response times, or reduce IO.

In our example, I tried to show that if you measure high log write times, then you should go look for ways to speed up your log drive(s), or take away the load on the log drives from other processes or queries.

As I mentioned at the start, measuring what is happening is always the best course of action. Don't rely on cache hit ratios, or best practices, or worst of all, guesswork.

Some problems and pitfalls

One of the biggest problems, I think, is the fact that the statistics are collected and exposed 'server wide' (technically they are collected per SQL Scheduler, but not exposed). This means you can only use them to say something sensible about resource utilization and response time composition on a server-wide basis. This is simply not enough, unless you have the luxury of testing your application and SQL statements on an isolated server, as in our example. But, of course, it's often hard or impossible to isolate and replicate production problems on an isolated test server.

What you really need is a "per session" or even "per statement" resource (wait and CPU usage) breakdown. Although I think it's very easy for Microsoft to implement things like this, they simply don't do it.

Another issue is that there can be quite a bit of asynchronous work going on in SQL Server, something that the Oracle world doesn't suffer from because of their process based UNIX implementation. For example, if you do a select from a table returning row data to a client, SQL Server can asynchronously scan your table, process the data, issue more I/O's and simultaneously send network packets to the client. This makes the R=S+W method slightly more difficult to use with SQL Server than it is with Oracle.

Getting "per session" stats out of SQL 2000

In the past, I have hacked into SQL Server to collect the statistics I needed, per user and per session, and performed session tracing including sql-statements, batch statistics and wait events. The collection and presentation are done by external stored procedures. I still have a small website up (http://www.sqlinternals.com/) where you can see examples, a presentation and a paper on the techniques I used, along with download code to test them yourself on SQL Server 2000.

WARNING:
My tools come with a big disclaimer: the code is based on call replacing at the machine code level, which can be very tricky and is, of course, totally unsupported in a production environment.

However, just to whet your appetitive for the sort of power you gain from being able to measure at the session level, consider the following example of what these SQL 2000 tools can do. You can pick any session (by spid), and show the wait event and CPU statistics; even for Parallel Queries it will show a breakdown per Execution Context.

A user session, executes a script that contains one CPU intensive query and one physical read intensive query is ran on a 100Mhz CPU machine (100Mhz?! yes, that old slow stuff is still great for CPU related testing purposes). There is no concurrent work going on.

The response time for this script is 160 seconds. Uisng my per session tools, you can see exactly where those 160 seconds were spent:

Spid        EC          WaitDesc           Time(ms)    Count       WaitSignalTime(ms)

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

55          0           CPU                146699      499         0                 

55          0           PAGEIOLATCH_SH     13101       483         173               

55          0           PAGEIOLATCH_UP     20          2           0                 

 

AvgWaitTime(ms)

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

293.98596

27.482401

10.0

The CPU time is about 146.7 seconds, and the wait time for physical I/O (PAGEIOLATCH_xx represents physical I/O) is around 13.1 seconds. Once you know that the major part of the response time for this user consists of CPU time then you can see immediately that upgrading CPU (speed) might help.

Following are the results obtained by doubling the CPU speed (200 MHz) and running the same script again:

Spid        EC          WaitDesc           Time(ms)    Count       WaitSignalTime(ms)

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

55          0           CPU                73579       522         0                 

55          0           PAGEIOLATCH_SH     15706       498         100               

55          0           PAGEIOLATCH_UP     28          2           0                 

 

AvgWaitTime(ms)

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

140.95593

31.738956

14.0

CPU time is almost halved, as expected since we doubled the CPU speed and the wait time for physical I/O is about 15.7 seconds. The overall response time is down to 90 seconds.

Enabling a basic wait event trace produces the following output:

Startbatch           tim=3433161, tid=0x43c, spid=51 ecid=0
user: 333 krnl: 69 ticks: 268470845

SqlExecute           tim=3433162, tid=0x43c, spid=51, ecid=0,
len=176, Stmt=SELECT COUNT(*)
FROM t1 a

                                        INNER LOOP JOIN t1 b

                                        ON b.c1 = a.c1 option (maxdop 1)

Waitaftersignal      tim=3433197, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=20, sigt=0, res=7:1:15

Waitaftersignal      tim=3433211, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=13, sigt=0, res=7:1:34

Waitaftersignal      tim=3433222, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=11, sigt=0, res=7:1:76

Waitaftersignal      tim=3433231, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=9, sigt=0, res=7:1:17

Waitaftersignal      tim=3433237, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=5, sigt=0, res=7:1:74

Waitaftersignal      tim=3433248, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=8, sigt=0, res=7:1:27

Waitaftersignal      tim=3433257, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=9, sigt=0, res=7:1:90

..etc...

Waitaftersignal      tim=3442799, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=14, sigt=0

Waitaftersignal      tim=3506860, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=16, sigt=0, res=2:1:75

Waitaftersignal      tim=3506865, tid=0x43c, spid=51, ecid=0,
WT=0x423, waited=4, sigt=0, res=2:1:2

Batchsummary         tim=3506866, tid=0x43c, spid=51, ecid=0,
user=72394, krnl=56, ela=73705

EndBatchOrSubproc    tim=3506866, tid=0x43c, spid=51, ecid=0,
(totThread:) user=72727, krnl=125

TotIOForBatch(Spid)  tim=3506866, tid=0x43c, spid=51, ecid=0,
PIO=80, LIO=51527

The SqlExecute line shows the query being executed. Each wait event generates a line with a wait type and an elapsed wait time. When the statement is finished, it's easy to see the CPU consumption of 72727 ms, which can be attributed fully to the LIO count: the statement generated a huge amount of logical I/O, out of the buffer cache I/O's, which consume only CPU cycles.

I hope this at least gives you a feel for the potential power of these techniques. I do have a version for the first SQL Server 2005 release, but I haven't spend much time developing it, and bringing it up to the same level as the SQL Server 2000 code, so it's not on there (yet?).

Summary

Despite the fact that DMVs supply only server-level (and sometimes database-level) statistics, and don't drill down to the session level, they are still a very useful tool for performance profiling and diagnosis. Other interesting scenarios are parallel queries where multiple execution contexts are working for one SPID or session in SS2005. In that case you can not simply add all the wait and CPU times together and match with the response time, but you can add times at the Execution Context level.

In a next article I will show some more examples of dealing with different wait events and how to interpret them. Both SQL Server 2000 and 2005 will be addressed.

References and further reading

Wait events

Microsoft SQL Server Development Customer Advisory Team:

http://blogs.msdn.com/sqlcat/default.aspx

Unfortunately the two guys, Gert Drapers and Tom Davidson, who published and presented on the wait event subject have both moved on to other teams. Gert has some presentations available on his website: http://www.sqldev.net/

Here also has a very good presentation on the subject and describes a lot of SQL Server 2005 wait events here: http://www.microsoft.com/technet/prodtechnol/sql/2005/tsprfprb.mspx

SQLOS

Slava Oks' Blog (where I just read he left his team also!): http://blogs.msdn.com/slavao/

Slava has some very good papers on the SQLOS subject, mostly focusing on memory management, but also on the scheduler. He also wrote excellent chapter in a new book edited by Ken Henderson: SQL Server 2005 Practical Troubleshooting. The same book has a very good chapter on SQLOS and scheduling issues, by Sameer Tejani, and a chapter called 'Waiting and blocking issues' by Santeri Voutilainen.

Ken Henderson also wrote 'The Guru's Guide to SQL Server: Architecture and Internals'. It is a bit of a strange book in my opinion, which probably should have been two books I think. The first half deals with SQL Server 2000 Internals very well, but the seconds half deals with all kinds of subjects, on a more superficial level. Some of the chapters of this book are available on MSDN. I am looking forward to his SQL Server 2005 version.

IOMeter

IOMeter is an IO stress and measurement tool developed by Intel. It is now an Open Source tool, and freely downloadable from http://www.iometer.org/.

Mario Broodbakker

Author profile:

For almost two years now, Mario has been working as an Oracle performance engineer for HP Windows Integrity Engineering in Redmond, Washington. Before that, he spent more than 10 years doing Oracle performance consultancy and benchmark work in his native Holland for HP, Compaq and Baan Development. Challenged by the lack of usable performance data in SQL Server 2000, he developed his own interface and tools, as a sort of pet project. Although his daily work is purely Oracle related it's still fun and educating to pick up the SQL Server challenge during a rainy weekend (they do exist in the Seattle area). Some of his hobby projects can be seen and downloaded at www.sqlinternals.com, Mario can be reached at mariob at sqlinternals.com.

Search for other articles by Mario Broodbakker

Rate this article:   Avg rating: from a total of 60 votes.


Poor

OK

Good

Great

Must read
Have Your Say
Do you have an opinion on this article? Then add your comment below:
You must be logged in to post to this forum

Click here to log in.


Subject: Good job
Posted by: Adam Machanic (view profile)
Posted on: Friday, March 23, 2007 at 12:17 PM
Message: Great intro to the topic of waits.

Unfortunately, the "tools" link on your Web site is broken. Please fix so we can check them out :)

Subject: fixed link
Posted by: Anonymous (not signed in)
Posted on: Friday, March 23, 2007 at 1:28 PM
Message: Thanks for reporting that, Adam. I just fixed it (and the article link, that was also messed up by my script editor).
Later today I will post SQL Server 2000 SP4 stuff too.

Subject: Exxxcellent! Very nice.
Posted by: Anonymous (not signed in)
Posted on: Saturday, April 14, 2007 at 5:17 PM
Message: Naturally, I'll tell my boss these are all my ideas... ;)

You da man! Very good work!

JR

Subject: Bravo
Posted by: Venugopal Gunti (not signed in)
Posted on: Wednesday, April 02, 2008 at 7:49 PM
Message: An interesting perception towards waits. I am glad that i have come across this article. Keep the good work, mate!

VG

Subject: www.sysinternals.com is broke again
Posted by: reddy (not signed in)
Posted on: Wednesday, June 11, 2008 at 4:35 PM
Message: Mario good work. Can you fix the web site?

Subject: Good Job
Posted by: Ashwani Roy (not signed in)
Posted on: Tuesday, June 17, 2008 at 9:41 AM
Message: thanks for the ref to salva Oks's Blog. Nice article.

Cheers
Ashwani

Subject: Thank you
Posted by: Sri (not signed in)
Posted on: Thursday, June 19, 2008 at 8:07 PM
Message: Thank you for the article.

Precious few articles on Async_Network_IO.

Subject: Greate Article Every DBA must read
Posted by: snivas (view profile)
Posted on: Tuesday, October 27, 2009 at 3:35 AM
Message: I can say only it is "Greate Article, Every DBA must read"

Thanks

 

Phil Factor
Searching for Strings in SQL Server Databases

Sometimes, you just want to do a search in a SQL Server database as if you were using a search engine like Google.... Read more...

 View the blog

Top Rated

Searching for Strings in SQL Server Databases
 Sometimes, you just want to do a search in a SQL Server database as if you were using a search engine... Read more...

Continuous Delivery and the Database
 Continuous Delivery is fairly generally understood to be an effective way of tackling the problems of... Read more...

The SQL Server Sqlio Utility
 If, before deployment, you need to push the limits of your disk subsystem in order to determine whether... Read more...

The PoSh DBA - Reading and Filtering Errors
 DBAs regularly need to keep an eye on the error logs of all their SQL Servers, and the event logs of... Read more...

MySQL Compare: The Manual That Time Forgot, Part 1
 Although SQL Compare, for SQL Server, is one of Red Gate's best-known products, there are also 'sister'... Read more...

Most Viewed

Beginning SQL Server 2005 Reporting Services Part 1
 Steve Joubert begins an in-depth tour of SQL Server 2005 Reporting Services with a step-by-step guide... Read more...

Ten Common Database Design Mistakes
 If database design is done right, then the development, deployment and subsequent performance in... Read more...

SQL Server Index Basics
 Given the fundamental importance of indexes in databases, it always comes as a surprise how often the... Read more...

Reading and Writing Files in SQL Server using T-SQL
 SQL Server provides several "standard" techniques by which to read and write to files but, just... Read more...

Concatenating Row Values in Transact-SQL
 It is an interesting problem in Transact SQL, for which there are a number of solutions and... Read more...

Why Join

Over 400,000 Microsoft professionals subscribe to the Simple-Talk technical journal. Join today, it's fast, simple, free and secure.