What are wait events and why are they important for performance analysis?

~ franklinyamamoto

While trying to get to the bottom of a SQL Server performance issue, on many occasions I’ve seen engineering teams and in some cases DBA’s start focussing on perfmon counters to determine where a SQL performance issue is coming from.  Performance counters quite often will report symptoms of a performance issue and can many times lead you down the wrong path.

In this post I will explain what wait events are and how they can help you determine the root cause of a performance issue more quickly than by starting with looking at performance counters.

What are wait events?

When a query executes it is generally doing one of two things:

  1. Using CPU
  2. Waiting on something

When I say “Waiting on something” this can be a large variety of different operations.  Some common ones I run into are:

  1. PAGEIOLATCH_* (waiting on IO of a data file)
  2. LCK_* (waiting on a lock)
  3. PAGELATCH_* (waiting to access a buffer in memory)
  4. RESOURCE_SEMAPHORE (Memory pressure internal to SQL Server)
  5. CXPACKET (parallel query execution)
  6. WRITELOG (slow transaction log performance)

The elapsed time of a query can best be broken down into the sum of the wait events it encounters + the CPU time of the query.  It is important to note, CPU time is not a wait event.

The timeline below helps illustrate what an individual query execution might look like when taking wait events and CPU time into account.

In the timeline above, the update query is submitted to SQL Server. It first consumes 5 milliseconds of CPU time.  Eventually the query does some physical IO which causes it to wait 10 milliseconds (PAGEIOLATCH_EX).  Next the query runs into lock wait (LCK_M_U) which causes the query to wait for 3,000 ms.  After the query obtains the lock it is able to complete after 7 milliseconds of CPU time.  From this we can see what the query is doing for the duration of the execution.  Based on this knowledge you can take appropriate action to resolve the performance bottle neck (i.e. find the blocking session causing the lock wait).

I’ll mention this now, but the above scenario is slightly different for parallel execution plans.  I have another post discussing this.  I’d recommend reading through this post prior to getting into waits related to parallel execution plans.

How can I view wait events

  • sys.dm_os_wait_stats
  • sys.dm_exec_requests
  • Extended Events
  • Query Store

I will discuss the first two options in this post.  The other two I will discuss in future posts since there’s enough to discuss on the sys.dm_os_wait_stats and sys.dm_exec_requests in just this post.

What is sys.dm_os_wait_stats, and why isn’t it the best way to view wait events?

So now that we know what wait events are, how do we look them up?  You can query sys.dm_os_wait_stats.  This returns statistics for all wait events that occurred since the system last restarted.  There are two limitations with this:

  1. The wait events are for all activity – they are not tied to a specific query
  2. There is no way to see when the wait events occurred

The first point is the harder of the two to address unless you happen to be on SQL Server 2017 or Azure SQL Database.  If you are not on one of these releases you will need to query sys.dm_exec_requests to see what an executing query is currently doing (waiting on something or using CPU).  The value of knowing what queries are affected by what wait events helps eliminate a lot of noise.

select * from sys.dm_os_wait_stats
order by wait_time_ms desc

The above query returns all wait types ordered by the sum of wait time (descending).  What’s interesting about the output is the first wait event that is actually affecting my workload is in the 18th row returned (WRITELOG).  In other words there is a lot of noise you need to sort through to look for wait events that are actually impacting user processes.

The second point you can work around to some extent.  You can log the output from sys.dm_os_wait_stats and perform deltas via a scheduled job in order to historically collect wait stats at scheduled intervals.  If you find yourself going down this path you should probably consider purchasing an APM tool.

What’s in sys.dm_exec_requests?

You can query sys.dm_exec_requests to see a request that is currently executing.  This will show you what the current wait event is, what query is executing, and how much CPU the executing request has consumed since it started executing.

The following query will help you see this (this query requires VIEW SERVER STATE access):

SELECT er.start_time,
er.total_elapsed_time, er.status,
er.cpu_time, er.wait_type,
er.wait_time, er.wait_resource,
er.session_id, er.blocking_session_id,
SUBSTRING(st.text, (er.statement_start_offset/2)+1,
((CASE er.statement_end_offset
WHEN -1 THEN DATALENGTH(st.text)
ELSE er.statement_end_offset
END - er.statement_start_offset)/2) + 1) AS statement_text,
convert(XML, qp.query_plan) as execution_plan
FROM sys.dm_exec_requests er
INNER JOIN sys.dm_exec_sessions s on er.session_id = s.session_id
cross apply sys.dm_exec_sql_text(er.sql_handle) st
cross apply sys.dm_exec_text_query_plan(er.plan_handle,
er.statement_start_offset,
er.statement_end_offset) qp
WHERE er.session_id != @@spid AND s.is_user_process = 1
order by 1

In the above query we are using the following 4 tables:

  1. sys.dm_exec_requests
  2. sys.dm_exec_sessions
  3. sys.dm_exec_sql_text
  4. sys.dm_exec_text_query_plan

We use sys.dm_exec_requests to retrieve what is currently executing.  We use sys.dm_exec_sessions to filter processes which are user processes (as opposed to background processes). We use sys.dm_exec_sql_text to get the text of the query currently executing. We use sys.dm_exec_text_query_plan to retrieve the execution plan of the query currently executing.

Below is the typical output of running this.Let’s look at the first row.  The start_time is when the request started executing on the server (local time relative to the server timezone).  The total_elapsed_time is the number of milliseconds the request has been executing.  The status column will typically show one of these three values:

  1. suspended
  2. running
  3. runnable

Suspended

