Waits With Outsized Importance

Brent Ozar has a few wait types whose appearance in your “uh-oh” list is disproportionate to the wait type’s relative percentage:

RESOURCE_SEMAPHORE_QUERY_COMPILE – this means a query came in, and SQL Server didn’t have an execution plan cached for it. In order to build an execution plan, SQL Server needs a little memory – not a lot, just a little – but that memory wasn’t available. SQL Server had to wait for memory to become available before it could even build an execution plan. For more details and a reproduction script, check out my Bad Idea Jeans: Dynamically Generating Ugly Queries post. In this scenario, cached query plans (and small ones) may be able to proceed just fine (depending on how much pressure the server is under), but the ugly ones will feel frozen.

Read on for a couple more examples of poison wait types.

Incomplete Execution Plan Wait Stats

Brent Ozar has found an issue with query-level wait stats in SQL Server 2016 SP1:

That sounds amazing! Our server only had 609 milliseconds of wait time altogether, none of which was spent waiting on storage! Our storage must be super-blazing fast, and there’s practically no way to tune it to wait less than 609 milliseconds, right?

Spoilers:  it’s not that fast.

Hypervisor-Driven Wait Stats

Paul Randal explains that delays in the hypervisor layer could be responsible for SOS_SCHEDULER_YIELD waits in SQL Server:

Specifically, I was concerned about SOS_SCHEDULER_YIELD waits. This is a special wait type that occurs when a thread is able to run for 4ms of CPU time (called the thread quantum) without needing to get suspended waiting for an unavailable resource. In a nutshell, a thread must call into the SQLOS layer every so often to see whether it has exhausted its thread quantum, and if so it must voluntarily yield the processor. When that happens, a context switch occurs, and so a wait type must be registered: SOS_SCHEDULER_YIELD. A deeper explanation of this wait type is in my waits library here.

My theory was this: if a VM is prevented from running for a few milliseconds or more, that could mean that a thread that’s executing might exhaust its thread quantum without actually getting 4ms of CPU time, and so yield the processor causing an SOS_SCHEDULER_YIELD wait to be registered. If this happened a lot, it could produce a set of wait statistics for a virtualized workload that appears to have lots of SOS_SCHEDULER_YIELDs, when in fact it’s actually a VM performance problem and the SOS_SCHEDULER_YIELD waits are really ‘fake’.

Read on for more details, and definitely check out the link.  It was an eye-opener when I learned that SOS_SCHEDULER_YIELD didn’t mean “need more/more powerful CPUs.”

OLEDB Waits In CHECKTABLE

Lonny Niederstadt has dropped a boatload of information on us, with a four-part series looking at the OLEDB wait type when running DBCC CHECKTABLE.  Part 1 sets up the problem:

So… yeah.  Definitely a relationship between the number of pages in the heap and the number of OLEDB waits.  Something(s) increase the number of OLEDB waits beyond the number of data pages, the number of used pages and the number of reserved pages in a way that I haven’t deciphered yet, though.

Part 2 looks at what happens when logical checks run and not just physical checks:

On this very simple heap, with nearly the same number of rows as pages in the heap, the number of OLEDB wait events is nearly the same – only increased by one – when “upgrading” the checktable operation from physical_only to a checktable with logical checks.

Part 3 switches to using a clustered index, and things start getting wacky:

So how do the results match with expectations?  Whoa!!  25745 OLEDB wait events as the starting point for MAXDOP 1 and 2.  Then single-stepping up to 25752 OLEDB wait events for MAXDOP 8.  25752 is exactly 4 times the used page count of 6438 for the clustered index.  So the OLEDB wait events went from a small number more than the count of pages/rows with the heap… to almost 4 times as many with the clustered index.  *That* was a bit unexpected.

Part 4 looks at a heap with a non-clustered index:

All right.  What if we use a heap with a nonclustered include index?  Based on the table and index definition below, I expect the nonclustered include index nci_OLEDB_TEST_HEAP_NCI_INCLUDE to be remarkably similar to the clustered index we previously used.

Interesting reading so far in this series.

Finding Queries Which Generate Waits

Kendra Little explains how to find which queries are causing waits in SQL Server:

I once had an extremely busy system where we had growing CMEMTHREAD waits. This is an unusual wait, and our question was: is this being caused by a single query, just a few queries, or all queries? We were able to answer this by setting up an extended events trace and looking at waits by query, but this had some downsides:

  1. Extended Events has no GUI in 2008R2, and setting up and testing the scripts took a bit of time (more minor issue)
  2. Generating wait information by query on a very busy system generates a lot of output, so we had to be careful to set up sampling and filtering so we didn’t impact performance (more major issue)

