2013年3月12日 星期二

.NET Debugging Demos Lab 3: Memory - Review

原始文章:
.NET Debugging Demos Lab 3: Memory
.NET Debugging Demos Lab 3: Memory - Review

Set up a performance monitor log

  1. 開啟http://127.0.0.1/Links.aspx 頁面
  2. 開啟效能監視器(所有程式→系統管理工具)
    1. 執行→新增資料收集器集合工具→名稱lab3-memory、手動建立
    2. 勾選效能計數器
    3. 新增(抽樣間隔1秒):
      1. .NET CLR Memory的w3wp
      2. Process的w3wp
    4. 根目錄→可以自選(ex. D:\Logs)
    5. 執行身分(工作管理員權限)
    6. 點選儲存後開啟

Reproduce the problem

  1. 用迴圈執行http://127.0.0.1/Links.aspx 4000次
    1. 在cmd.exe在tinyget的安裝目錄下執行 "tinyget -srv:localhost -uri:/BuggyBits/Links.aspx -loop:4000"
    2. 用VS的壓測工具
    3. Note:可以依自己電腦而調降迴圈次數,避免電腦產生記憶體不足的情況。
  2. 停止效能監視器的lab-memory

Examine the performance logs點選效能監視工具→效能監視器右圖上方工具列→檢視紀錄檔資料

    1. 點選記錄檔:選擇log所在位置 D:\Log\....
    2. 時間範圍:選擇測試4000次loop的時間
    3. 資料→新增下列資料,並調整刻度到0.0000001
      • .NET CLR Memory/# Bytes in all Heaps
      • .NET CLR Memory/Large Object Heap Size
      • .NET CLR Memory/Gen 2 heap size
      • .NET CLR Memory/Gen 1 heap size
      • .NET CLR Memory/Gen 0 heap size
      • Process/Private Bytes
      • Process/Virtual Bytes
    • Q:這些Counter最後的值為?(請把時間範圍取在所有Counter保持水平的)
    • Q:比較Virtual Bytes, Private Bytes and #Bytes in all Heaps的曲線,是否有異同之處
    • A:Virtual Bytes, Private Bytes and #Bytes in all Heaps曲線接相似,這代表所有的heap(.net GC memory)都有逐漸增加memory的使用(),
    • 根據以下的經驗法則,可以辨識是何種的"leak"
      • a.virtual bytes jump, private bytes stay flat =>產生virtual byte leak
        • 有部分物件保存在記憶體但沒有被用到→利用debug diag找到他
      • b. private bytes jump but #Bytes in all heaps stay flat => native or loader heap leak. 
        • 利用debug diag 和/或確認集合的數量是否增加 (counter under .net clr loading)
      • c. #Bytes in all heaps and private bytes follow eachother => 檢視  .net GC 的heaps
    • Virtual bytes and Private bytes擁有不小的差距,這是很正常的,因為有不少的記憶體都拿去作為 GC heaps (and other things like dlls etc.)。virtual bytes增加是以階梯的方式增加,是因為其他的 heaps (and other mem) 也是如此增加。
    • Q:可以從記錄檔中看出是屬於何種leak?(a native "leak", a .net memory "leak" or a leak on the loader heap)
    • A:比較屬於事前者,看起來像 .net GC memory issue.
    • Q:在log的最後 (在tinyget 結束或壓測結束後)memory的曲線是保持flat還是降下來?
    • A:曲線保持flat,因為記憶體配置已經被更改過了。
  1. 增加.NET CLR Memory/# Gen 0 Collections, .NET CLR Memory/# Gen 1 Collections, .NET CLR Memory/# Gen 2 Collections
    • Q: 是否有任何的Collection在測試結束後產生?如果沒有,為什麼?
    • A:沒有,因為garbage collections只有發生在allocations或是在呼叫GC.Collect()時才會發生,因此在執行完壓測後,並沒有人會去執行collect 直到必要的時候。
  2. 開啟工作做管理員,處理程序頁籤下:檢視→選取欄位→選擇虛擬記憶體大小(認可大小),比較記憶體使用率跟虛擬記憶體大小的值以及紀錄中Private Bytes跟Virtual Bytes的值。(Note: 由於使用的單位是K所以必須要乘以1024)
    • Q: 記憶體使用率顯示甚麼?
    • Q: 虛擬記憶體顯示甚麼?
    • A:在尚未執行dump之前的記憶體使用率約為4960MB, 當執行memory dump跳到5145MB。這邊重要的是要了解是這數字代表的意思。
    • From the task manager helpfiles we have the following info about these columns..............
    • Performance monitor has these explanations about the counters we added
      Private Bytes"the current size, in bytes, of memory that this process has allocated that cannot be shared with other processes."
      Virtual Bytes"the current size, in bytes, of the virtual address space the process is using. Use of virtual address space does not necessarily imply corresponding use of either disk or main memory pages. Virtual space is finite, and the process can limit its ability to load libraries."
      Working Set"the current size, in bytes, of the Working Set of this process. The Working Set is the set of memory pages touched recently by the threads in the process. If free memory in the computer is above a threshold, pages are left in the Working Set of a process even if they are not in use. When free memory falls below a threshold, pages are trimmed from Working Sets. If they are needed they will then be soft-faulted back into the Working Set before leaving main memory."
      #Bytes in all heaps"This counter is the sum of four other counters; Gen 0 Heap Size; Gen 1 Heap Size; Gen 2 Heap Size and the Large Object Heap Size. This counter indicates the current memory allocated in bytes on the GC Heaps."
      Gen 0 heap size"This counter displays the maximum bytes that can be allocated in generation 0 (Gen 0); its does not indicate the current number of bytes allocated in Gen 0. A Gen 0 GC is triggered when the allocations since the last GC exceed this size. The Gen 0 size is tuned by the Garbage Collector and can change during the execution of the application. At the end of a Gen 0 collection the size of the Gen 0 heap is infact 0 bytes; this counter displays the size (in bytes) of allocations that would trigger the next Gen 0 GC. This counter is updated at the end of a GC; its not updated on every allocation."
      Gen 1 heap size"This counter displays the current number of bytes in generation 1 (Gen 1); this counter does not display the maximum size of Gen 1. Objects are not directly allocated in this generation; they are promoted from previous Gen 0 GCs. This counter is updated at the end of a GC; its not updated on every allocation."
      Gen 2 heap size"This counter displays the current number of bytes in generation 2 (Gen 2). Objects are not directly allocated in this generation; they are promoted from Gen 1 during previous Gen 1 GCs. This counter is updated at the end of a GC; its not updated on every allocation."
      LOH size"This counter displays the current size of the Large Object Heap in bytes. Objects greater than 20 KBytes 85000 bytes are treated as large objects by the Garbage Collector and are directly allocated in a special heap; they are not promoted through the generations. This counter is updated at the end of a GC; its not updated on every allocation."
       A few things of note here...
      1. Gen 0 heap size shows the budget for Gen 0, not the size of the objects in Gen 0.
      2. Gen 0, 1, 2 and LOH counters are updated after each collection, not after each allocation.
      3. The LOH explanation says that objects over 20 k are large objects, that used to be the case in 1.0 but has changed since then and since the counters are not version specific this hasn't been updated. For 1.1. and 2.0 it is 85000 bytes. 
      4. The working set consists of the pages loaded in RAM that have been recently touched by the process, it really doesn't have anything to do with the private bytes of the process (which is what we usually look at when we look at the memory usage of the process), it may be more and it may be less than private bytes. For winforms apps (non-services) there is usually a big difference in the workingset when you minimize the apps since the pages are then trimmed from the working set.  For services (like ASP.NET that usually doesnt happen so private bytes and working sets tend to stay in the same range) 

