.Net 調式案例—實驗1 hang複習回顧

.Net 調式案例—實驗1 假死（hang）複習回顧

這是10個實驗中的第一個，這個實驗中會使用叫「BuggyBits」的站點。要開始這個實驗，若是你還一籌莫展，請看我前面發表的文章。

我感受到這些「手邊的實驗」會產生不少的問題，雖然我會盡力來回答留言評論中的問題，但我不能保證我所有都回答，因此若是你看到別人的評論，你可以解答，那請你幫我解答疑一下。

注意：在實驗中的問題（Q:…..）僅僅是查找問題所在的一個幫助性提示，我會節制一些包含答案的評論，直到我發佈了對這個實驗的一個複習（Review）的文章，在原實驗發佈的一週之後我會發布覆習這個實驗的文章，給你們一個簡短的思考時間。

請自由的發表評論，不管好與壞，這樣我才能知道哪些有用哪些是沒有用的。

好了，沒有其餘的二話，開始第一個實驗：

問題再現

1） 瀏覽http://localhost/BuggyBits/FeaturedProducts.aspx 。這大約會過5秒後顯示，你能夠在頁面底部看到開始時間和執行時間。

2） 打開5個瀏覽器，指向同一個地址，而後同時的刷新他們。注意他們每個的執行時間，你要保證他們每個的開始時間都是幾乎一致的。（若是不是，那你沒有運行那個註冊表文件）。
Q：執行時間是多少？
A：瀏覽器1：5.0s，瀏覽器2：9.1s，瀏覽器3：12.57s，瀏覽器4：16.07s，瀏覽器5： 18.61s，若是你沒有看到執行時間的增加，那你要檢查一下你是否運行了那個程序壓縮包裏面的reg 註冊表文件，要否則，你會看到在全部的請求中的開始時間上都有5秒的延遲。
Q：w3wp.ext 的cpu的使用率是多少？高仍是低？
A：很是低的cpu使用率，0-5%。
　Q：出現假死（hang）症狀的潛在緣由是什麼？
A：隨着請求的時間增長，cpu使用率很是低，它表現出a）咱們在等待某個獨佔的公用的資源，b）咱們沒有進程緊密地循環，因此被阻塞可能的多是某個外部的資源。

獲得一個內存dump文件

1）打開一個命令窗口，把路徑指到調式器目錄，輸入下面的命令，但不要敲回車鍵。
adplus –hang –pn w3wp.exe –quiet
注意：quiet這個開關量是爲了讓命令在運行過程當中不會彈出詢問對話框，由於在請求結束前咱們沒有這麼多的時間來處理這些而後獲得dump文件，典型的，你遇到的對話框多是詢問你是「set cscript as your default script」、「set up your symbol path」、「you are about to gather a hang dump」，簡單的，你能夠都點「是（Yes）」。

2）重現問題，經過你前面瀏覽5個瀏覽器的方式，或者經過tinyget ，利用下面的命令 :

tinyget -srv:localhost -uri:/BuggyBits/FeaturedProducts.aspx -threads:30 -loop:50
注意：這個意思是啓動30個線程，發送50個請求到FeaturedProducts.aspx。

3） 在adplus 的命令窗口敲回車鍵，當請求還在執行中的時候獲得一個dump文件。

Q：在adplus 假死（hang）模式下，是什麼觸發了內存dump文件的產生？
A：這是一個有點疑惑的問題，dump文件的產生是你運行了adplus，它不是等到發生hang這種狀況時纔開始產生文件，這個和-crash 這個開關量不一樣，因此，你可使用-hang這個開關量，在任什麼時候候，而無須關注進程是否真的處於hang狀態時。這個也是在高內存使用率時咱們一般的作法。

Q：要抓取一個進程的內存dump文件，你須要什麼權限？

Q：dump文件保存在了哪裏？提示：查看WinDbg的幫助文件。

A：這兩個問題，略過。若有須要再回答。

在WinDbg中打開dump文件

1） 打開WinDbg，經過菜單上的「open crash dump」來打開dump文件。

2） 設置符號文件的位置。

3） 加載SOS。

檢查棧

