.NET對象與Windows控制代碼（三）：控制代碼泄露執行個體分析

標籤：explorer   open   習慣   代碼   開啟   rem   event   多少   window   

在上篇文章.NET對象與Windows控制代碼（二）：控制代碼分類和.NET控制代碼泄露的例子中，我們有一個控制代碼泄露的例子。例子中多次建立和Dispose了DataReceiver和DataAnalyzer對象，但由於忘記調用DataAnalyzer的Stop方法，導致產生控制代碼泄露。本文假定我們已經發現了泄露現象但還不知道原因，討論如何在這種情況下分析問題。

一、發現問題

在程式運行約一個小時以後，通過工作管理員發現控制代碼數超過5000，線程數也超過1000。對於一段只需要並行接收和分析資料的簡易代碼來說，這顯然太不正常了，我們可以判斷程式已經產生了泄露。

 

通過工作管理員可以非常方便的查看程式即時的資源佔用情況，但無法瞭解到曆史資料和趨勢。程式是一開始就需要分配和使用這麼多資源，還是長時間啟動並執行結果？如果是後者，那麼是運行過程中平穩持續的增長，還是在某個時間節點之後的突然增長？弄清楚這些問題是必要的，我們可以藉此初步判斷出記憶體泄露是與使用者的特定操作相關，或者與特定時間點上產生的事件相關；是跟程式的初始化有關，還是跟某些從始至終啟動並執行背景工作相關。

效能監控器可以很直觀的顯示這一趨勢，其中內建了很多有用的計數器，我們可以從圖形化介面中觀察這些計數器值的變化規律，瞭解系統和進程的健全狀態。使用Win + R按鍵組合開啟“運行”視窗，輸入perfmon開啟效能監控器。點擊綠色加號按鈕開啟“添加計數器”對話方塊，選擇Process中的Handle Count和Thread Count，然後選擇LeakExample進程作為執行個體，添加這兩個計數器。

接下來觀察這些數值的變化。在這期間，我們像往常一樣的使用程式，可以重複進行一些可能造成記憶體泄露的操作。在運行過一段時間後，得到了如下的圖表。控制代碼數和線程數在持續的增長，很容易猜測到跟Timer有關，因為Timer定期觸發，並且每次觸發都需要使用線程。即便如此，仍然需要確切的定位究竟是什麼對象產生了泄露，因為實際的項目中可能用到的Timer或者後台線程的代碼遠遠不止一兩處。

 

二、分析運行中的進程

首先應該找出5000多個控制代碼究竟代表什麼對象。利用Process Explorer查看該進程，在下方面板中檢查控制代碼列表，發現有大量的Event控制代碼和Thread控制代碼，更進一步的，我們想知道到底有多少Event和Thread。

 

在這個列表中難以看出各種控制代碼的數量。可以按下Ctrl+A按鍵組合，將Process Explorer中的進程列表和選中進程的控制代碼列表儲存為文字檔，而後利用你所習慣使用的文本查看工具統計其中特定控制代碼的數量，我們這裡使用Chrome瀏覽器的搜尋功能看到約有4063個Event控制代碼和1008個Thread控制代碼（註：也可以使用Windbg的!handle命令查看控制代碼統計資訊）。

 

到這裡，我們有一個大致的印象，即泄露的對象是Event和Thread，其中Event佔大多數。下一步需要找出是誰建立出了這些對象，可以使用Windbg跟蹤對象的建立。Windbg是非常方便的Windows調試工具，可以利用強大的SOS擴充命令診斷.NET程式中的各種問題，最新的Windbg（截止2016年4月）可以從MSDN的Download the WDK, WinDbg, and associated tools頁面下載，點擊頁面上的Get Debugging Tools for Windows (WinDbg)連結即可。

將Windbg附加到LeakExample.exe進程，而後使用!handle和!htrace命令對進程控制代碼進行分析。!handle命令可以列出進程內所有控制代碼，也可以查看特定控制代碼的資訊，而!htrace顯示控制代碼的堆疊追蹤。我們先使用!htrace -enable啟用控制代碼跟蹤，然後讓進程繼續運行幾分鐘時間，再中斷程式的執行，用!htrace -diff查看自上次快照以來新開啟的控制代碼。由於命令輸出過長，一些不重要的資訊被隱去用省略符號代替。

