Last night a #sqlhelp question from Monica Rathbun (@SQLEspresso) caught my eye:
Now some of us take way too much delight in worrying about obscure wait types, and since I’ve recently been in preemptive territory I thought I should take some degree of interest. Spoiler alert: I did nothing to solve Monica’s problem, but my attempt to figure out where the wait type might emanate from made me realise that this is worth a blog post.
Without getting hung up on the detail, here is a very crude and simple way to hunt for areas of SQL Server that may use a particular wait type. The only prerequisite is that you need to be willing and able to attach Windbg to SQL Server, and that you have public symbols loaded.
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.
Upon starting the debugger, the module load addresses are listed right away. You can also use the lm command at any time afterwards to list them again. In my case, I got this for sqllang:
ModLoad: 00007ffe`23870000 00007ffe`25ad7000 C:\Program Files\Microsoft SQL Server\MSSQL12.MSSQLSERVER\MSSQL\Binn\sqllang.dll
So we have a start and end memory address. Take note of the length in bytes, using Windbg as a calculator:
0:063> ? 07ffe`25ad7000 - 7ffe`23870000 Evaluate expression: 36073472 = 00000000`02267000
Update 2017/08/29:
I’m keeping the original version below as a permanent record of a schoolboy error. Searching for a four-byte pattern expressed as a doubleword can in fact bring up hits, BUT only ones which are doubleword aligned, i.e. starting on an address divisible by 4. The correct way to cast the net wide enough is to use the -b flag and searching for four consecutive bytes; this search doesn’t presuppose doubleword alignment. Remembering to byte-reverse the pattern, that first command should have been s -b 0x7ffe`23870000 L0x2267000 d4 01 01 00. I was just lucky to have caught a fish using the -d variation.
Great. Now we have everything we need. The s command searches for patterns in a range of memory, and we’ll use the -d flag to make it a doubleword search. First few tries come up empty:
0:063> s -d 0x7ffe`23870000 L0x2267000 000101d4 0:063> s -d 0x7ffe`23870000 L0x2267000 000201d4 0:063> s -d 0x7ffe`23870000 L0x2267000 000401d4 0:063> s -d 0x7ffe`23870000 L0x2267000 000801d4
But now we get one:
0:063> s -d 0x7ffe`23870000 L0x2267000 001001d4 00007ffe`287d39f8 001001d4 8948f633 48602474 68247489 ....3.H.t$`H.t$h
Ignore everything other than the address at the start of the line – we’re not expecting the byte dump to make sense to the human eye. Let’s see what piece of code this belongs to – the uf disassembles the function that this piece of memory falls in.
0:063> uf 0x7ffe`287d39f8
I’m not even going to show you the output, because this one turned out to be a red herring – experience and/or intuition needed to confirm that. But let’s go on…
0:063> s -d 0x7ffe`23870000 L0x2267000 002001d4 0:063> s -d 0x7ffe`23870000 L0x2267000 004001d4 0:063> s -d 0x7ffe`23870000 L0x2267000 008001d4 0:063> s -d 0x7ffe`23870000 L0x2267000 010001d4 0:063> s -d 0x7ffe`23870000 L0x2267000 020001d4 0:063> s -d 0x7ffe`23870000 L0x2267000 040001d4 0:063> s -d 0x7ffe`23870000 L0x2267000 080001d4 0:063> s -d 0x7ffe`23870000 L0x2267000 100001d4
Still nothing, but then we strike gold:
0:063> s -d 0x7ffe`23870000 L0x2267000 200001d4 00007ffe`246a3fe4 200001d4 244c8d48 32bee840 4890ff1d ... H.L$@..2...H 00007ffe`246a6694 200001d4 244c8d48 0c0ee840 4890ff1d ... H.L$@......H 00007ffe`246a8d44 200001d4 244c8d48 e55ee840 4890ff1c ... H.L$@.^....H 00007ffe`246ac8a4 200001d4 244c8d48 a9fee840 4890ff1c ... H.L$@......H 00007ffe`246b0404 200001d4 244c8d48 6e9ee840 4890ff1c ... H.L$@..n...H ... and many more!
Try the uf trick again on the first one:
0:063> uf 0x7ffe`246a3fe4
And we get rewarded with a disassembly of the function sqllang!IWrapInterface<IAccessor>::Release – this one pretty much comes with flashing lights given that IAccessor reeks of COM and we were expecting something involving “RELEASE”. I’ll spare you the bulk of the assembly dump, but would like to highlight the bit that confirms the setup of a preemptive wait type:
00007ffe`246a3fe3 bad4010020 mov edx,200001D4h 00007ffe`246a3fe8 488d4c2440 lea rcx,[rsp+40h] 00007ffe`246a3fed e8be321dff call sqllang!AutoSwitchPreemptive::AutoSwitchPreemptive (00007ffe`238772b0)
That assignment to the edx register means that the encoded wait type is the second parameter to the AutoSwitchPreemptive constructor. And while it may not always be a recognisable setup, in this case I was already familiar with AutoSwitchPreemptive (see here).
Now this kind of trawling is by no means scientific. The wait type could have been loaded from a memory address, in which case it wouldn’t have been hard-coded in the function. And of course without the code running in context, it doesn’t tell you what kind of call stack it might show up in – only running the relevant code paths and catching the wait through a breakpoint or XEvent will do that. But as a quick and dirty way of hunting for wait type usage in a module up there on the marble slab? Hey, it works for me.