When a request is in a suspended state it is currently in a wait event.  You will see a value in the wait_type column indicating the type of wait event that is occurring.  The wait_time will indicate how long the current instance of the wait event occurred.  In this example we were in a PAGEIOLATCH_EX (waiting on physical read) for 2 milliseconds.  It should be noted, there can be many short wait events that add up to a sizable amount of the total elapsed time.  Unfortunately there is no simple way to see the cumulative amount of wait time for short wait events unless you are on SQL 2017 or Azure SQL Database.  If you run this query multiple times back to back and consistently see the query registering the same wait event type (i.e. PAGEIOLATCH_*) it gives you a pretty decent picture of where your query is spending its time (waiting on IO).

Another column of interest is the cpu_time.  The cpu_time is cumulative for the executing request. If you subtract the total_elapsed_time column from the cpu_time you should have a decent approximation of how much time was spent in waits.  In this example we should have:

593 ms (elapsed time) – 137 ms (cpu time) = 456 ms (most likely wait time)

So if we typically see this query in a wait type of PAGEIOLATCH_*, we can make the assumption this query is likely spending most of its time waiting on physical IO.  So for this example we can probably assume that of the 593 ms of elapsed time 137 ms was using CPU and approximately 456 ms was IO related.  As a result, this would make me research the following areas (most likely in this order):

  • Is my query doing too much physical IO due to a bad execution plan?
  • Is my physical disk performance causing slow IO?
  • Do I need to increase the memory available to SQL Server to ensure data is cached in the buffer?

As you can see, we were able to identify as closely as possible a good approximation of what our query is doing when it executes.

Running

Let’s look at the second row:

We can see that this request is in a running status.  This means that at this current point in time the query was consuming CPU.  When a query is in a running status you will not see a value in the wait_type column.  Let’s look at where our query is spending its time:

545 ms (elapsed time) – 160 ms (cpu time) = 385 ms

This means there are 385 ms likely being spent in waits.  You would have to run our query against sys.dm_exec_requests a few more times to see what wait_type shows up to take an educated guess as to what waits this query is experiencing.

Runnable

Let’s look at the third row:

We can see that this query is in a runnable status.  When a query is in a runnable status it means it is not in a wait event, but it is actually queued up to get some CPU time.  There is a wait type, SOS_SCHEDULER_YIELD, that I’ve heard people equate with waiting on CPU.  I don’t think that’s totally accurate. The SOS_SCHEDULER_YIELD wait type occurs when a request using CPU yields usage of CPU in order to allow other requests to execute.  This might appear on a really busy system with lots of processors but no real CPU pressure.  I’ve found that a better indicator of CPU pressure is to watch for a large percentage of requests appearing in a runnable state whenever you query sys.dm_exec_requests.  This means there are not enough processors to service the query workload and requests are trying to get CPU time but are consistently unable to.

I’ve mentioned the Azure SQL Database and SQL 2017 query store a couple times and thought I should point this out.  The query store assumes SOS_SCHEDULER_YIELD is CPU wait.  In Azure SQL Database this might be a slightly more representative measure of CPU wait since it appears that Azure SQL Database yields more often when in lower DTU levels; however, this doesn’t seem to be quite as accurate from non Azure SQL Databases.

Long waits vs short waits

In the example above we were looking at a PAGEIOLATCH_EX wait type.  In this example the wait event was relatively short.  The reason for this is modern disk subsystems typically have pretty low IO latencies and as a result the corresponding waits for physical IO operations are relatively low.  Some wait events can be longer – a good example is a lock wait LCK_*.  I’ve found that some wait events (through experience) can typically be grouped into being long vs short.  Here’s a table that would show you what to typically expect:

Wait Type Long/Short Exceptions
PAGEIOLATCH_* Short I’ve seen these get quite high on sick disk sub systems. You might start seeing messages
similar to the following in your sql ERRORLOG: SQL Server has encountered x occurrence(s) of I/O requests taking longer than x seconds…
LCK_* Long Most of the time these are longer, but on occasion a lot of short lock waits may appear.
PAGELATCH_* Short Under high contention for PFS, GAM, or SGAM pages these can be high, but normally they are very short since they are just synchronizing access to pages in the buffer.
RESOURCE_SEMAPHORE Long On occasion this will be short, but usually they are long when they start appearing.
WRITELOG Short On very rare occasions these can be long.

That’s great, but what if the performance issue isn’t currently occurring?

As I mentioned earlier, if you are on SQL Server 2017 or Azure SQL Database you can use the new Query Store feature to view query level wait events in the past.  If not you may want to consider purchasing an APM tool capable of monitoring query level wait events (Ahem… SQLGrease).

Parting thoughts

Just the other day I was asked to look at an issue occurring at a client.  Users were complaining about long query executions.  The server engineers involved could not find an obvious problem.  The DBA involved didn’t see anything that indicated a health issue with the database.  The problem was bounced around for about two days between different groups until I got involved and followed the process I described above.  Within a few minutes of diagnosis work we determined user queries were stuck in IO waits (PAGEIOLATCH_*).  At this point we were able to research via perfmon counters which disks/luns were experiencing issues and come up with a solution to fix the problem.  The key to the solution was identifying the problem queries and what waits were affecting them.

Wait event analysis isn’t the end all be all for  analyzing performance issues.  Having the ability to view execution plans as they executed when performance issues occurred is another important piece of the equation.  I’m also not discounting the value of using perfmon counters because they can be helpful in diagnosing an OS or hardware issue.

Happy tuning!

SQLGrease and wait event analysis

How can SQLGrease help you get to the root cause of your performance problems?  Watch our demo video.

Watch us diagnose a query timeout with SQLGrease:

See how you can get query level wait events without Query Store: