ASP.NET Debug系列之三：Crash調試

原文作者：Tess
原文連結：http://blogs.msdn.com/tess/archive/2008/02/11/net-debugging-demos-lab-2-crash-review.aspx
譯者：Wencui  http://www.cnblogs.com/David-Qian

前兩天翻譯了Tess Debug系列的Hang調試，今天就繼續和大家看看Tess的第三篇文章，Crash調試。同樣，由於機器的差異，可能你的調試結果和Tess有所差異，不過這個不要緊，只要你知道其中的原理就可以了。文章的圖片可能會不太清楚，如果需要，大家可以去Tess的原文上看。

ASP.NET  Debug系列之一：環境搭配 

Windbg，sos，tinyget，adplus常用命令

ASP.NET Debug系列之二：Hang調試

 

1. 問題重現

1) 瀏覽到http://localhost/BuggyBits/Reviews.aspx頁面。

2) 點擊Refresh按鈕，它將使得w3wp.exe程式crash(IIS 5下是aspnet_wp.exe)。注意，如果你裝有Visual Studio的話，Just-In-Time的訊息將會彈出，你可以點擊no按鈕，此時我們不需要來Just-in-Time 偵錯。

2. 檢查系統日誌

開啟日誌(在命令列中可以輸入eventvwr.exe)。日誌對於不同版本的系統和IIS可能會有所不同。在系統日誌中，我們可以看到這條資訊：

問題1：你的日誌是什麼樣子的？
結果1：在Tess的機器中(Windows 2003，.NET 2.0 SP1)，系統日誌如上所示。同時，在程式日誌中， 有如下兩條資訊：

從第一條資訊看，它像是一個nullreference的異常所致

第二條資訊顯示，Review的Finalize方法導致了nullreference的異常。但也有可能你看不到第二條資訊，這個因不同的系統，IIS版本，.NET版本等而異。

問題2：exit code 0xe0434f4d代表著什麼呢？
結果2：這個code是.NET異常的一個等價物。不管是SQL exception，nullreference exception還是FileNotFoundException，它們都將會用0xe0434f4d code來表示。

問題3：從這些日誌中，你能判斷是什麼導致了程式的crash嗎？
結果3：從程式日誌的第二條資訊中，我們可以很容易的看出，程式的crash是因為Finalize Review這個對象時產生的異常引起的。

3. 擷取一個dump檔案

1) 開啟http://localhost/BuggyBits/Reviews.aspx頁面，但是不要點擊"Refresh"按鈕。

2) 開啟命令列視窗並切換到debugger tools所在的目錄，然後輸入：adplus -crash -pn w3wp.exe，並立即敲斷行符號。

問題1：一個新的視窗將出現在工具列上，這個程式是什嗎？
結果1：這個程式的表徵圖是：

其實這就是debugger，它正在運行著cdb，是windbg沒有UI狀態下的等價物。

問題2：dubugger在等待著什麼呢？
結果2：下面的一張表將顯示什麼樣的events/exceptions adplus會監視，以及當其中的之一發生時，adplus將會做什麼。

一些縮寫：L=在debuglog中寫日誌，T=記錄時間，S=記錄stack，M=最小的dump，F=全的dump，E=在eventlog中寫日誌。如果你想adplus捕捉你想要的events，你可以自訂一個cfg檔案供adplus使用。

3) 在reviews頁面上點擊"Refresh"按鈕以重現問題。

問題1：在debugger tools目錄，什麼檔案被建立了？
結果1：在Tess的機器上，如下檔案被建立在crash檔案夾(名字中含有crash_mode)下：

ADPlus_report.txt
<DIR> CDBScripts
PID-4628__W3WP.EXE__Date_02-11-2008__Time_13-14-0808.log
Process_List.txt
PID-4628__W3WP.EXE__1st_chance_AccessViolation__mini_17a4_2008-02-11_13-14-19-358_1214.dmp
PID-4628__W3WP.EXE__1st_chance_Process_Shut_Down__full_17a4_2008-02-11_13-14-31-889_1214.dmp
PID-4628__W3WP.EXE__2nd_chance_NET_CLR__full_17a4_2008-02-11_13-14-20-093_1214.dmp

