2013年3月7日 星期四

.NET Debugging Demos Lab 1: Hang - Review

Note:Debug的結果跟Thread ID會因為操作的速度以及基礎環境而有所出入。原作者使用W2k3,而作者我是用Win7。
原始出處.NET Debugging Demos Lab 1: Hang - Review

Reproduce the problem:

  1. 瀏覽http://localhost/BuggyBits/FeaturedProducts.aspx
    • 顯示這個頁面需要五秒,可以在頁面下看到開始跟執行時間。
  2. 開啟五個相同的頁面,並且盡量同時重整頁面(reflash)
    • 留意每個頁面的執行時間,並且確認開始時間是幾乎相同的(如果沒有,就代表可能沒有先執行一開始說的reg)
    • Q:執行時間分別為多少?
    • A:依序應該是5s、9.3s、13.96s、17.99、21.53(會有出入,不過如果看到的都是5s那就表示,你沒有幾乎同時的送出request)
    • Q:從工作管理員觀看w3wp.exe的CPU使用率,是高還是低?
    • A:非常低,根本就是0

Get a memory dump:

  1. 以系統管理員開啟 cmd.exe
    • 移至Debugger tool 目錄 cd C:\Program Files (x86)\Windows Kits\8.0\Debuggers\x64
  2. 先執行所要Dump的腳本
    • 開五個ie依序點開http://127.0.0.1/FeaturedProducts.aspx
    • 或者使用TinyGet 執行,產生30個Thread及50次迴圈(但我不行用)
      • tinyget -srv:localhost -uri:/BuggyBits/FeaturedProducts.aspx -threads:30 -loop:50
  3. 執行上述過程中在cmd 執行Adplus -hang -pn w3wp.exe -quiet -o D:\dumps
    • 因為dump需要很快,所以使用-quiet 避免跳出其他要求的對話框,也許還是會跳出其他的詢問視窗,不過你可以點選yes即可
    • Q:在Adplus的hang模式下,甚麼東西是觸發新的memory dump?
    • A:這是一個陷阱題。當輸入上述指令時就觸發了新的Memory dump,在hang模式下不需要任何額外的事件(不像crash),所以不必真的在系統被hanging的時候才能執行Memory dump。
    • Q:為了對Process進行Memory dump需要那些權限?
    • A:WinDbg/Adplus跟其他的Debugging工具,在權限上沒有甚麼不同。你需要擁有或取得高的使用權限。在hang模式下,dump是採用non-invasive的方式,也就是不須侵入Process。因此在進行Memory dump時,不需跟目標Process是相同winstation 。這在藉由terminal server進行Debugging服務的時候是相當方便的。在Crash模式下,就必須要在相同的winstation 上,也就是說當你用terminal server或遠端進行Debugging時,就必須要藉由log
    • Q:dump在哪產生?提示:觀看WinDbg針對adplus/hang的說明
    • A:預設的dump會被放在C:\debuggers\裡,但下指令時包含了-o D:\dumps就是為了將dumps移至特定資料夾。資料夾內回包含下列元件:
      • CDBScript:一個內含config檔的檔案,用來告知WinDbg/cdb甚麼指令需執行
        • 我的是DebuggerScript.txt
      • ADPlus_report.txt:發生資訊,也就是Adplus做了甚麼事
      • PID-5656__W3WP.EXE__Date_02-06-2008__Time_11-15-0505.log:運行的紀錄檔,在hang模式下這個記錄檔包含了所有Thread的stack、loaded modules info以及指令!runaway的輸出。如果沒有dumpfile,就可以看這個紀錄檔的內容,找出為什麼。
        • 我的是ADPlus_log_0a14_2013-03-07_14-15-59-089.log
      • PID-5656__W3WP.EXE__full_1c38_2008-02-06_11-15-08-005_1618.dmp:dump檔
        • 我的是FULLDUMP_HangMode_w3wp.exe__0a14_2013-03-07_14-15-59-143_2804.dmp
      • Process_List.txt :顯示所有dump時系統正在值得程序
        • 我沒有!!!!

