So if you read my previous post on Basic Debugging Concepts and Setup, you are familiar with how to open a SQL Server dump or attach to the SQL Server process (sqlservr.exe). You are also familiar with what symbols are and why we need them. If you missed it, you can read it here:
In this post, we are going to go over a few basic commands that we will use from time to time in the blog, and that you may use to browse around inside a SQL dump or a live debug. Then in subsequent posts, we’ll build on these commands and learn new commands as we go deeper.
In the first post, I mentioned how the stack trace would be the most important piece of information in the dump. You use it to see what the current thread was doing. This is not to say that other data inside the debugging session or dump is not useful, but we’ll often start here to get a “feel” for what this thread was doing. In this post, I am looking at a live target – that is to say, I’ve attached the debugger directly to the sqlservr.exe process.
Now, to attach to sqlservr, we have to use the PID (Process ID). We can get this in one of several ways. You can use Task Manager:
- Open Task Manager - Click on the Processes Tab - Check the PID column (if you don’t see this, then click View –> Select Columns to add it)
Or, you can use the tasklist.exe or tlist.exe programs – both console applications:
tasklist –v | find /i “sqlservr.exe”
tlist –v | find /i “sqlservr.exe” (tlist.exe is included with the debugging tools installation)
tasklist –v | find /i “sqlservr.exe”
tlist –v | find /i “sqlservr.exe” (tlist.exe is included with the debugging tools installation)
Or, from with SQL Server, just run the following in Management Studio:
Once you have your PID, you are ready to connect. Check my previous post for instructions on how to do this…
NOTE: Attaching a debugger to a process will stop the execution of the process. The server will appear to “hang” to other users and applications. NEVER do this on a live production server or a server being actively used by users and application.
Now, we are ready to do some browsing with basic commands in the debugger. For these commands, I use the Command Window in Windbg (opens by default and is accessible through the View Menu). You can get some of this data through the use of the GUI windows inside of Windbg, which allows for a point-and-click experience to debugging. However, I find this is not sufficient when digging deep.
So first, a stack trace is specific to a thread – and SQL Server is obviously a multi-threaded application. To get a list of threads, we use the tilde command (~):
0:044> ~ 0 Id: 13d8.a6c Suspend: 1 Teb: 000007ff`fffdd000 Unfrozen 1 Id: 13d8.1d14 Suspend: 1 Teb: 000007ff`fffd5000 Unfrozen 2 Id: 13d8.1934 Suspend: 1 Teb: 000007ff`fffac000 Unfrozen 3 Id: 13d8.15d0 Suspend: 1 Teb: 000007ff`fffaa000 Unfrozen 4 Id: 13d8.c98 Suspend: 1 Teb: 000007ff`fffa8000 Unfrozen 5 Id: 13d8.17f4 Suspend: 1 Teb: 000007ff`fffa6000 Unfrozen 6 Id: 13d8.164c Suspend: 1 Teb: 000007ff`fffa4000 Unfrozen 7 Id: 13d8.1ea0 Suspend: 1 Teb: 000007ff`fffa2000 Unfrozen 8 Id: 13d8.1b68 Suspend: 1 Teb: 000007ff`fffa0000 Unfrozen 9 Id: 13d8.1dc8 Suspend: 1 Teb: 000007ff`fff9e000 Unfrozen 10 Id: 13d8.95c Suspend: 1 Teb: 000007ff`fff9c000 Unfrozen 11 Id: 13d8.1588 Suspend: 1 Teb: 000007ff`fff9a000 Unfrozen 12 Id: 13d8.138c Suspend: 1 Teb: 000007ff`fff98000 Unfrozen 13 Id: 13d8.1534 Suspend: 1 Teb: 000007ff`fff96000 Unfrozen 14 Id: 13d8.fb4 Suspend: 1 Teb: 000007ff`fff94000 Unfrozen 15 Id: 13d8.58c Suspend: 1 Teb: 000007ff`fff92000 Unfrozen 16 Id: 13d8.1438 Suspend: 1 Teb: 000007ff`fffd7000 Unfrozen 17 Id: 13d8.6a0 Suspend: 1 Teb: 000007ff`fff90000 Unfrozen 18 Id: 13d8.1974 Suspend: 1 Teb: 000007ff`fff8e000 Unfrozen 19 Id: 13d8.1b7c Suspend: 1 Teb: 000007ff`fff8c000 Unfrozen 20 Id: 13d8.1050 Suspend: 1 Teb: 000007ff`fff8a000 Unfrozen 21 Id: 13d8.1a9c Suspend: 1 Teb: 000007ff`fff88000 Unfrozen 22 Id: 13d8.1084 Suspend: 1 Teb: 000007ff`fff86000 Unfrozen 23 Id: 13d8.48c Suspend: 1 Teb: 000007ff`fff84000 Unfrozen 24 Id: 13d8.19b0 Suspend: 1 Teb: 000007ff`fff82000 Unfrozen 25 Id: 13d8.1bbc Suspend: 1 Teb: 000007ff`fff80000 Unfrozen 26 Id: 13d8.18f0 Suspend: 1 Teb: 000007ff`fff7e000 Unfrozen 27 Id: 13d8.15a8 Suspend: 1 Teb: 000007ff`fff7c000 Unfrozen 28 Id: 13d8.600 Suspend: 1 Teb: 000007ff`fff78000 Unfrozen 29 Id: 13d8.fb8 Suspend: 1 Teb: 000007ff`fff76000 Unfrozen 30 Id: 13d8.12b8 Suspend: 1 Teb: 000007ff`fff72000 Unfrozen 31 Id: 13d8.1ed8 Suspend: 1 Teb: 000007ff`fff70000 Unfrozen 32 Id: 13d8.85c Suspend: 1 Teb: 000007ff`fff6e000 Unfrozen 33 Id: 13d8.9a0 Suspend: 1 Teb: 000007ff`fff6c000 Unfrozen 34 Id: 13d8.1e74 Suspend: 1 Teb: 000007ff`fff68000 Unfrozen 35 Id: 13d8.230c Suspend: 1 Teb: 000007ff`fff5e000 Unfrozen 36 Id: 13d8.1be8 Suspend: 1 Teb: 000007ff`fff7a000 Unfrozen 37 Id: 13d8.135c Suspend: 1 Teb: 000007ff`fffd9000 Unfrozen 38 Id: 13d8.f1c Suspend: 1 Teb: 000007ff`fffd3000 Unfrozen 39 Id: 13d8.1a38 Suspend: 1 Teb: 000007ff`fff60000 Unfrozen 40 Id: 13d8.1994 Suspend: 1 Teb: 000007ff`fff6a000 Unfrozen 41 Id: 13d8.1930 Suspend: 1 Teb: 000007ff`fffae000 Unfrozen 42 Id: 13d8.1fd8 Suspend: 1 Teb: 000007ff`fff74000 Unfrozen 43 Id: 13d8.1eb0 Suspend: 1 Teb: 000007ff`fffdb000 Unfrozen . 44 Id: 13d8.21c0 Suspend: 1 Teb: 000007ff`fff66000 Unfrozen
Here we have 45 threads – starting with 0. The period in the left hand margin indicates the current thread that is “in context” – as does the prompt (0:044>). This is just a chronological numbering used by the debugger. The column following Id: is the actual process ID and thread ID in hexadecimal (pid.tid). I’ve looked ahead and know that I have a query running on thread 36 (or 1be8). I would like to see it’s stack trace. I can view it by issuing the stack trace command, “k”. The “k” command takes several parameters that provide more information such as function arguments (kv), frame numbering (kn), memory used (kf), etc… Right now, we’ll focus on just the “k” command. I can either set my context to this thread, or view it by explicitly stating I want this thread when issuing the “k” command. To set my context, I use ~36s. The “s” says to take thread 36 (~36) and set our context (s). To just view the stack trace while still in the context of another thread, I state the thread and give the stack command like this: ~36k. I set my context and got my stack trace like this:
0:044> ~36s ntdll!NtSignalAndWaitForSingleObject+0xa: 00000000`7775164a c3 ret 0:036> k Child-SP RetAddr Call Site 00000000`0c09b7c8 00000000`77652f60 ntdll!NtSignalAndWaitForSingleObject+0xa 00000000`0c09b7d0 00000000`00aec99e kernel32!SignalObjectAndWait+0x110 00000000`0c09b880 00000000`00ad3783 sqlservr!SOS_Scheduler::SwitchContext+0x84e 00000000`0c09bb20 00000000`00ad4b06 sqlservr!SOS_Scheduler::Suspend+0x9f 00000000`0c09bb60 00000000`00b8363a sqlservr!SOS_Task::Sleep+0x346 00000000`0c09be90 00000000`00b6287e sqlservr!CXStmtQuery::ErsqExecuteQuery+0x4c27 00000000`0c09eda0 00000000`00b60fe3 sqlservr!CMsqlExecContext::ExecuteStmts<1,1>+0xb6c 00000000`0c09f030 00000000`00b61499 sqlservr!CMsqlExecContext::FExecute+0x593 00000000`0c09f1b0 00000000`00b63ff2 sqlservr!CSQLSource::Execute+0x2f9 00000000`0c09f2d0 00000000`00b5ebbb sqlservr!process_request+0x370 00000000`0c09f590 00000000`00ae2abb sqlservr!process_commands+0x2b2 00000000`0c09f790 00000000`00ae0fda sqlservr!SOS_Task::Param::Execute+0x11b 00000000`0c09f8b0 00000000`00ae2665 sqlservr!SOS_Scheduler::RunTask+0xca 00000000`0c09f940 00000000`0108abb0 sqlservr!SOS_Scheduler::ProcessTasks+0x95 00000000`0c09f9b0 00000000`0108c4b0 sqlservr!SchedulerManager::WorkerEntryPoint+0x110 00000000`0c09fa70 00000000`0108a060 sqlservr!SystemThread::RunWorker+0x60 00000000`0c09faa0 00000000`0108a9ef sqlservr!SystemThreadDispatcher::ProcessWorker+0x12c 00000000`0c09fb30 00000000`735037d7 sqlservr!SchedulerManager::ThreadEntryPoint+0x12f 00000000`0c09fbc0 00000000`73503894 MSVCR80!_callthreadstartex+0x17 [f:\dd\vctools\crt_bld\self_64_amd64\crt\src\threadex.c @ 348] 00000000`0c09fbf0 00000000`775ff56d MSVCR80!_threadstartex+0x84 [f:\dd\vctools\crt_bld\self_64_amd64\crt\src\threadex.c @ 326] 00000000`0c09fc20 00000000`77733281 kernel32!BaseThreadInitThunk+0xd 00000000`0c09fc50 00000000`00000000 ntdll!RtlUserThreadStart+0x21
Now, we are in the context of thread 36. The top function, “ntdll!NtSignalAndWaitForSingleObject” is what is executing or what executed last. In this case, this is an API that places our thread into a wait state – waiting to be signaled when what it needs is ready. Don’t worry about Child-SP and RetAddr for now. They are specific to the construction of the stack frame and where we return execution to when execution of the current function completes.
Now, let’s say I need to know what version of SQL Server I am working with here. To do so, we use the lm command. Again, this command has many parameters that just follow the base command stub, but let’s get verbose information for the module sqlservr:
0:036> lmvm sqlservr start end module name 00000000`00ad0000 00000000`04314000 sqlservr (pdb symbols) c:\symbols\public\sqlservr.pdb\1A48B7C4D60D41E1A9F1BF1ADE8DCC742\sqlservr.pdb Loaded symbol image file: C:\Program Files\Microsoft SQL Server\MSSQL10.CRASH\MSSQL\Binn\sqlservr.exe Image path: C:\Program Files\Microsoft SQL Server\MSSQL10.CRASH\MSSQL\Binn\sqlservr.exe Image name: sqlservr.exe Timestamp: Thu Jul 10 02:02:17 2008 (4875A5E9) CheckSum: 0372739F ImageSize: 03844000 File version: 2007.100.1600.22 Product version: 10.0.1600.22 File flags: 0 (Mask 3F) File OS: 40000 NT Base File type: 1.0 App File date: 00000000.00000000 Translations: 0409.04b0 CompanyName: Microsoft Corporation ProductName: Microsoft SQL Server InternalName: SQLSERVR OriginalFilename: SQLSERVR.EXE ProductVersion: 10.0.1600.22 FileVersion: 2007.0100.1600.022 ((SQL_PreRelease).080709-1410) FileDescription: SQL Server Windows NT - 64 Bit LegalCopyright: Microsoft Corp. All rights reserved. LegalTrademarks: Microsoft SQL Server is a registered trademark of Microsoft Corporation. Comments: SQL
The red, bolded and underlined section shows me we are dealing with SQL Server 2008 RTM. I can also see it is 64 bit, where the symbols are that are being used, where the executable is, and the timestamp of the date this executable was compiled. If you run the “lm” command alone, you will get a list of modules loaded into SQL Server’s address space.
To verify the target of our debugger, we can use the pipe command, | :
0:036> | . 0 id: 13d8 attach name: C:\Program Files\Microsoft SQL Server\MSSQL10.CRASH\MSSQL\Binn\sqlservr.exe
Another common task is to dump the contents of memory. To do this, we use the “d” command. This command also comes with many different parameters. For instance, “dc” dumps memory at the supplied address and maps/translates this to ASCII character data. Whereas, “dd” just leaves the information in double-word (32 bit integer) format. This may be used to analyze memory in heap space, or memory on the stack to see what data is passed in the arguments. For example, we can dump memory used by the stack from thread 10 as follows:
0:044> ~10s ntdll!NtSignalAndWaitForSingleObject+0xa: 00000000`77a3164a c3 ret 0:010> k Child-SP RetAddr Call Site 00000000`0813d4b8 00000000`77832f60 ntdll!NtSignalAndWaitForSingleObject+0xa 00000000`0813d4c0 00000000`0029c99e kernel32!SignalObjectAndWait+0x110 00000000`0813d570 00000000`00284575 sqlservr!SOS_Scheduler::SwitchContext+0x84e 00000000`0813d810 00000000`00283ea8 sqlservr!SOS_Scheduler::SuspendNonPreemptive+0xc5 00000000`0813d850 00000000`0029cfad sqlservr!EventInternal<Spinlock<149,1,0> >::Wait+0x428 00000000`0813de40 00000000`0037b27a sqlservr!ResQueueBase::Dequeue+0x19d 00000000`0813df00 00000000`00292abb sqlservr!SQLServerLogMgr::LogWriter+0x21a 00000000`0813f460 00000000`00290fda sqlservr!SOS_Task::Param::Execute+0x11b 00000000`0813f580 00000000`00292665 sqlservr!SOS_Scheduler::RunTask+0xca 00000000`0813f610 00000000`0083abb0 sqlservr!SOS_Scheduler::ProcessTasks+0x95 00000000`0813f680 00000000`0083c4b0 sqlservr!SchedulerManager::WorkerEntryPoint+0x110 00000000`0813f740 00000000`0083a060 sqlservr!SystemThread::RunWorker+0x60 00000000`0813f770 00000000`0083a9ef sqlservr!SystemThreadDispatcher::ProcessWorker+0x12c 00000000`0813f800 00000000`751437d7 sqlservr!SchedulerManager::ThreadEntryPoint+0x12f 00000000`0813f890 00000000`75143894 MSVCR80!_callthreadstartex+0x17 [f:\dd\vctools\crt_bld\self_64_amd64\crt\src\threadex.c @ 348] 00000000`0813f8c0 00000000`777df56d MSVCR80!_threadstartex+0x84 [f:\dd\vctools\crt_bld\self_64_amd64\crt\src\threadex.c @ 326] 00000000`0813f8f0 00000000`77a13281 kernel32!BaseThreadInitThunk+0xd 00000000`0813f920 00000000`00000000 ntdll!RtlUserThreadStart+0x21 0:010> dc 00000000`0813df00 00000000`0813df00 00000014 00000000 0a160080 00000000 ................ 00000000`0813df10 00000000 00000000 00000000 00000000 ................ 00000000`0813df20 00000000 00000000 00000000 00000000 ................ 00000000`0813df30 00000000 00000000 00000000 00000000 ................ 00000000`0813df40 00000000 00000000 00000014 00000000 ................ 00000000`0813df50 00000003 00000000 00000000 00000000 ................ 00000000`0813df60 00000e74 00000000 0a160800 00000000 t............... 00000000`0813df70 00000000 00000000 00000000 00000000 ................ 0:010> dc 00000000`0813df80 0a168ad0 00000000 1f56abff 0000a7dc ..........V..... 00000000`0813df90 0813f490 00000000 01f33050 00000000 ........P0...... 00000000`0813dfa0 00000000 00000000 1f56abdf 0000a7dc ..........V..... 00000000`0813dfb0 0813df88 00000000 01f33050 00000000 ........P0...... 00000000`0813dfc0 00000000 00000000 0a160080 00000000 ................ 00000000`0813dfd0 802881a0 00000000 00000000 00000000 ..(............. 00000000`0813dfe0 00000000 00000000 00000000 00000000 ................ 00000000`0813dff0 00000000 00000000 00000001 00000000 ................
First we change to thread 10 (~10s), then we dump the stack (k). Finally, we picked a frame (a line in the stack trace) and dumped the memory address for the Child-SP. The Child-SP is the base pointer for a frame in a stack trace – basically where in memory this frame starts. A stack grows up or backwards in memory as it gets larger. A little more on this when we discuss the “r” command.
The commands we’ve covered so far are some of the most common in all types of debugging scenarios. We’ll finish up our introductory command list with the following list of commands that you may need – though not as often as stack and memory commands:
The “vertarget” command simply gives us the version of the OS on the target machine or machine a dump was taken from as well as system up time (and time the dump was taken or time of the current live session):
0:010> vertarget Windows 7 Version 7600 MP (2 procs) Free x64 Product: WinNt, suite: SingleUserTS kernel32.dll version: 6.1.7600.16385 (win7_rtm.090713-1255) Machine Name: Debug session time: Sat Feb 6 21:53:13.731 2010 (UTC - 5:00) System Uptime: 1 days 13:30:20.147 Process Uptime: 0 days 1:06:40.664 Kernel time: 0 days 0:00:00.670 User time: 0 days 0:00:01.700
The “.chain” command is used to list extension DLLs and their paths that are loaded into the debugger. Extension DLLs provide additional commands in the debugger. For instance, a command we haven’t discussed - !handle – is contained in a DLL extension file named ntsdexts.dll. The !handle command returns the handle table for the process. Handles are used by processes to access resources such as files, Ports, Events, and other objects in the process and operating system. Notice the symbol prefixing the command –> “!”. The exclamation mark is used before extension commands that are contained in external DLL files and not part of the debugger. The debugger will come with a few extension DLLs pre-loaded. Execute .chain to see these. Each one will have a help command, so you can execute:
0:010> !uext.help Commands for C:\Program Files\Debugging Tools for Windows (x64)\winext\uext.dll: !evlog - Display information from the event log !findstack - Find all stacks containing the given symbol !handle - Display information about open handles !help - Displays information on available extension commands !mapped_file - Retrieves the name of the file associated with the mapping containing the given address !runaway - Display thread execution times !uniqstack - Like debugger's built-in ~* k [b,v,p,n], but this will exclude stacks that look like other stacks already printed !vadump - Display complete virtual memory layout description !vprot - Dumps virtual memory info for the given address !help <cmd> will give more information for a particular command
and .extmatch will help you find the commands as well:
0:010> .extmatch /D /e uext * !uext.evlog !uext.findstack !uext.handle !uext.help !uext.mapped_file !uext.runaway !uext.uniqstack !uext.vadump !uext.vprot
Now, if we are dealing with a dump or debug scenario that resulted from an exception, we can get some information from it with the !analyze command. Often times it is good to include the –v parameter to get verbose info. The syntax of the command is here, but the output is quite verbose and too much for the blog. It’s goal is to give you a head start on what the problem is and where the exception occurred that lead to the issue:
0:010> !analyze -v
The “x” command simply dumps the symbols inside our symbol files. If I want to find all symbols that are part of the SOS Scheduler (a class) inside the SQL Server module (sqlservr) that begin with “Run”, then I would issue the following command to get the symbols:
0:010> x sqlservr!SOS_Scheduler::Run* 00000000`00290f10 sqlservr!SOS_Scheduler::RunTask = <no type information>
NOTE: Be careful to not run x sqlservr!* as this will run for a very long time due to the number of APIs and public variables in sqlservr.exe.
It’s beyond the scope of this post – which is getting quite long – to discuss CPU architecture and their registers. However, to view those registers, we use the “r” command as seen here:
0:010> r rax=00000000015a79b8 rbx=00000000000002a0 rcx=00000000804a3800 rdx=00000000804a3803 rsi=0000000000000000 rdi=00000000ffffffff rip=0000000077a3164a rsp=000000000813d4b8 rbp=00000000802883d0 r8=00000000804a2080 r9=00000000002c25a0 r10=0000000000000000 r11=346dc5d63886594b r12=0000000000000000 r13=00000000000001ac r14=0000000003b108d0 r15=0000000000000000 iopl=0 nv up ei pl zr na po nc cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000244 ntdll!NtSignalAndWaitForSingleObject+0xa: 00000000`77a3164a c3 ret
CPUs have a number of registers – storage locations built right onto the processor. Take “rax” above. This register is a multipurpose register and is commonly used to hold return values and the results of operations. From it’s name, “rax”, we know this is 64 bit architecture. On a 32 bit platform, it was called “eax”. Additionally, the size of the register is 64 bit – which is what makes this a 64 bit processor. Each “digit” represents 4 bits or a “nibble”. Therefore, all bits on is a 1111, which is 15, or 0xf. Therefore, it takes two digits here to represent a byte. And if each digit is 4 bits, and we have 16 digits – then 16 x 4 = 64 bits.
Now a few special registers are the “rip”and the “rsp” registers. The “rip” is the current IP pointer – or the instruction pointer. As it sounds, this is the next instruction to execute. The “rsp” register contains a pointer to the current location on the stack. We can use brackets () to get the actual address from the register and find what were we are in the assembly:
0:010> u [rip] ntdll!NtSignalAndWaitForSingleObject+0xa: 00000000`77a3164a c3 ret 00000000`77a3164b 0f1f440000 nop dword ptr [rax+rax] ntdll!ZwSinglePhaseReject: 00000000`77a31650 4c8bd1 mov r10,rcx 00000000`77a31653 b877010000 mov eax,177h 00000000`77a31658 0f05 syscall 00000000`77a3165a c3 ret 00000000`77a3165b 0f1f440000 nop dword ptr [rax+rax] ntdll!ZwStartProfile: 00000000`77a31660 4c8bd1 mov r10,rcx
We see that we are in ntdll!NtSignalAndWaitForSingleObject – which of course is the top frame in our stack trace above in this post for thread 10. The “u” command is the disassembly command – to dump the assembly code for a function or at a specific address.
When doing a live debug, you may wish to wait for SQL Server – or another application to hit a specific point in the code – perhaps a function call you found when analyzing the symbols above with the “x” command. You can use the symbol name or the memory address where the function starts. Later, you can set conditional breakpoints with conditions that will be evaluated to determine whether or not to stop. Additionally, you can set breakpoints on memory access. For now, simply setting a breakpoint when SQL Server makes a call to a function takes this format:
0:010> bp sqlservr!<function or method call>
To list the breakpoints, use the bl command, which returns a numbered list. Then use the number to clear the breakpoint with bc. Here is an example:
0:010> x sqlservr!SOS_Scheduler::R* 00000000`01ab2640 sqlservr!SOS_Scheduler::RemoveFromCompletedTasks = <no type information> 00000000`01ac4ca0 sqlservr!SOS_Scheduler::RemoveFromPendingQueue = <no type information> 00000000`01455eb0 sqlservr!SOS_Scheduler::ResetMaxWaitStats = <no type information> 00000000`00290f10 sqlservr!SOS_Scheduler::RunTask = <no type information> 00000000`01ac4af0 sqlservr!SOS_Scheduler::RetrieveTask = <no type information> 00000000`00814250 sqlservr!SOS_Scheduler::RemoveFromAbortedQueue = <no type information> 00000000`002831c0 sqlservr!SOS_Scheduler::Resume = <no type information> 0:010> bp sqlservr!SOS_Scheduler::RunTask 0:010> bl 1 e 00000000`00290f10 0001 (0001) 0:**** sqlservr!SOS_Scheduler::RunTask 0:010> bc 1 0:010> bl
The appropriate last command to describe is the “.hh” command. This will launch help from inside the Debugger command window. This is a compiled HTML help file (.chm) that contains the hundreds of commands available to you natively in the debugger and in extensions included with the debugger. Thanks to extensions, the number of possible commands are somewhat limitless in the debugger. The help file even contains basic information on the APIs for developing your own set of commands in an extension DLL file. So spend some time browsing the help file to see what other information you can get out of your debugging session.