0:482> !htrace -enable Handle tracing enabled. Handle tracing information snapshot successfully taken. 0:482> g (1988.2f3c): Break instruction exception - code 80000003 (first chance) eax=7fbc0000 ebx=00000000 ecx=00000000 edx=779fd23d esi=00000000 edi=00000000 eip=77993540 esp=5a75ff28 ebp=5a75ff54 iopl=0         nv up ei pl zr na pe nc cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000246 ntdll!DbgBreakPoint: 77993540 cc              int     3 0:015> !htrace -diff Handle tracing information snapshot successfully taken. 0x6 new stack traces since the previous snapshot. Ignoring handles that were already closed... Outstanding handles opened since the previous snapshot: -------------------------------------- Handle = 0x00000b68 - OPEN Thread ID = 0x00002a68, Process ID = 0x00001988   0x779a4b7c: ntdll!ZwCreateThreadEx+0x0000000c 0x75d3bc5d: KERNELBASE!CreateRemoteThreadEx+0x00000161 0x7643281d: KERNEL32!CreateThreadStub+0x00000020 0x6c54b51f: clr!Thread::CreateNewOSThread+0x0000009b 0x6c54b358: clr!Thread::CreateNewThread+0x000000a8 0x6c54b8ad: clr!ThreadpoolMgr::CreateUnimpersonatedThread+0x00000275 0x6c54b9fc: clr!ThreadpoolMgr::MaybeAddWorkingWorker+0x00000129 0x6c53f298: clr!ManagedPerAppDomainTPCount::SetAppDomainRequestsActive+0x0000002f -------------------------------------- Handle = 0x00000b64 - OPEN Thread ID = 0x00002a68, Process ID = 0x00001988   0x779a49fc: ntdll!ZwCreateEvent+0x0000000c 0x75d376a0: KERNELBASE!CreateEventExW+0x0000006e 0x75d376f0: KERNELBASE!CreateEventW+0x00000027 0x6c54a106: clr!CLREventBase::CreateManualEvent+0x00000036 0x6c54a84f: clr!Thread::AllocHandles+0x00000064 0x6c54b4f4: clr!Thread::CreateNewOSThread+0x00000074 0x6c54b358: clr!Thread::CreateNewThread+0x000000a8 0x6c54b8ad: clr!ThreadpoolMgr::CreateUnimpersonatedThread+0x00000275 0x6c54b9fc: clr!ThreadpoolMgr::MaybeAddWorkingWorker+0x00000129 0x6c53f298: clr!ManagedPerAppDomainTPCount::SetAppDomainRequestsActive+0x0000002f 0x6ae49bd3: mscorlib_ni+0x00389bd3 0x6adcd38c: mscorlib_ni+0x0030d38c -------------------------------------- Handle = 0x00000b60 - OPEN Thread ID = 0x00002a68, Process ID = 0x00001988   0x779a49fc: ntdll!ZwCreateEvent+0x0000000c … … -------------------------------------- Handle = 0x00000b70 - OPEN Thread ID = 0x00002a68, Process ID = 0x00001988   0x779a49fc: ntdll!ZwCreateEvent+0x0000000c … … -------------------------------------- Handle = 0x00000b54 - OPEN Thread ID = 0x00002a68, Process ID = 0x00001988   0x779a49fc: ntdll!ZwCreateEvent+0x0000000c … … -------------------------------------- Handle = 0x00000b50 - OPEN Thread ID = 0x000011f8, Process ID = 0x00001988   0x779a49fc: ntdll!ZwCreateEvent+0x0000000c … … -------------------------------------- Displayed 0x6 stack traces for outstanding handles opened since the previous snapshot.