Get a memory dump


  1. 以工作管理員開啟cmd.exe移至debuggers的目錄輸入"Adplus -hang -pn w3wp.exe -o D:\dumps"
  2. 設定Symbol路徑及載入SOS
    1. Q:dump多大?
    2. A:1.07GB
    3. Q:跟Private Bytes, Virtual Bytes and # Bytes in all Heaps.差異?
    4. A:Private Bytes(6.25GB), Virtual Bytes(58.4GB) and # Bytes in all Heaps(0.85GB)跟 # Bytes in all Heaps相近.

Examine the memory to get an idea of where the memory is going

  1. 執行 !address -summary (可看到大約的記憶體使用情況)。Hint: 可以參考WinDbg的說明文件
    1. Q: Which values corresponds best to the following
      1. Private Bytes 
        1. A:MEM_PRIVATE
      2. Virtual Bytes
        1. A:NONE
    2. Q: Where is most of the memory going (which RegionType)?
      1. <unknown> 
    3. Q: What does Busy, Pct(Busy) and Pct(Tots) mean?
      1. 數據不同~無法解答
    4. Q: What does MEM_IMAGE mean?數據不同~無法解答
    5. Q: Under what region does .net memory fit in and why?數據不同~無法解答
    6. From perfmonce we could see that #Bytes in all Heaps follows Private bytes very closely meaning that the increase in memory is mostly an increase in .NET memory.  In other words we are looking for an answer to why our .net GC heaps keep growing.數據不同~無法解答