1） 檢查本地調用堆棧

~* kb 2000

2） 檢查.net 的調用堆棧

~* e !clrstack

Q：你能看到一些式樣或認出一些調用堆棧中那些暗示一個進程在等待同步機制的部分麼？
A：dump文件裏面有許多和下面圖中相似的本地調用堆棧的線程，斜體字中的那一塊不能獲得具體的信息，由於他們是託管的。

0:066> k 2000

ChildEBP RetAddr

1156e9b4 79ed9a62 mscorwks!Thread::DoAppropriateWait+0x40

1156ea10 79e78944 mscorwks!CLREvent::WaitEx+0xf7

1156ea24 79ed7b37 mscorwks!CLREvent::Wait+0x17

1156eab0 79ed7a9e mscorwks!AwareLock::EnterEpilog+0x8c

1156eacc79f59024 mscorwks!AwareLock::Enter+0x61

1156eb34 79fc6352 mscorwks!AwareLock::Contention+0x199

1156ebd4 0ff10dd3 mscorwks!JITutil_MonContention+0xa3

WARNING: Frame IP not in any known module. Following frames may be wrong.

1156ec34 793ae896 0xff10dd3

1156ee8c6614d8c3 mscorlib_ni+0x2ee896

1156eec4 6614d80fSystem_Web_ni+0x22d8c3

1156ef00 6614d72fSystem_Web_ni+0x22d80f

00000000 00000000 mscorlib_ni+0x2c111c

下面是託管的調用堆棧：

0:066> !clrstack

OS Thread Id: 0x960 (66)

ESP EIP

1156ea4c7d61d051 [GCFrame: 1156ea4c]

1156eb88 7d61d051 [HelperMethodFrame: 1156eb88]

System.Threading.Monitor.Enter(System.Object)

1156ebdc 0ff10dd3 DataLayer.GetFeaturedProducts()

1156ec18 0ff10c6cFeaturedProducts.Page_Load(System.Object, System.EventArgs)

1156ec5866f12980

System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)

1156ec68 6628efd2

System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)

1156ec78 6613cb04 System.Web.UI.Control.OnLoad(System.EventArgs)

1156ec88 6613cb50 System.Web.UI.Control.LoadRecursive()

1156ec9c6614e12d System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)

1156ee98 6614d8c3 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)

1156eed0 6614d80fSystem.Web.UI.Page.ProcessRequest()

把他們放在一塊兒，看起來以下：

0:066> k 2000

ChildEBP RetAddr

1156e7b0 7d4e286cntdll!ZwWaitForMultipleObjects+0x15

1156e858 79ed98fd kernel32!WaitForMultipleObjectsEx+0x11a

1156e8c0 79ed9889 mscorwks!WaitForMultipleObjectsEx_SO_TOLERANT+0x6f

1156e8e0 79ed9808 mscorwks!Thread::DoAppropriateAptStateWait+0x3c

1156e964 79ed96c4 mscorwks!Thread::DoAppropriateWaitWorker+0x13c

1156e9b4 79ed9a62 mscorwks!Thread::DoAppropriateWait+0x40

1156ea10 79e78944 mscorwks!CLREvent::WaitEx+0xf7

1156ea24 79ed7b37 mscorwks!CLREvent::Wait+0x17

1156eab0 79ed7a9e mscorwks!AwareLock::EnterEpilog+0x8c

1156eacc79f59024 mscorwks!AwareLock::Enter+0x61

1156eb34 79fc6352 mscorwks!AwareLock::Contention+0x199

1156ebd4 0ff10dd3 mscorwks!JITutil_MonContention+0xa3

1156ea4c7d61d051 [GCFrame: 1156ea4c]

1156eb88 7d61d051 [HelperMethodFrame: 1156eb88]

System.Threading.Monitor.Enter(System.Object)

1156ebdc 0ff10dd3 DataLayer.GetFeaturedProducts()

1156ec18 0ff10c6cFeaturedProducts.Page_Load(System.Object, System.EventArgs)

1156ec5866f12980

System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)

1156ec68 6628efd2

System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)

1156ec78 6613cb04 System.Web.UI.Control.OnLoad(System.EventArgs)