可以看到，在兩次!htrace命令之間有6個handle被開啟，由呼叫堆疊可知其中有1個Thread對象和5個Event對象，並且在第1個Thread對象之後的4個Event都屬於該線程。如果重複!htrace -diff多次，可以發現一個規律，即每個Thread對象被建立之後，緊接著就會有4個Event對象在同一線程中被開啟，說明在本例中泄露的根源在於Thread對象，這也解釋了為什麼Event控制代碼數大致是Thread的4倍。實際上每個線程在建立的時候的確會建立4個Manual Event，從上面控制代碼開啟時的呼叫堆疊也能看出，clr!Thread::CreateNewOSThread方法除了建立Thread對象，也會建立幾個Manual Reset Event用於控制線程的掛起和恢複。

查看Event和Thread控制代碼的詳細資料，下面的輸出顯示了Thread控制代碼所指向的線程Id，以及其後的Event控制代碼資訊。

0:015> !handle 0x00000b68 f Handle b68   Type            Thread   Attributes         0   GrantedAccess    0x1fffff:          Delete,ReadControl,WriteDac,WriteOwner,Synch          Terminate,Suspend,Alert,GetContext,SetContext,SetInfo,QueryInfo,SetToken,Impersonate,DirectImpersonate   HandleCount     4   PointerCount      6   Name                   <none>   Object Specific Information     Thread Id   1988.261c     Priority    10     Base Priority 0     Start Address 6c54a086 clr!Thread::intermediateThreadProc 0:015> !handle 0x00000b64 f Handle b64   Type            Event   Attributes         0   GrantedAccess    0x1f0003:          Delete,ReadControl,WriteDac,WriteOwner,Synch          QueryState,ModifyState   HandleCount     2   PointerCount      3   Name                   <none>   Object Specific Information     Event Type Manual Reset     Event is Set

接下來查看這個新啟動的線程在執行什麼代碼，這個資訊將協助我們找到是哪裡的代碼建立了該線程。我們需要載入SOS擴充，並利用上面輸出的Thread Id資訊。

