SFTSRC.StockTrader asp.net 2.0 web application will be used to introduce you to a series of debugging labs. We will start with a simple asp.net application which crashes and follow up with memory leak, memory fragmentation, application performance and application hang.
The first lab in series will show you how an application can crash if you are not being careful while implementing finalizer.
Website user gets “Server Application Unavailable error” message from time to time.
ASP.NET Debugging Lab
This lab is prepared based on a production issue resolved at a customer site. Please note that you can download this debugging lab from here. Web project/solution has been created using visual studio 2008.
What will you learn
1. How to debug asp.net application
2. How to identify what is causing asp.net application pool to recycle
3. WinDbg / sos basic commands to analyze a crash dump
Breaking down your thought process
1. Since website user gets to see a generic error handler page, you will need to identify why http request is failing.
2. As shown in the above diagram, website and webservice are hosted on two different servers, so you need to identify the server where request is failing
3. You should look at the http error logs/iis logs and the events logs on each server to identify the issue
4. Logs will also help you determine if there is a network issue
After looking at the server logs, we have determined that worker process is getting recycled on a sever hosting Sftsrc Stock Trading WebService. A worker process can get recycled depending on the configuration, low on virtual memory, crash due to unhandled exception etc. Let’s assume that you don’t have any information on what has caused worker process to recycle
Let’s look at the lab which is prepared based on the above issue description.
We will analyze this issue using Lab01- Download it from here.
1. Once you download the lab, create 2 virtual directory “StockTrader” and “TradeWS”
2. “StockTrader” will be set to folder “\Lab01\SFTSRC.StockTrader”
3. “TradeWS” will be set to folder “\Lab01\SFTSRC.UnmanagedService”
4. Browse to http://localhost/StockTrader/Default.aspx
You will see the website as shown below
5. Enter Stock Symbol, Quantity, Price and click on Submit Order
6. Once you submit an order, you will see “Server Unavailable Error” page in a few seconds.
7. If you look at the iis log, you will see http 503 error
please visit http://www.w3.org/Protocols/rfc2616/rfc2616-sec10.html for description on HTTP 1.1 status code
8. Event log will have the error message “asp.net process recycle or stopped unexpectedly.”
9. Attach a debugger to your worker process
10. we will use adplus configuration file to get a crash dump on first chance access violation.
11. download accessviolation.cfg from here
12. go to your windbg folder and run the following command
cscript.exe adplus.vbs -c accessviolation.cfg
13. Browse to http://localhost/StockTrader/Default.aspx again
14. Once you get “server unavailable error”, you should have the dump files created under your windbg folder
15. Please note that adplus configuration file has <ProcessName>aspnet_wp.exe</ProcessName> by default, if you are using windows server then change it to <ProcessName>w3wp.exe</ProcessName>. You may have multiple dumps created if you have more than one application pool. You can identify the worker process id for the application pool hosting TradeWS and then you can create a dump based on process id.
16. Open the dump file( *****.EXE__1st_chance_AccessViolation__full_*****c.dmp) using windbg
17. Run following command to load sos dll
0:009> .loadby sos mscorwks
18. You should always run !analyze -v when you are doing a crash dump analysis, most of the time this one command is enough to tell you what has caused the crash
0:009> !analyze -v
Attempt to read from address 00000000
0195F948 05CD0848 SFTSRC_UnmanagedService!SFTSRC.UnmanagedService.UnmanagedService.GetTLS()+0×20
0195F950 05CD07E6 SFTSRC_UnmanagedService!SFTSRC.UnmanagedService.UnmanagedService.Finalize()+0x1e
I have omitted most of the output for the sake of brevity.
19. You will notice that application has crashed while executing Finalize
20. On a side note you can look at all the Exception objects on managed heap with the following command
0:009> !dumpheap -type Exception
21. disassemble managed method Finalize using IP
0:009> !u 05cd07e6
05cd07e0 ff15c005cc05 call dword ptr ds:[5CC05C0h] (SFTSRC.UnmanagedService.UnmanagedService.GetTLS(), mdToken: 06000028)
>>> 05cd07e6 8bce mov ecx,esi
· You will notice that Exception is occurring while calling GetTLS, where it tries to assign the return value
22. On a side note, you can use View->Registers window to look at registers for the current thread or use r command
23. disassemble managed method GetTLS using IP
0:009> !u 05cd0848
05cd0841 e81a085b73 call mscorlib_ni+0x1c1060 (79281060) (System.Threading.Thread.GetData(System.LocalDataStoreSlot), mdToken: 060012f3)
05cd0846 8bc8 mov ecx,eax
>>> 05cd0848 8b01 mov eax,dword ptr [ecx]
24. You will notice that this is occurring right while calling to System.Threading.Thread.GetData() and ecx register is null
25. SOS dll has powerful command to look at clr data structure. We are going to look at GetTLS() implementation by dumping the IL(intermediate language) of this method
26. in order to dumpil, you have to first convert instruction pointer IP to Method Descriptor
0:009> !ip2md 05cd0848
Method Name: SFTSRC.UnmanagedService.UnmanagedService.GetTLS()
0:009> !dumpil 05cc05b8
ilAddr = 05c72250
IL_0000: ldstr “ThreadSpecificData”
IL_0005: call System.Threading.Thread::GetNamedDataSlot
IL_000c: call System.Threading.Thread::GetData
IL_0011: callvirt System.Object::ToString
IL_0016: callvirt System.String::get_Length
27. As shown in above IL, it has crashed while converting System.Threading.Thread::GetData object to String so that means System.Threading.Thread::GetData is returning NULL
Application Pool crashed on finalizer thread while executing Thread.GetData(). If you are not familiar with Thread Local Storage, please read it on MSDN http://msdn.microsoft.com/en-us/library/ms686749.aspx . Thread.GetData get the allocated data from thread slot but the issue here is, thread data slots are unique per thread. No other thread (not even a child thread) can get that data. Please see more details on MSDN http://msdn.microsoft.com/en-us/library/system.threading.thread.getdata.aspx . We all know that Finalizer runs on a separate thread and a finalizer thread wakes up when it the Q is notified.
You will see that in SFTSRC.UnmanagedService.UnmanagedService.CreateTLS() method, we are allocating the data slot which is in a totally different thread that’s why Finalizer thread doesn’t have access to thread specific data and resulting in crash.
You can run the following command to look at all the thread stacks
OS Thread Id: 0x11cc (20)
05c4ec64 7c90e4f4 [HelperMethodFrame: 05c4ec64] System.GC.WaitForPendingFinalizers()
05c4ecb4 05cd07aa SFTSRC.UnmanagedService.UnmanagedService.CreateTLS()
05c4ecc0 05cd06e8 TradeWebService.OrderService.SendOrder(System.String, UInt32, Int32, System.String, System.String)
You will notice that, while sending the order, we create a TLS and then in order to force GC and Finalizer, CreateTLS() method calls GC.Collect and GC.WaitForPendingFinalizers.
Never access a thread specific data in Finalizer. This lab uses Thread Local Storage to show you the thread specific data but it could be anything. For example, in windows application, thread which creates a handle or control owns it so you can’t access those in finalizer.
1. use !tls command to look at Thread Local Storage slot
2. use !teb to get familiar with thread environment block and how to use it with !tls
3. ~ command to display all the threads and get their corresponding TEB
4. Search memory to find which thread has created the slot