21 May, 2012

What my application is doing? (introducing Threads Snapshot Tool)

Have you ever wondered what your application might do in this very moment? Have you tried to troubleshoot hangs and deadlocks?

Attaching debugger

Well, you can connect a Delphi debugger to your application. Just launch Delphi, open your project and use "Run" / "Attach to process" command. Select your process and click OK. Now you can use threads window (View / Debug windows / Threads) and call stack window (View / Debug windows / Call stack) to analyze state of your application. You may check what it's doing, check variables values, etc.

But what if debugger is not available? Sure, you can try to install and use Delphi remote debugger. What if this happens on customer's machine? Yeah, you can ask customer if he can allow you to connect to his machine, install remote debugger and analyze the case. That sounds not very comfortable...

Threads Snapshot Tool

EurekaLog 7 as well as standalone EurekaLog Tools Pack have a Threads Snapshot Tool, which can help you to peek inside running applications. Basically, it's a simple GUI exe with 1 helper DLL. You can pack it into .zip archive and send it to the customer, asking to run it on his machine. Then customer may send you log files back, so you can analyze them locally.

Here is how it looks:

UI of Threads Snapshot Tool
All you need to do is to select your running application and click on the button. This will ask you where to save log files and will take a snapshot of all threads inside selected application.

Log file was created
Here is a sample log from the hang inside some simple application:

Process [ 0E8C / 3724 ]: C:\Users\Александр\Documents\RAD Studio\Projects\RichEdit\richeditdemo.exe (2012.05.21 19:15:27)

[ 2CA8 / 11432 ] Priority: 8

EIP:    7727F8B1  EFlags: 00000246
EBP:    0018FB5C  ESP:    0018FAF0
EAX:    00000000  EBX:    00000000  ECX:    00000000  EDX:    00000000
ESI:    000006BC  EDI:    00000000
SegCS:  00000023  CegSS:  0000002B  SegGS:  0000002B  SegFS:  00000053  SegES:  0000002B  SegDS:  0000002B

DeadLock: True
Blocked waiting for thread [ 27DC / 10204 ]
thread -> thread: [ 27DC / 10204 ] is blocked -> SendMessage -> thread: [ 2CA8 / 11432 ] is blocked