0:015> .loadby sos clr 0:015> !threads ThreadCount:      323 UnstartedThread:  0 BackgroundThread: 266 PendingThread:    0 DeadThread:       56 Hosted Runtime:   no                                                                          Lock         ID OSID ThreadOBJ    State GC Mode     GC Alloc Context  Domain   Count Apt Exception    0    1  fb8 005015e8     26020 Preemptive  4EEC2A44:00000000 004f9540 0     STA    2    2  a20 0050e080     2b220 Preemptive  00000000:00000000 004f9540 0     MTA (Finalizer)    8    5 14cc 00553c48   102a220 Preemptive  00000000:00000000 004f9540 0     MTA (Threadpool Worker)  284  280  f34 1178fa50   3029220 Preemptive  00000000:00000000 004f9540 0     MTA (Threadpool Worker)  286  283 1ff4 117bd278   3029220 Preemptive  00000000:00000000 004f9540 0     MTA (Threadpool Worker)  761  764 229c 24cfc070   3029220 Preemptive  00000000:00000000 004f9540 0     MTA (Threadpool Worker)  849  865 1bc8 490eb860   3029220 Preemptive  00000000:00000000 004f9540 0     MTA (Threadpool Worker) XXXX  868    0 490e82f0   1039820 Preemptive  00000000:00000000 004f9540 0     Ukn (Threadpool Worker)  900  900 1054 490edd58   3029220 Preemptive  00000000:00000000 004f9540 0     MTA (Threadpool Worker)  898  901  654 490d9370   3029220 Preemptive  00000000:00000000 004f9540 0     MTA (Threadpool Worker)  903  903  828 490d9e00   3029220 Preemptive  00000000:00000000 004f9540 0     MTA (Threadpool Worker) XXXX  904    0 490ead30   1039820 Preemptive  00000000:00000000 004f9540 0     Ukn (Threadpool Worker) XXXX 1004    0 11758b70   1039820 Preemptive  00000000:00000000 004f9540 0     MTA (Threadpool Worker)   10 1005 2844 117590b8   3029220 Preemptive  00000000:00000000 004f9540 0     MTA (Threadpool Worker)    7 1006  314 11759600   3029220 Preemptive  00000000:00000000 004f9540 0     MTA (Threadpool Worker) … … … … 316  804 2164 0054f960   3029220 Preemptive  00000000:00000000 004f9540 0     MTA (Threadpool Worker)  318  803 1758 24a3e810   3029220 Preemptive  00000000:00000000 004f9540 0     MTA (Threadpool Worker)  317  802 27bc 116e1540   3029220 Preemptive  00000000:00000000 004f9540 0     MTA (Threadpool Worker)    5  801 261c 117152d0   3029220 Preemptive  4EEC0C44:00000000 004f9540 0     MTA (Threadpool Worker) 0:015> ~5s eax=00000000 ebx=00000258 ecx=00000001 edx=4fa6bc17 esi=0465ee48 edi=00000000 eip=779a64f4 esp=0465ee04 ebp=0465ee6c iopl=0         nv up ei pl nz na pe nc cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000206 ntdll!KiFastSystemCallRet: 779a64f4 c3              ret 0:005> !clrstack OS Thread Id: 0x261c (5) Child SP       IP Call Site 0465eef4 779a64f4 [HelperMethodFrame: 0465eef4] System.Threading.Thread.SleepInternal(Int32) 0465ef68 6ad83365 System.Threading.Thread.Sleep(Int32) 0465ef6c 001d04cd LeakExample.DataAnalyzer.DoAnalyze(System.Object) [D: \TimerLeak\TimerLeak\Form1.cs @ 88] 0465ef7c 6adede48 System.Threading.TimerQueueTimer.CallCallbackInContext(System.Object) 0465ef80 6adc2367 System.Threading.ExecutionContext.RunInternal(… …) 0465efec 6adc22a6 System.Threading.ExecutionContext.Run(… …) 0465f000 6adedd91 System.Threading.TimerQueueTimer.CallCallback() 0465f034 6adedc4c System.Threading.TimerQueueTimer.Fire() 0465f074 6ade11a5 System.Threading.TimerQueue.FireQueuedTimerCompletion(System.Object) 0465f078 6adcdd34 System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem() 0465f08c 6adcd509 System.Threading.ThreadPoolWorkQueue.Dispatch() 0465f0dc 6adcd3a5 System.Threading._ThreadPoolWaitCallback.PerformWaitCallback() 0465f300 6c432652 [DebuggerU2MCatchHandlerFrame: 0465f300]

從呼叫堆疊可以看出，新線程是由Timer觸發的，回呼函數是DoAnalyze，參照上篇文章中的代碼，得知它就是DataAnalyzer中的analyzeTimer。這本身沒有什麼問題，但是檢查多個線程的呼叫堆疊，重複以上的步驟進行多次分析後，發現所有新增的線程都是由這個timer觸發的。Timer本身被設定為每秒觸發一次，而每次觸發的執行時間都小於一秒。出現大量的線程，說明timer對象本身產生了泄露，即進程中有大量的timer執行個體在運行，而程式設計的本意是進程中只存在一個analyzeTimer。到這裡問題已經比較明顯了，往往已經可以從代碼審查中找出問題，即analyzeTimer沒有被Dispose。

三、小結

針對有控制代碼泄露的程式，本文描述了一種分析的思路。分析的對象是運行中的進程，因此這是一種動態分析，即我們可以在它啟動並執行過程中，反覆的重現問題，而後觀察新的泄露情況。實際的項目中，這個過程是尋找問題複現關鍵點的過程，也是反覆猜測和證實，以及發現新線索的過程。可以進行動態分析實際上是比較幸運的，因為另一些情況下，問題發生之後很難再次重現，或者現場環境不允許我們進行反覆的嘗試。這時我們需要快速的搜集環境資料，並打好記憶體轉儲Dump檔案，事後進行靜態分析。下一篇文章，我們仍然用這個例子，探討如何進行Dump分析，並討論一點Timer的實現細節。

.NET對象與Windows控制代碼（三）：控制代碼泄露執行個體分析