Open the dump in Windbg.exe

  1. 執行WinDbg
    • Open Crush Dump 開啟dump所在位置 D:\dumps
  2. 設定symbol File Path
    • SRV*D:\Symbols*http://msdl.microsoft.com/downloads/symbols
    • 勾選reload
  3. 載入SOS
    • WinDbg 輸入.load sos
      • 必須先從C:\Windows\Microsoft.NET\Framework64\v2.0.50727複製SOS.dll到C:\Program Files (x86)\Windows Kits\8.0\Debuggers\x64
    • WinDbg 輸入.loadby sos mscorwks

Examine the stacks

  1. 檢查native callstacks
    1. 執行~* kb 2000
  2. 檢視.net callstacks
    1. 執行~* e !clrstack
    2. Q:是否有發現任何patterns或認得任何callstacks暗示有Thread這在等待synchronization mechanism
    3. A:執行後會發現有很多Thread的callstack跟下方的圖很像,原始文章中有提到部分斜體灰色內容是因為WinDbg沒有權限去看.Net底層的東西~但是我的沒有= = 
以下是.NET callstacks
把兩張圖結合起來,可以從RetAddr去比對~
黃色的區塊由下往上閱讀(stack特性),發現先呼叫了FeaturedProducts.Page_Load(System.Object, System.EventArgs)接著呼叫DataLayer.GetFeaturedProducts()接著我們會發現裡面有AwareLock::Enter這代表著正在等待.net的lock。所以編譯起來的程式應該會像是


    • void GetFeaturedProducts(){
    •   ...
    •   lock(...){
    •     // do something
    •   }
    •   ...
    • }

Troubleshoot the hang


  1. 在WinDbg執行 !syncblk 檢視擁有lock的Thread
    • Q: What thread owns the lock?
    • A
    • 最後一個Thread 資訊(我的範例是26)就是擁有lock的Thread,而這個Thread一定又在做部分的GetFeaturedProducts() 或者是hold住了我們想要進去的lock(從dump中可以發現,thread 26正在sleep)
    • Q:有多少Thread正在等待Lock?提示:MonitorHeld  = 1 代表擁有,=2代表等待
    • A:MoniterHeld 為5代表我們有(5-1)/2=2個Thread在等待,,可以藉由輸入下列指令證明計算是否正確。(Monitor.Enter代表lock~但因為我沒有呈現,所以找另一個AwareLock::Enter+)
  2. 取得其中一個Waiter(提示:Waiter的call stack有AwareLock::Enter)並且看一下它如何運作。
    • ~24s                          (移置目標Thread,我的是24)
    • kb 2000                    (檢視native stack)
    • !clrstack                    (檢視.net stack)
    • Q:哪個.Net 程式正在等待lock?
    • A:DataLayer.GetFeaturedProducts()
  3. 看看Owner的運行

    • ~24s                          (移置目標Thread,我的是24)
    • kb 2000                    (檢視native stack)
    • !clrstack                    (檢視.net stack)
    • Q:為什麼blocking?
    • A:因為DataLayer.GetFeaturedProducts()呼叫了 ThreadNative::Sleep+0xf9,這也是為什麼會被Block住的原因。(黃色區塊的第一列代表DataLayer.GetFeaturedProducts(),第二列式page_load)
  4. 根據上述推論,.Net Code應該長得像:
    • void GetFeaturedProducts(){
    •   ...
    •   lock(syncobj)
    • {
    •      Thread.Sleep(....);
    •     // do something
    •   }
    •   ...
    • }
    • 可以開啟原始檔確認。
    • 如預期,GetFeaturedProducts()具有lock而且sleep 5秒,這當然會產生較長的等待時間,不過會利用sleep是因為它是一個容易重現相同結果的範例。這個結果當然取決於大量的應用程式,不過這包含如何知道這個程式將會運行多久以及發現是否有Thread 比預期的更常被lock。
    • 藉由檢視路徑去確認是否有盡量減少lock區塊以降低單一資源的等待時間。