Examine the .NET GC Heaps

  •  執行 !eeheap -gc 檢視 .NET GC heaps的大小
    • Q: 有多少個Heap? 為什麼?
    • A:4個Heap,每個Processor都各擁有一個GC Heap
    • Q: .net GC heaps占用了多少記憶體 ?  跟 #Bytes in all Heaps比較看看。
    • A:0.85GB,跟#Bytes in all Heaps相近
    • Q: large object heap佔了多少空間  Hint: 加上所有Large Object heap segments.的記憶體大小,在效能管理員中比較Large Object Heap. 
    • A:最大的large object heap 不過也才0.15MB,

  •  執行 !dumpheap -stat 去以統計的方式dump出所有.net objects(Note: 可以藉由執行 !help DumpHeap 取得關於DumpHeap的指令說明或參考這篇這篇這篇)
    • Q: 比較一下5~10個使用最多記憶體的物件, 是Leaking嗎?
    • A:大部分記憶體都被String用掉,這很常見,因為大部分的應用程式都有用到String。但0.67GB好像有點不可思議 ,而且36007個Links看起來一樣很可疑,特別是在dump中stringbuilders也具備幾乎相同的數量。
    • Q: Size行所顯示的是甚麼Size?也就是說包含了哪些東西?  Hint: 查看 (!dumpheap -stat explained) 取得更多的解釋。
    • A:如果執行!do <object>(必須藉由!dumpheap -mt <string MT>去找出object的位置ex. !dumpheap -mt 00000001cca9d288上圖Link的MT位置,然後隨便找一個Object的結果~如下圖 )將會看到一個Link有 一個pointer指向 stringbuilder (url) 和一個pointer指向string (name),該Object的Size為32byte包含Pointer和一些overhead (method table etc.)。如果執行!objsize <bjext> (ex. !objsize  00000001cca9d288)就會發現該Object的實際大小為20176byte。這個大小包含了變數成員,也就是說涵蓋了所有會用到的物件。在!dumpheaps所看到的只是每個連結的32byte。不把原始物件的大小涵蓋進來的原因如下:
      • 計算時間會加長
      • 有些物件(A、B)可能回同時指向物件C,如果執行!objsize A及B,這樣都會涵蓋到C的大小,這樣會無法排除。
      • 在這個範例中,Link的大小看起來就是一個實際上只有包含一個url跟一個name的link。然而若從web control來看,它包含了另一個成員var _parent,若執行!objsize,則parent的大小也會計算到。這樣就是很明顯的不需要了。
    • 正常來說,作者在執行 !dumpheap -stat 後從在輸出的下方看到string時,已經不太會立即介紹,以下是作者的原因:
      • 輸出中所呈現的String所佔的記憶體大小,指的是真正的大小。如果比較一下dataset的大小,可以發現該數值只有涵蓋指向Array行列的Pointer,並不包含內容。所以dataset的大小將永遠比變數string小。
      • String是大部分Object的leaf nodes,也就是說datasets、aspx 網頁、session、labels etc.都包含string,所以在application中一定會有大部分的string
    • 然而在這個範例中,string太多且占據了太多記憶體,如果不找些東西來塞住,就只能隨著string一直成長。

  • 將變數string dump出來,看看是否有pattern或error,所以必須要試著輸入不同的大小進行dump,以找出龐大的string在哪。
    • 從 !dumpheap -stat的結果找出System.String的method table (MT) 並執行下列指令
      • !dumpheap -mt <string MT> -min 85000 -stat
        • (ex !dumpheap -mt 000007fee72a7ca8 -min 25000 -stat)
      • !dumpheap -mt <string MT> -min 10000 -stat
      • !dumpheap -mt <string MT> -min 20000 -stat
      • !dumpheap -mt <string MT> -min 30000 -stat
      • !dumpheap -mt <string MT> -min 25000 -stat
    • Q: 在哪個範圍內,擁有最多的object?
    • A:20000~25000

  • Dump out the strings in that range
    • !dumpheap -mt <string MT> -min 20000 -max 25000 
      • ex. !dumpheap -mt 000007fee72a7ca8  -min 20000 -max 25000
    • 在這個範例裡,幾乎所有的物件尺寸都相同,是不是有點奇怪。

  • Dump out a few of them to find out what they contain
    • !do <address of string - first column in the !dumpheap -mt output>
      • ex. !do 00000001cca9d2d0 
    • Q: What do these strings contain?
    • A:看起來是個網址。(String: http://blog.msdn.com/toddca)

  • 取一個數值並指出他們被放置在哪(也就是說為什麼他們不會被collected)Note: 可以嘗試不同的數值。
    • !gcroot <address of string>
    • Q: Where are they rooted?  Why?
    • A: The string 是tring builder的變數成員,依序是Link object而且該object位於 Finalizer queue ,這表示該like已經為finalization做好準備而且正在等被finalize

Examine the finalizer queue and the finalizer thread

  1. 查看 finalizer queue
    • 執行!finalizequeue
    • Q: What objects are listed in the finalizequeue output? Hint: run !help finalizequeue
    • A: 所有擁有finalizers/destructors皆已被註冊在 finalizer queue,所以一旦物件被garbage collected finalizer將會執行destructor除非該物件的finalization是有問題的。
    • Q: 有多少物件是處在 "ready for finalization"?  這表示?
    • A:總共約有35868個物件,這些物件已經被garbage collected 而且準備好被finalized,如果ready for finalization顯示出大於0的數字,這代表finalizer很有可能被blocked住了,這就是為什麼object會堵在waiting to be finalized 而且佔據了記憶體。

  2. 藉由執行!threads在清單內找到finalizer thread 。
  3. 移到finalizer thread 並檢視其原生stack
    • ~21s   (21 必須是finalizer thread)
    • kb 2000
    • !clrstack
    • Q: What object is it finalizing?
    • A: 正在執行 Link.Finalize()
    • Q: What is it doing?  Why is this causing high memory usage?
    • A:針對該link object的Finalizer 停留在sleep,也就是說Finalizer 被block,導致Process內沒有任何東西會被finalized,然而所有等著執行finalization 的物件都在記憶體中等著Finalizer 被unblock。

Examine the code for verification

  1. Open Link.cs to find the destructor/finalizer for the Link class to see the problematic code

Conclusion:

Performing any type of blocking operations in the finalizer is very dangerous since this causes no objects to be finalized. Apart from checking that you do not perform any blocking operations in the finalizer you should always strive to dispose/close all objects with finalizers/destructors so that you don't end up in this all too common situation.