-------------------------------------------------------------------------------------------------------------------------------------
|Methods |Details|Stack   |Address |Module          |Offset  |Unit        |Class           |Procedure/Method               |Line    |
-------------------------------------------------------------------------------------------------------------------------------------
|Running Thread: ID=11432; Parent=0; Priority=0                                                                                     |
|Class=; Name=                                                                                                                      |
|Comment=                                                                                                                           |
|-----------------------------------------------------------------------------------------------------------------------------------|
|7FFFFFFE|03     |00000000|7727F8B1|ntdll.dll       |0001F8B1|ntdll       |                |ZwWaitForSingleObject          |        |
|00000020|03     |0018FB60|764A118F|kernel32.dll    |0001118F|kernel32    |                |WaitForSingleObjectEx          |        |
|00000020|03     |0018FB78|764A1143|kernel32.dll    |00011143|kernel32    |                |WaitForSingleObject            |        |
|00000020|04     |0018FB8C|004E69A9|richeditdemo.exe|000E69A9|remain      |TMainForm       |FileOpen                       |351[5]  |
|00000020|03     |0018FBB4|0044AFAB|richeditdemo.exe|0004AFAB|Classes     |TBasicAction    |Execute                        |        |
|00000020|03     |0018FBBC|004658FD|richeditdemo.exe|000658FD|ActnList    |TContainedAction|Execute                        |        |
|00000020|03     |0018FBCC|004666B8|richeditdemo.exe|000666B8|ActnList    |TCustomAction   |Execute                        |        |
|00000020|03     |0018FBE0|00495F00|richeditdemo.exe|00095F00|Menus       |TMenuItem       |Click                          |        |
|00000020|03     |0018FBEC|00497413|richeditdemo.exe|00097413|Menus       |TMenu           |DispatchCommand                |        |
|00000020|03     |0018FBF4|004DB9EB|richeditdemo.exe|000DB9EB|Forms       |TCustomForm     |WMCommand                      |        |
|00000020|03     |0018FC00|00476D64|richeditdemo.exe|00076D64|Controls    |TControl        |WndProc                        |        |
|00000020|03     |0018FC18|0047B628|richeditdemo.exe|0007B628|Controls    |TWinControl     |WndProc                        |        |
|00000020|03     |0018FD7C|004D88FC|richeditdemo.exe|000D88FC|Forms       |TCustomForm     |WndProc                        |        |
|00000020|03     |0018FDA8|0047ACC8|richeditdemo.exe|0007ACC8|Controls    |TWinControl     |MainWndProc                    |        |
|00000020|03     |0018FDD8|0044B650|richeditdemo.exe|0004B650|Classes     |                |StdWndProc                     |        |
|00000020|03     |0018FE1C|750B6D35|USER32.dll      |00016D35|USER32      |                |(possible GetThreadDesktop+210)|        |
|00000020|03     |0018FE94|750B77BF|USER32.dll      |000177BF|USER32      |                |(possible CharPrevW+307)       |        |
|00000020|03     |0018FEF4|750B7885|USER32.dll      |00017885|USER32      |                |DispatchMessageW               |        |
|00000020|03     |0018FF04|004E182F|richeditdemo.exe|000E182F|Forms       |TApplication    |ProcessMessage                 |        |
|00000020|03     |0018FF20|004E1872|richeditdemo.exe|000E1872|Forms       |TApplication    |HandleMessage                  |        |
|00000020|03     |0018FF44|004E1B9D|richeditdemo.exe|000E1B9D|Forms       |TApplication    |Run                            |        |
|00000020|04     |0018FF74|004EDCE8|richeditdemo.exe|000EDCE8|richeditdemo|                |Initialization                 |15[4]   |
|00000020|03     |0018FF8C|764A3398|kernel32.dll    |00013398|kernel32    |                |BaseThreadInitThunk            |        |
-------------------------------------------------------------------------------------------------------------------------------------

[ 27DC / 10204 ] Priority: 8

EIP:    750B72B9  EFlags: 00000246
EBP:    02D0FEF8  ESP:    02D0FEB8
EAX:    00D59FB0  EBX:    02090F60  ECX:    00000000  EDX:    00000000
ESI:    00D59FB0  EDI:    00000000
SegCS:  00000023  CegSS:  0000002B  SegGS:  0000002B  SegFS:  00000053  SegES:  0000002B  SegDS:  0000002B

DeadLock: True
Blocked waiting for SendMessage owned by thread [ 2CA8 / 11432 ]
thread -> SendMessage -> thread: [ 2CA8 / 11432 ] is blocked -> thread: [ 27DC / 10204 ] is blocked

-------------------------------------------------------------------------------------------------------------------
|Methods |Details|Stack   |Address |Module          |Offset  |Unit    |Class      |Procedure/Method       |Line   |
-------------------------------------------------------------------------------------------------------------------
|Running Thread: ID=10204; Parent=0; Priority=0                                                                   |
|Class=; Name=                                                                                                    |
|Comment=                                                                                                         |
|-----------------------------------------------------------------------------------------------------------------|
|7FFFFFFE|03     |00000000|750B72B9|USER32.dll      |000172B9|USER32  |           |(possible GetPropW+146)|       |
|00000020|03     |02D0FEFC|750B96C0|USER32.dll      |000196C0|USER32  |           |SendMessageW           |       |
|00000020|04     |02D0FF20|004E6918|richeditdemo.exe|000E6918|remain  |TLoadThread|UpdateStatus           |336[1] |
|00000020|04     |02D0FF3C|004E68F6|richeditdemo.exe|000E68F6|remain  |TLoadThread|Execute                |331[1] |
|00000020|03     |02D0FF48|00448FDA|richeditdemo.exe|00048FDA|Classes |           |ThreadProc             |       |
|00000020|03     |02D0FF78|00406828|richeditdemo.exe|00006828|System  |           |ThreadWrapper          |       |
|00000020|03     |02D0FF8C|764A3398|kernel32.dll    |00013398|kernel32|           |BaseThreadInitThunk    |       |
-------------------------------------------------------------------------------------------------------------------

