Investigating perfomance bottlenecks in  SQL Server 2008 by looking at wait events using the XE trace system

Introduction.

In my previous articles  SQL Server Wait Events: Taking the Guesswork out of Performance Profiling,  and Taking the Guesswork out of SQL Server Performance Profiling Part 2, I introduced the concepts of performance analysis based on wait events.

In short, the idea behind this concept is to take the response time of a SQL statement (or a batch or a user session) and split it up into CPU time and Wait time..

Earlier versions of SQL Server only maintain wait time (aggregated) on the server level, or you can see the wait times and the wait reasons, and when they actually occur in views like sysprocesses or sys.dm_os_waiting_tasks. Starting with SQL Server 2005, the wait events are finally documented in the SQL Server BOL, and more and more background is provided in blogs, KB Articles, forums etc.

A wait event ‘happens’ when the SQL Server scheduler (implemented in the SQLOS) decides to suspend a running task.

This can be because a ‘long’ operation starts, such as disk,  network I/O, or  lock. It can also happen when the allotted time quantum that a task can be active on the CPU ends. At this moment this seems to be a hard-coded 4 ms. This is the means by which that the SQL Server scheduler makes sure that every task in SQL Server gets its turn running on the CPU. By carefully looking at the way the response time is build up, one can make intelligent decisions on where to look for possible optimizations, or capacity planning: For instance, if on your SQL Server box 90% of the total used (response) time consists of I/O waits and only 10% of the time is spend on the CPU, then adding CPU capacity or upgrading to faster CPUs is unlikely to have a very large impact on response times. The same is true for individual queries. If one query spends 90% of its time waiting for I/O, then speeding up the CPU will only impact the other 10% of the response time picture.

SQL Server 2008 introduces Extended Events (XE) a new event handling system. XE is a flexible and lightweight event trace system.

The SQL Server engine is instrumented with tracing code in many locations. It is possible to trace ‘traditional’ events as existed in older SQL Trace versions, events like ‘RPC:Completed’. ‘sp_completed’, ‘lock timeout’ etc.

An exciting new tracing feature, is the means by which one can trace information about SQL Server OS (SQLOS) wait events

Each event contains a set of interesting columns that will be logged to a ‘target’. In this example, we have chosen a file. Next to the ‘default’ set of columns for an event, extra information can be logged as well. This is done by defining ‘actions’ on a traced event. Below is an example of standard columns that are logged for the event ‘wait_info’ in the package ‘sqlos‘, and for the event, ‘sql_statement_completed’ in the sqlserver package, which will also be used in the example:

Next is an example on how to setup wait event tracing and collecting information from an ‘asynchronous file target’.  Only specific events are collected for session_id=53.

First we create the ‘event session’, and start it.

After this, we can run an example query from a session with session_id=53, a count(*) query was run on a 1 million row (unindexed) table.

Example 1:

Example 2:

The next example shows how to collect the trace information from the trace files for further processing. As you can see from the example, the files is read ‘through’ a virtual function, ‘sys.fn_xe_file_target_read_file’, and the rows are returned in XML form.

The insert into the xTable counted 4938 rows. For the next summary I only collected the ‘wait_info’ ‘end’ events (1560 rows) and the ‘sql_statement_completed’ event (1 row):

Now in order to extract the CPU and Wait information and match it with the total response time, we run the following queries:

This is the result of the above queries:

So what we can see here is that the statement response time (duration) was 6156 ms (apparently, the  sqlserver.sql_statement_completed.duration is measured in microseconds)

The CPU time used was 1892 ms and the wait time for the three different wait events was 45+10+59163 ms = 59218 ms. Including the measured signal_time (the time between the end of the actual wait and the resumption of work) this nicely adds up to the total duration of the query.

For more information on the specific wait events, search the SQL Server BOL for the sys.dm_os_wait_stats view. All wait events are documented here.

It is also possible to look at each individual wait event. This can be useful to detect skew in wait durations for example. If you detect that certain I/O operations take longer than others, it might be interesting to add other XEvents to trace. Events like ‘file_read_completed’ will show which file was read and which offset within the file. The event ‘physical_page_read’, can tell which page for which file. These events can help detecting if you might be reading from slow disks or doing random I/O while you were expecting to do sequential I/Os.

This article, submitted in May, was originally scheduled for publication as part of Simple-Talk’s celebration of the launch of SQL Server 2008 next month, but has been brought forward in view of the current interest in the subject