.NET對象與Windows句柄（三）：句柄泄露實例分析

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

1、發現問題

在程序運行約一個小時之後，經過任務管理器發現句柄數超過5000，線程數也超過1000。對於一段只須要並行接收和分析數據的簡易代碼來講，這顯然太不正常了，咱們能夠判斷程序已經產生了泄露。

 

經過任務管理器能夠很是方便的查看程序實時的資源佔用狀況，但沒法瞭解到歷史數據和趨勢。程序是一開始就須要分配和使用這麼多資源，仍是長時間運行的結果？若是是後者，那麼是運行過程當中平穩持續的增加，仍是在某個時間節點以後的忽然增加？弄清楚這些問題是必要的，咱們能夠藉此初步判斷出內存泄露是與用戶的特定操做相關，或者與特定時間點上產生的事件相關；是跟程序的初始化有關，仍是跟某些從始至終運行的後臺任務相關。

性能監視器能夠很直觀的顯示這一趨勢，其中內置了不少有用的計數器，咱們能夠從圖形化界面中觀察這些計數器值的變化規律，瞭解系統和進程的運行情況。使用Win + R組合鍵打開「運行」窗口，輸入perfmon打開性能監視器。點擊綠色加號按鈕打開「添加計數器」對話框，選擇Process中的Handle Count和Thread Count，而後選擇LeakExample進程做爲實例，添加這兩個計數器。

接下來觀察這些數值的變化。在這期間，咱們像往常同樣的使用程序，能夠重複進行一些可能形成內存泄露的操做。在運行過一段時間後，獲得了以下的圖表。句柄數和線程數在持續的增加，很容易猜想到跟Timer有關，由於Timer按期觸發，而且每次觸發都須要使用線程。即使如此，仍然須要確切的定位到底是什麼對象產生了泄露，由於實際的項目中可能用到的Timer或者後臺線程的代碼遠遠不止一兩處。

 

2、分析運行中的進程

首先應該找出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。

3、小結

針對有句柄泄露的程序，本文描述了一種分析的思路。分析的對象是運行中的進程，所以這是一種動態分析，即咱們能夠在它運行的過程當中，反覆的重現問題，然後觀察新的泄露狀況。實際的項目中，這個過程是尋找問題復現關鍵點的過程，也是反覆猜想和證明，以及發現新線索的過程。能夠進行動態分析其實是比較幸運的，由於另外一些狀況下，問題發生以後很難再次重現，或者現場環境不容許咱們進行反覆的嘗試。這時咱們須要快速的蒐集環境數據，並打好內存轉儲Dump文件，過後進行靜態分析。下一篇文章，咱們仍然用這個例子，探討如何進行Dump分析，並討論一點Timer的實現細節。