1156ec88 6613cb50 System.Web.UI.Control.LoadRecursive()

1156ec9c6614e12d System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)

1156ee98 6614d8c3 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)

1156eed0 6614d80fSystem.Web.UI.Page.ProcessRequest()

從這個調用堆棧中，咱們從下往上讀，能夠看到 FeaturedProducts.Page_Load函數調用了DataLayer.GetFeaturedProducts() 這個函數，而這個函數調用了Monitor.Enter()，這是 .net 中嘗試獲得一個鎖（lock）的象徵。這個代碼應該看起來和下面的相似：

void GetFeaturedProducts(){

...

lock(...){

// do something

}

...

}

咱們在lock(….)這個地方卡住了，由於其餘人已經佔有了這塊東西。

尋找假死（hang）的問題點

1） 找到擁有鎖（lock）的線程ID

!syncblk

Q：那一個線程有鎖？
A：個人 !syncblk 報告以下：

0:066> !syncblk

Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner

20001c6f74 85 10f4a0a70 1ea0 30 02f07964 System.Object

-----------------------------

Total 22

CCW 2

RCW 0

ComClassFactory 0

Free 5

擁有這個鎖（lock）的線程是在最後幾列（Owning Thread Info），這裏是30，這個線程就是GetFeaturedProducts() 正在作些事情的部分，或者說擁有了咱們都要進取的鎖的部分。

Q：有多少線程在等待這個鎖？提示：MonitorHeld =1 表明擁有者，2表明等待者。
A：MonitorHeld 這裏的值是85，意味着咱們有一個擁有者和84/2=42個等待者，有42個等待着的請求要這個鎖（lock）若是咱們運行：

.shell -ci "~* e !clrstack" FIND /C "Monitor.Enter"

看看在這些調用堆棧中有多少個Monitor.Enter，它返回42，這個咱們剛纔的值吻合。

2）拿一個等待者（提示：等待者會被標誌爲AwareLock::Enter），而後看看它在幹什麼。

~5s （切換到5號線程）

kb 2000 （檢查本地棧）

!clrstack （檢查.net 棧）

Q：哪個.net 的函數在等待鎖？
A：DataLayer.GetFeaturedProducts()

3） 看看鎖擁有者在幹什麼

~30s （切換到30號線程，上面咱們看到是30號線程是擁有者）

kb 2000 （檢查本地棧）

!clrstack （檢查.net 棧）

Q：爲何會堵塞？
A：30號線程中DataLayer.GetFeaturedProducts() 調用 Thread.Sleep()，因此這個能夠解釋爲何會阻塞。

0:030> !clrstack

OS Thread Id: 0x1ea0 (30)

ESP EIP

1036ec88 7d61cca8 [HelperMethodFrame: 1036ec88] System.Threading.Thread.SleepInternal(Int32)

1036ecdc 0ff10ddd DataLayer.GetFeaturedProducts()

1036ed18 0ff10c6cFeaturedProducts.Page_Load(System.Object, System.EventArgs)

4） 檢查.net 源代碼，看看佔有鎖的函數，而後驗證你的理論。

public DataTable GetFeaturedProducts()

{

lock (syncobj)

{

//faking a long running query to the database

Thread.Sleep(5000);

//populate a table with the featured products

DataTable dt = new DataTable();

DataRow dr;

...

}

...

}

和但願的同樣，GetFeaturedProducts() 拿了一個鎖，讓線程延遲了5秒，這裏只說一個很長時間操做的佔位符，使用了一個sleep來簡化相似的操做。要使這個效果減弱在很大程度上依賴於應用程序，進一步說，就是依賴於這個操做的時間有多長，要找出它們，若是線程阻塞得比想象中的要長，經過重複的尋找來確保咱們僅僅鎖住了最小一部分的代碼來避免不少請求等待單個資源。

提示

這裏還有一些英文的很是有用的文章：

Things to ignore when debugging an ASP.NET Hang - Update for .NET 2.0

A Hang Scenario, Locks and Critical Sections

.NET Hang Debugging Walkthrough

Automated .NET Hang Analysis