從上面的檔案中，我們可以看出，adplus產生了三個dump檔案。第一次的access violation(NullReferenceException)將產生一個最小的dump檔案。由於此exception並未被處理，於是引起了第二次的CLR exception。最終，導致了process的shutdown。其實，從三個dump檔案的時間戳記可以很容易的得知它們產生的順序。

4. 使用windbg調試

1) 開啟CLR exception的dump檔案(xx_2nd_chance_NET_CLR_xx)。

這裡有些要說明的地方。.NET中，exception是比較常見的。當我們的程式中拋出異常時，這個叫做1st chance。此時我們可以使用try/catch語句來捕獲這個異常。但是，如果我們並沒有及時捕獲這個異常，並且這個異常不能被.NET的全域異常處理掉，它就變成了2nd異常。任何2nd的異常都將導致process的crash。

2) 設定symbols的path，並且load sos。這些都是基本步驟，前面都提到過，不再多說。

在crash mode下，由於dump是在異常發生時產生的，因而active的thread就是發生異常的thread。

問題1：你的dump中，哪個thread是active的？
結果1：active的thread是#20。如果我們用!threads命令來查看thread的資訊的話，我們可以發現#20 thread是Finalizer thread。

5. 檢查callstack以及exception

1) 檢查native以及managed callstack。

問題1：這個thread是什麼類型的thread？
結果1：從kb 2000命令中，我們可以看出它是Finalizer thread，但是由於它是發生異常的thread，我們無法使用!clrstack來查看更多的managed callstack的資訊。

問題2：這個thread正在做什嗎？
結果2：它正在回收某些objects，在回收的過程中拋出了異常，並最終成為2nd異常。

2) 檢查exception

!pe

!pe/!PrintException 命令將列印出當前堆棧上正在被拋出的exception。

問題1：這是個什麼類型的exception？
結果1：這個是Null 參考的異常 NullReferenceException。

注意，在大多數的情況下，我們很難得到2nd exception發生前的stack trace。這樣的話，我們需要使用別的命令來找出更多的關於1st exception的資訊。

3) 在堆棧上查看更多關於1st exception的資訊

問題1：1st exception的地址是什嗎？
結果1：在中，我們可以看到2nd exception的地址是0x2f0cb3c，因而，我們比較可知，1st exception的地址是 0x6f1e5e4。

4) 查看1st exception的資訊以及callstack。

問題1：exception是在哪個方法中被拋出的？
結果1：在Review class的Finalizer方法中。

問題2：什麼object正在被回收？
結果2：是Review object。

問題3：通常情況下，當異常被拋出時，我們如果沒有使用try/catch塊的話，它將會被ASP.NET全域異常來處理，同時顯示給使用者一個錯誤提示頁面，為什麼這個異常並不能被處理，而致使process的crash呢？
結果3：ASP.NET的全域異常處理僅僅用來捕獲處理requests時的exception。在我們的例子中，異常是發生在Finalizer thread中的，它並不屬於某一個特定使用者，因而也無法將錯誤資訊顯示給某一特定使用者。這樣就導致了process的crash。

6. 驗證我們的代碼

1) 開啟Review.cs，查看它的Finalizer方法。

問題1：哪一行代碼會拋出exception？
結果1：從代碼中，我們可以很容易的看出，當string非空時，它被賦值null，這將導致NullReferenceException。如果我們並不能查看原始碼，我們可以通過!u命令來查看JIT產生的彙編代碼。這裡暫不做討論，在以後的文章中再做解釋。

同樣，這篇文章非常的長，也翻譯了很長時間，希望能夠對大家有所協助

Have a nice day!