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.
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.”
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.
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.
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.
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.
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:
- Extended Events has no GUI in 2008R2, and setting up and testing the scripts took a bit of time (more minor issue)
- 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.
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.
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.
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.
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.
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.
So here are two different ways that we can use SQL Servers wait statistics for troubleshooting purposes. Both views give us really useful information but both have different purposes. If we wanted to look back over time then the sys.dm_os_wait_stats will give us a view of wait time totals. Typically we would capture the information via a scheduled job and analyse the data for spikes during periods where issues might be suspected.
For performing real-time analysis of wait statistics then we should base queries on the sys.dm_os_waiting_tasks view where we can see accurate wait duration values as they are happening within our instance.
In my opinion wait statistics are the most important piece of information when troubleshooting SQL Server so learning about the different types is vital for anyone using SQL. Thankfully there is a wealth of really useful information about wait statistics out there; I’ve listed some of my favourite posts below.
Click through for an example, as well as links to more resources.