When you have such log file - can you determinate why the application is not responding?

Yes, now you can do it very easily. First, note that there are two threads, both of each is in a deadlock state (note "Deadlock: True"). Two deadlocks mean that these two threads are waiting for each other. Why they do it? You can determinate this either by looking at call stack or at wait chains.

Analyzing call stacks

Call stack for first thread indicate that main thread has called WaitForSingleObject function to wait for something inside it's TMainForm.FileOpen method. You can determinate what main thread waits by looking at source code:
WaitForSingleObject(LoadThread.Handle, INFINITE); // remain.pas, line 351

Second thread is a worker thread. It calls SendMessage from its UpdateStatus method. You can determinate which window will receive this message by looking at source code:
SendMessage(MainForm.Handle, WM_DoSomething, 0, 0); // remain.pas, line 336

As you can see, main thread created a worker thread to load file in the background and is waiting for its completion. And worker thread tried to update status of main window by sending a window message to it. Thus, you get a hang, because main thead is waiting for worker thread and it can not process message, which background thread has sent to it. And this is the reason for the hang.

Analyzing wait chains

And you can confirm this guess by looking at wait chains for each thread. Wait chain for main thread is:
Blocked waiting for thread [ 27DC / 10204 ]
thread -> thread: [ 27DC / 10204 ] is blocked -> SendMessage -> thread: [ 2CA8 / 11432 ] is blocked
Which means: "main thread (2CA8) is blocked by waiting for worker thread (27DC), which is blocked by SendMessage, which is waiting for thread 2CA8 (which is the main thead)".

Wait chain for worker thread is:
Blocked waiting for SendMessage owned by thread [ 2CA8 / 11432 ]
thread -> SendMessage -> thread: [ 2CA8 / 11432 ] is blocked -> thread: [ 27DC / 10204 ] is blocked
Which means: "worker thread (27DC) is blocked by SendMessage, which is waiting for main thread (2CA8), which is waiting for thread 27DC (which is the worker thread)".

So, you immediately get information about what both threads are waiting for! Any of two wait chains allows you to fully reconstruct the problem scenario.

Final notes

Threads Snapshot Tool requres debug information for your application to display human-readable call stacks. It supports all usual sources of debug information for EurekaLog 7: EurekaLog itself, map files, TD32/TDS, DLL export, JclDebug, madExcept, Microsoft formats. Therefore, if you compile your application with EurekaLog (any version) - then you do not need any additional actions. If not - then you need to supply debug information for your application. One simple way to do this - set "Map file" = "Detailed" option ("Linker" tab in project options inside IDE) and deploy .map files along with your .exe and .dll files.

Wait Chains are created only on Windows Vista and above. For Windows XP and below - only call stacks and CPU states are provided.

Threads Snapshot Tool is available in both x86-32 and x86-64 versions. You need to use application of corresponding bitness. Attempt to use 32-bit Threads Snapshot Tool to capture state of 64-bit application (and visa versa) will result in error message.

32-bit version of Threads Snapshot Tool is installed under C:\Program Files\EurekaLab\EurekaLog 7\Bin\ folder by default. 64-bit version is installed only on 64-bit editions of Windows. It's placed in C:\Program Files (x86)\EurekaLab\EurekaLog 7\Bin64\ by default.

Threads Snapshot Tool consists of ThreadsSnapshotGUI.exe and ThreadsSnapshotWorkerDLL.dll files. Those are the files which you can copy to another machine. ThreadsSnapshot.exe is a console equivalent of ThreadsSnapshotGUI.exe file. You can use it to capture state from the console by calling it with arguments (launch it without agruments to get help on using).