It contains six parts:
- Preparations – common actions for preparing for all debugging cases.
- Delphi – debugging hang with Delphi.
- EurekaLog – debugging hang with EurekaLog.
- Process Explorer – debugging hang with Process Explorer.
- Threads Snapshot – debugging hang with Threads Snapshot.
- A practical example – example with artificial hang.
Preparations
Well, before you start actual debugging – you need to do some tasks first. First thing is: you need to add debug information to your project and make a build (not just compile). Different tools requires/supports different formats of debugging info, so just enable everything – so you don’t need to think about it :) This step is required, if you want to deal with human-readable sources and not some raw machine code and offsets.Okay, so you need to turn on these options on “Linking” page (Project/Options/Linking): "MAP file" - Detailed, "Debug Information" (it’s called "Include TD32 debug info" in old Delphi versions) - True, "Include remote debug symbols" - True:
Apart from debug info, you should also enable "Stack Frames" and "Use Debug DCUs" options on "Compiling" page:
Please, allow me not describe again, what these options are doing.
Don’t forget to make Build after changes. Obviously, if you have several projects (DLL, BPL, etc) – then you need to do the same thing for each project. Also note, if you’re building with run-time packages, you should disable them for debugging session, if it’s possible. Packages increase complexity of debugging significantly.
Delphi
You could think: "but I can’t reproduce this hang under debugger!" or "I do not have Delphi installed on that machine!". Wait a moment, don’t go to the next article’s item.First: you don’t need to run your application under Delphi. You can run your program as usual (without any debugger attached), work as much, as you need (few days?) – and wait, until it hang. Now you can attach Delphi’s debugger to hanged process and start debugging. Second: if you don’t have Delphi installed – you can use remote debugger. I won’t go into details here, as we have a lot things to do today, but it’s not hard task – refer to Delphi’s help.
So, you’ve run your application, it worked for some time and hanged. Now open Delphi, open your project and do Run/Attach to process command:
Delphi’s debugger will connect to selected process and will set it on pause – by hitting breakpoint in special debugger’s service thread:
You can ignore that debugger’s thread – just open Threads window and select any of your threads for debugging. You can view call stacks, walk call stack, switch threads, analyze variables, do stepping and running, etc, etc – in other words: you may debug your application as usual. If there is debug information available – you can close CPU window and debug by using source code.
Note, that you should use Windows Vista or above for debugging, if this is possible – that’s because these OS support new feature called “Wait Chain Traversal”. Delphi’s debugger is capable of using it, starting with Delphi 2009. So, if you’re using Delphi 2009 or above and Windows Vista or above – then you can see wait chain status in Threads window:
EurekaLog
EurekaLog have anti-freeze feature. Well, I’ve already covered it in much details a long time ago in a separate article. For this reason, I’ll not discuss it in details here, as there is a lot of other material to discuss.Short summary: this is a very convenient feature, if you can use it in your application. You can’t use it, if your main thread is not pumping messages (like console or service applications). The result is usual EurekaLog report with call stack and accompanied information, focusing on hanged thread. This feature is handy for letting you know about problems on client machines. It will report you about any hang on the field. But if you want to debug a reproducible hang – it’s better to use Delphi’s debugger, as shown above.
Process Explorer
If you can’t use Delphi for some reason – then the only thing left is manual debugging.You may use a Process Explorer tool for that. But before doing actual debugging, you need to do two steps. Both steps are optional, but highly recommended.
Step one – setup system debug information in Process Explorer. Windows ships with raw binaries, which have their debug information stripped. We just enabled debug info for our project (see first article’s item), but how can we do the same thing for the Windows itself? Well, Microsoft is aware of that issue and it can give you debug info separately, if you ask for this. You can download this debug info and get you pretty human-readable call stacks.
First you need to download and install Windows Debugging Tools. Next, you need to make a choice: either you download all debug info at once in one package or you can download it by request for each executable. You may try the first approach, if you want, but I prefer the second way.
You need to create a writable folder for the second way. And setup a Process Explorer of course (Options/Configure symbols):
First edit specifies path to DbgHelp.dll – pick the one from installed Windows Debugging Tools.
Second edit contains two things: first – your writable folder (it’s
C:\ProgramData\DebugSymbols for me, but I’ve added a “write” access to it), where you want to store debug info; second – a debug info server, which will serve your requests for new debug info (I’m using default Microsoft’s server: http://msdl.microsoft.com/download/symbols).After setting these things, Process Explorer will start to use debug information for system binaries. It will ask server for appropriate version of debug info and cache (store) it in the specified folder. So, you may see a "Loading symbols for ABC.exe+0xXYZ..." text while watching threads or call stacks.
Step two – you need to convert your map-file to some other format. The reason: Delphi generates several debug info formats, but all of them are Borland-related. Process Explorer, being a Microsoft’s tool, can accept a range of Microsoft’s formats, but not Borland’s ones. You can do this by using map2dbg tool. This is a simple console utility. Download, unpack, open cmd and write:
map2dbg Project1.exeThis tool will use Project1.exe and Project1.map to create a Project1.dbg, which can be used by Microsoft’s tools.
Well, I’ve just said a lot of things. Now I need to show you, what you’ll gain from all this stuff. So, here are 3 screenshots below. Walk from top to bottom: call stack without both steps (no system’s and no project’s debug info), call stack with first step only (system’s debug info present, project’s debug info is not), and call stack with both steps completed (both system’s and project’s debug info are available):
So, as you can see, enabling debug info gives you 3 things:
- More readable call stack (you got module!routine+offset instead of just module+offset)
- More full call stack (tracing heuristic may filter out calls without accessible debug info for validating entry)
- More meaningful call stack (analyzer may show you the wrong function name without debug info – if code calls internal function, which have no name, but there is a public function with name nearby)
Now, what exactly should you do with Process Explorer? Well, you should run your application and let it hang. Now, you run Process Explorer, select your process, right click on it –> Properties, and select Threads tab in properties window:
Here you can watch your threads, what they are doing, who eats CPU, who is waiting for something, etc. You can select a thread and hit "Stack" button to view this thread’s call stack (see three screenshots above for example).
Of course, you can’t view variables or something like that – only states and execution points of threads. So you need to use your psychic powers to figure out what’s going on. It’s harder, than debugging in Delphi, but possible.
Threads Snapshot
Well, using Process Explorer though not that hard, but sure doesn’t look as piece-a-cake for beginner (and especially for customer!). There is a lot of work and a lot of new concepts. Honestly saying, all this mess with debug info is not very convenient, isn’t it? So I decided to write a small and simple tool, which allows you to select a process and it will dump all information about threads to text file. This information includes:- Basic info: ID, priority, etc.
- Call stack. Tool supports the following sources: Borland-related, JCL, EurekaLog and madExcept. I’ll add support for Microsoft and download-at-request (as Process Explorer does) a bit later.
- Wait Chain Traversal information (on Windows Vista and above only).
- Thread’s context – CPU’s registers and flags.
User interface:
Resulting log file:
Process [ 147C / 5244 ]: H:\Test\Project88.exe (2010.06.08 16:31:07) [ 18C4 / 6340 ] Priority: 8 Wait Chain Count = 1; Deadlock: False Type: Thread; status: Blocked; process: [ 147C / 5244 ]; thread: [ 18C4 / 6340 ]; wait time: 701985; context switches: 4040 EIP: 772E438D EFlags: 00000202 EBP: 0018FF1C ESP: 0018FEEC EAX: 000100B8 EBX: 0008E301 ECX: 00000000 EDX: 00000000ESI: 00000000 EDI: 0018FEE4 SegCS: 00000023 CegSS: 0000002B SegGS: 0000002B SegFS: 00000053 SegES: 0000002B SegDS: 0000002B ---------------------------------------------------------------------------------------------------------------------------------------------- |Methods |Details|Stack |Address |Module |Unit |Class |Procedure/Method |Line | ---------------------------------------------------------------------------------------------------------------------------------------------- |Calling Thread: ID=6340; Priority=??; Class= | |--------------------------------------------------------------------------------------------------------------------------------------------| |00000008|03 |00000000|772E438D|user32.dll |USER32 | |WaitMessage | | |000000F2|04 |0018FF20|0049F5CC|Project88.exe|Forms |Forms |TApplication.Idle |10358[0] | |000000F2|04 |0018FF20|0049E8FF|Project88.exe|Forms |Forms |TApplication.HandleMessage |9814[23] | |000000F2|04 |0018FF44|0049E8E8|Project88.exe|Forms |Forms |TApplication.HandleMessage |9813[0] | |000000F2|04 |0018FF44|0049EC1D|Project88.exe|Forms |Forms |TApplication.Run |9951[201]| |000000F2|04 |0018FF74|0049EB54|Project88.exe|Forms |Forms |TApplication.Run |9925[0] | |000000F2|04 |0018FF74|004A6C91|Project88.exe|Project88|Project88|Project88 |13[73] | |000000F2|03 |0018FF8C|770D3675|kernel32.dll |kernel32 | |BaseThreadInitThunk | | |000000F2|03 |0018FF98|77B29D70|ntdll.dll |ntdll | |Unknown function at 77B29D70 near RtlInitializeExceptionChain| | |000000F2|03 |0018FFD8|77B29D4B|ntdll.dll |ntdll | |Unknown function at 77B29D4B near RtlInitializeExceptionChain| | |000000F2|03 |0018FFD8|77B29D40|ntdll.dll |ntdll | |Unknown function at 77B29D40 near RtlInitializeExceptionChain| | ---------------------------------------------------------------------------------------------------------------------------------------------- [ 1834 / 6196 ] Priority: 8 Wait Chain Count = 1; Deadlock: False Type: Thread; status: Blocked; process: [ 147C / 5244 ]; thread: [ 1834 / 6196 ]; wait time: 720156; context switches: 2 EIP: 77B100FD EFlags: 00000202 EBP: 02F7FF88 ESP: 02F7FDF4 EAX: 77B51C7F EBX: 77B51C20 ECX: 00000000 EDX: 00000000ESI: 006B7C60 EDI: 00000000 SegCS: 00000023 CegSS: 0000002B SegGS: 0000002B SegFS: 00000053 SegES: 0000002B SegDS: 0000002B ----------------------------------------------------------------------------------------------------------------------------------- |Methods |Details|Stack |Address |Module |Unit |Class|Procedure/Method |Line| ----------------------------------------------------------------------------------------------------------------------------------- |Calling Thread: ID=6196; Priority=??; Class= | |---------------------------------------------------------------------------------------------------------------------------------| |00000008|03 |00000000|77B100FD|ntdll.dll |ntdll | |ZwWaitForMultipleObjects | | |000000F2|03 |02F7FF8C|770D3675|kernel32.dll|kernel32| |BaseThreadInitThunk | | |000000F2|03 |02F7FF98|77B29D70|ntdll.dll |ntdll | |Unknown function at 77B29D70 near RtlInitializeExceptionChain| | |000000F2|03 |02F7FFD8|77B29D4B|ntdll.dll |ntdll | |Unknown function at 77B29D4B near RtlInitializeExceptionChain| | |000000F2|03 |02F7FFD8|77B29D40|ntdll.dll |ntdll | |Unknown function at 77B29D40 near RtlInitializeExceptionChain| | -----------------------------------------------------------------------------------------------------------------------------------As you can see, this is a tiny and convenient alternative to using Process Explorer tool. You can even ask your customer to capture snapshot for you. Just don’t forget to transfer all necessary files (like map-files).
I’ve just wrote this tools for a two days. So it’s a bit untested. I think that fixed version of this tool may appear in EurekaLog v7.
A practical example
I’ve also wrote a simple test application with two buttons. You can use it as training example. First button creates several threads, which deadlock due to circular waiting. Second button creates a memory corruption, which leads to hang. Run this example, hit any button and try to figure out a reason for hang. See if you can debug these cases.Using Delphi: if you have WCT support – than it’s piece-a-cake to debug first case: just run application, hit button, put application on pause and look on Threads window:
You’ll see a problem immediately. You have 3 threads (ignore last thread – it’s debugger’s thread, not yours). The main thread (a first one) waits for worker thread (a second one) to complete. Second thread issues a SendMessage call, which targets last thread (third). Third thread handles the message, but it needs capture critical section, which is owner by second thread. Here is a deadlock: second thread waits third thread and third thread waits second thread.
If you don’t have WCT available – then you need to do this analysis manually. You need to switch between threads and see their call stacks:
Right after switching to thread – there will be CPU window with current machine instruction. You can ignore it and click on some call stack items to view source code instead.
You can reconstruct situation by analyzing call stacks of all three threads.
How the same situation looks in Process Explorer and Threads snapshot tools? Well, you can run Process Explorer and see call stacks for threads:
You don’t see line numbers here – but at least you see routine names and their sequence. For example, note
Thread1Func, dispatch-like, CriticalSection.Aquire, etc routines in the screenshot above. And again: you look at call stacks of all threads and trying to reconstruct the situation. It will be harder than using Delphi (you don’t see variables and line number), but (using a certain amount of psychic powers) possible.Considering Threads snapshot – it produces such log (I cut some unimportant details to minimize size):
Process [ 1A1C / 6684 ]: H:\Test\HangDemo.exe (2010.06.08 17:54:33) [ 1BD8 / 7128 ] Priority: 8 Wait Chain Count = 7; Deadlock: TrueType: Thread; status: Blocked; process: [ 1A1C / 6684 ]; thread: [ 1BD8 / 7128 ]; wait time: 1038023; context switches: 762 Type: Unknown; status: Owned; name: " "; timeout: 0; alertable: 0 Type: Unknown; status: Unknown; name: " "; timeout: 0; alertable: 0 Type: Unknown; status: Unknown; name: ""; timeout: 0; alertable: 0 Type: Unknown; status: Unknown; name: ""; timeout: 0; alertable: 0 Type: Unknown; status: Unknown; name: ""; timeout: 0; alertable: 0 Type: Unknown; status: Unknown; name: ""; timeout: 0; alertable: 0 EIP: 77B0F871 EFlags: 00000202 EBP: 0018F438 ESP: 0018F3CCEAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000000ESI: 00000120 EDI: 00000000 SegCS: 00000023 CegSS: 0000002B SegGS: 0000002B SegFS: 00000053 SegES: 0000002B SegDS: 0000002B ---------------------------------------------------------------------------------------------------------------------------------------------- |Methods |Details|Stack |Address |Module |Unit |Class |Procedure/Method |Line | ---------------------------------------------------------------------------------------------------------------------------------------------- |Calling Thread: ID=7128; Priority=??; Class= | |--------------------------------------------------------------------------------------------------------------------------------------------| |00000008|03 |00000000|77B0F871|ntdll.dll |ntdll | |ZwWaitForSingleObject | | |000000F2|03 |0018F43C|7757077E|KERNELBASE.dll|KERNELBASE| |WaitForSingleObjectEx | | |000000F2|03 |0018F43C|770D117F|kernel32.dll |kernel32 | |WaitForSingleObjectEx | | |000000F2|03 |0018F454|770D1141|kernel32.dll |kernel32 | |WaitForSingleObjectEx | | |000000F2|03 |0018F454|770D1133|kernel32.dll |kernel32 | |WaitForSingleObject | | |000000F2|03 |0018F468|770D1126|kernel32.dll |kernel32 | |WaitForSingleObject | | |000000F2|04 |0018F468|004B3580|HangDemo.exe |UnitMain |UnitMain|TfmMain.Button1Click |101[68] | |000000F2|04 |0018F47C|0048331F|HangDemo.exe |Controls |Controls|TControl.Click |7178[111] | ---------------------------------------------------------------------------------------------------------------------------------------------- [ 065C / 1628 ] Priority: 8 Wait Chain Count = 5; Deadlock: TrueType: Thread; status: Blocked; process: [ 1A1C / 6684 ]; thread: [ 065C / 1628 ]; wait time: 1038024; context switches: 34 Type: Unknown; status: No access; name: " "; timeout: 0; alertable: 0 Type: Unknown; status: Unknown; name: " "; timeout: 0; alertable: 0 Type: Unknown; status: Unknown; name: ""; timeout: 0; alertable: 0 Type: Unknown; status: Unknown; name: ""; timeout: 0; alertable: 0 EIP: 77B0F871 EFlags: 00000202 EBP: 0237FD40 ESP: 0237FCDC EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000000ESI: 006293C4 EDI: 00000000 SegCS: 00000023 CegSS: 0000002B SegGS: 0000002B SegFS: 00000053 SegES: 0000002B SegDS: 0000002B ------------------------------------------------------------------------------------------------------------------------------------------- |Methods |Details|Stack |Address |Module |Unit |Class |Procedure/Method |Line | ------------------------------------------------------------------------------------------------------------------------------------------- |Calling Thread: ID=1628; Priority=??; Class= | |-----------------------------------------------------------------------------------------------------------------------------------------| |00000008|03 |00000000|77B0F871|ntdll.dll |ntdll | |ZwWaitForSingleObject | | |000000F2|03 |0237FD44|77B28B9A|ntdll.dll |ntdll | |Unknown function at 77B28B9A near RtlIntegerToUnicodeString | | |000000F2|03 |0237FD44|77B28B43|ntdll.dll |ntdll | |Unknown function at 77B28B43 near RtlIntegerToUnicodeString | | |000000F2|03 |0237FD6C|77B12260|ntdll.dll |ntdll | |RtlEnterCriticalSection | | |000000F2|04 |0237FD6C|00441408|HangDemo.exe|SyncObjs|SyncObjs|TCriticalSection.Acquire |546[4] | |000000F2|04 |0237FD74|004B3354|HangDemo.exe|UnitMain|UnitMain|WndProc |43[20] | |000000F2|03 |0237FDA8|772D6215|user32.dll |USER32 | |Unknown function at 772D6215 near gapfnScSendMessage | | |000000F2|03 |0237FDA8|772D68E5|user32.dll |USER32 | |Unknown function at 772D68E5 near gapfnScSendMessage | | |000000F2|03 |0237FDEC|772D6893|user32.dll |USER32 | |Unknown function at 772D6893 near gapfnScSendMessage | | |000000F2|03 |0237FE20|772D682D|user32.dll |USER32 | |Unknown function at 772D682D near gapfnScSendMessage | | |000000F2|03 |0237FE20|772D7172|user32.dll |USER32 | |Unknown function at 772D7172 near GetWindowLongW | | |000000F2|03 |0237FEA8|772D682D|user32.dll |USER32 | |Unknown function at 772D682D near gapfnScSendMessage | | |000000F2|03 |0237FEA8|772D7D2C|user32.dll |USER32 | |Unknown function at 772D7D2C near LoadStringW | | |000000F2|03 |0237FEF0|772D7E2C|user32.dll |USER32 | |DispatchMessageW | | |000000F2|03 |0237FEF0|772D7EB8|user32.dll |USER32 | |GetMessageW | | |000000F2|03 |0237FF0C|772D7E92|user32.dll |USER32 | |GetMessageW | | |000000F2|04 |0237FF0C|004B3420|HangDemo.exe|UnitMain|UnitMain|Thread1Func |71[132] | |000000F2|04 |0237FF78|00405FE4|HangDemo.exe|System |System |ThreadWrapper |13579[40]| |000000F2|03 |0237FF8C|770D3675|kernel32.dll|kernel32| |BaseThreadInitThunk | | |000000F2|03 |0237FF98|77B29D70|ntdll.dll |ntdll | |Unknown function at 77B29D70 near RtlInitializeExceptionChain| | |000000F2|03 |0237FFD8|77B29D4B|ntdll.dll |ntdll | |Unknown function at 77B29D4B near RtlInitializeExceptionChain| | |000000F2|03 |0237FFD8|77B29D40|ntdll.dll |ntdll | |Unknown function at 77B29D40 near RtlInitializeExceptionChain| | ------------------------------------------------------------------------------------------------------------------------------------------- [ 1504 / 5380 ] Priority: 8 Wait Chain Count = 5; Deadlock: TrueType: Thread; status: Blocked; process: [ 1A1C / 6684 ]; thread: [ 1504 / 5380 ]; wait time: 1038024; context switches: 8 Type: Unknown; status: Running; name: " "; timeout: 0; alertable: 0 Type: Unknown; status: Unknown; name: " "; timeout: 0; alertable: 0 Type: Unknown; status: Unknown; name: ""; timeout: 0; alertable: 0 Type: Unknown; status: Unknown; name: ""; timeout: 0; alertable: 0 EIP: 772D723B EFlags: 00000202 EBP: 03C1FF28 ESP: 03C1FEE8 EAX: 00BD2C30 EBX: 005E0EC0 ECX: 00000000 EDX: 00000000ESI: 00BD2C30 EDI: 00000401 SegCS: 00000023 CegSS: 0000002B SegGS: 0000002B SegFS: 00000053 SegES: 0000002B SegDS: 0000002B ------------------------------------------------------------------------------------------------------------------------------------------- |Methods |Details|Stack |Address |Module |Unit |Class |Procedure/Method |Line | ------------------------------------------------------------------------------------------------------------------------------------------- |Calling Thread: ID=5380; Priority=??; Class= | |-----------------------------------------------------------------------------------------------------------------------------------------||00000008|03 |00000000|772D723B|user32.dll |USER32 | |Unknown function at 772D723B near GetPropW | | |000000F2|03 |03C1FF2C|772DCC02|user32.dll |USER32 | |Unknown function at 772DCC02 near GetWindow | | |000000F2|03 |03C1FF2C|772DCD7C|user32.dll |USER32 | |SendMessageW | | |000000F2|03 |03C1FF50|772DCD35|user32.dll |USER32 | |SendMessageW | | |000000F2|04 |03C1FF50|004B350F|HangDemo.exe|UnitMain|UnitMain|Thread2Func |85[67] | |000000F2|04 |03C1FF78|00405FE4|HangDemo.exe|System |System |ThreadWrapper |13579[40]| |000000F2|03 |03C1FF8C|770D3675|kernel32.dll|kernel32| |BaseThreadInitThunk | | |000000F2|03 |03C1FF98|77B29D70|ntdll.dll |ntdll | |Unknown function at 77B29D70 near RtlInitializeExceptionChain| | |000000F2|03 |03C1FFD8|77B29D4B|ntdll.dll |ntdll | |Unknown function at 77B29D4B near RtlInitializeExceptionChain| | |000000F2|03 |03C1FFD8|77B29D40|ntdll.dll |ntdll | |Unknown function at 77B29D40 near RtlInitializeExceptionChain| | -------------------------------------------------------------------------------------------------------------------------------------------Unfortunately, WCT output is not very well formatted yet (that’s my home-work! :) ), but you still can track wait chains. Besides, there are call stacks for threads (without system debug info – that’s my second home-task!), which strongly hint what is happening.
Nothing extremely hard here.
The second case is significantly harder. Because hang is not an error here – it’s just a consequence of another problem.
Okay, so you run application in Delphi and it hangs, so we put it on pause. We have only one thread, so WCT won’t give you any useful hints, even if it’s available. So we switch to main thread and analyze call stack:
And again: by clicking on call stack’s items we can see source code.
But analyzing call stack only is not enough this time. It’s unclear what happened. And application seems even not hanging – it’s doing something. That’s why we start doing single-step debugging to see, what application is doing. After walking a bunch of lines, we discover that application is busy doing some cycle with Sleep inside. This cycle constantly checking some flag. We can see that this code belongs to FastMM. And by reading comments, we realize that FastMM is trying to acquire some kind of lock. The flag is “busy/free” switch. Since FastMM is checking this flag for an hour - at this point it becomes clear that something isn’t right. Besides, we have only one thread in application – there is nobody else, who can be waited for. In other words, the state of flag is no longer corresponds to reality. I.e. it’s corrupted.
Unfortunately, resolving memory corruption is not that easy work and it’s another a big and separate topic, which I’ve finished discussing not so long ago.
So, the task of this case is to find the reason. We’ve found it: it’s a memory corruption problem. So, our hang analysis is done, but the problem is not identified yet and isn’t solved. So, the next step is analyzing for memory problems.
Actually, this second case looks the same in all tools: we get the same call stack, which can vary from time to time, but it will point to Sleep in 99% of cases. So we just check it few times, see the same values and suppose endless cycle here. We analyze, why there can be endless cycle and make an educated guess about memory problems. Here is example of the same call stack in Process Explorer:
Okay, I’m done for today. Hope that you’ve enjoyed today’s lesson.
P.S. If you want – there is an additional bit of information: how to get source line from pointer/address – see "How to find the exception source line" session here.