But we were able to use this to figure out that the wait was associated with all queries, not a few queries, which helped us down our troubleshooting path.

Kendra answers this (mostly) in the context of SQL Server 2008 R2, as that was the version the questioner had, but she does mention where later versions make life easier.

Single-Query Wait Stats

Robert Davis shows off a new wait stats-related feature in 2016 SP1:

Paul’s process gives you info on every instance of a wait the query experienced and it’s very easy to aggregate those results to see the top waits and their total effect on a query. Quite often though, you don’t need a lot of detail. You don’t need to know every wait, just the top several. If you are already generating the actual query plan to have a in-depth look at the plan, wouldn’t it be nice if the query wait stats were already in there for you?

Now they are. In SQL Server 2016 (I’m told it came in SP1, but I don’t have a non-SP1 instance to verify that), the actual execution plan includes the top waits for the query execution in the plan. You can see them by clicking on the left-most (first) operator in the plan and viewing the Properties (shortcut F4). It will list the top waits right there in the properties dialog for you.

Getting single-query wait stats in the execution plan makes life so much simpler.

LOGMGR_RESERVE_APPEND

Paul Randal explains an uncommon wait stat:

Last week I was sent an email question about the cause of LOGMGR_RESERVE_APPEND waits, and in Monday’s Insider newsletter I wrote a short explanation. It’s a very unusual wait to see as the highest wait on a server, and in fact it’s very unusual to see it at all.

It happens when a thread is generating a log record and needs to write it into a log block, but there’s no space in the log to do so. The thread first tries to grow the log, and if it fails, and the database is in the simple recovery mode, then it waits for 1 second to see if log clearing/truncation can happen in the meantime and free up some space. (Note that when I say ‘simple recovery mode’, this also included a database in full or bulk_logged, but where a full backup has not been taken – i.e. the database is operating in what’s called pseudo-simple.)

Read on for more details and a repro script.

Session-Level Wait Stats

Arun Sirpal points out that SQL Server 2016 has a session-level wait stats DMV:

This tells me about the waits since my last reboot or since a manual reset of the stats. It’s probably why you should do at least time-based analysis or reset the wait stats before starting, that is if you are interested in something time specific or if you want to understand certain workloads at a given time.

So the other option is that you could go down the session level route. With the session based analysis I took the query and changed it slightly to query sys.dm_exec_session_waits_stats and also pull back the session_id that I am interested in.

I had no idea this was available, and it’s something that I’ve wanted for a very long time, so that’s excellent.

Wanted: Database-Level Wait Stats

Arun Sirpal would like to see database-level wait stats:

Wait Stats is my “go-to” thing, when you want to dig into performance issues everyone knows you will probably end up using sys.dm_os_wait_stats. You cannot use this in the Azure world, you have to use a DMV that is scoped to the database level. I think this would be a nice idea to have with the “earth” based SQL Servers – the ability to return information about all the waits encountered by threads that executed at the database level.

The connect item can be found at this link: https://connect.microsoft.com/SQLServer/feedback/details/2647332/sys-dm-db-wait-stats-dmv?tduid=(262281c4c73a682498780643b77e80d1)(256380)(2459594)(TnL5HPStwNw-KjxCoz0pGWobbq7q1MQTIw)()

I like this idea.

Looking For Wait Types

Ewald Cress uses the debugger to search for particular waits:

In this case I was looking for PREEMPTIVE_COM_RELEASE, and sys.dm_xe_map_values tells me that on my 2014 RTM instance it has an index of 01d4 hexadecimal. Crazy as it sounds, I’m going to do a simple search through the code to look for places that magic number is used. As a two-byte (word) pattern we’ll get lots of false positives, but fortunately wait types are internally doublewords, with only one bit set in the high-order word. In other words, we’re going to look for the pattern 000101d4, 000201d4, 000401d4 and so forth up to 800001d4. Ignore the meaning of when which bit is going to be set; with only sixteen permutations, it’s quick enough to try them all.

Let’s focus on sqllang as the likely source – the below would apply to any other module too.

This post reminds me that my debugger skills aren’t very good.

Categories

September 2017
MTWTFSS
« Aug  
 123
45678910
11121314151617
18192021222324
252627282930