句柄泄露實例分析
在上篇文章.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句柄。
到這里，我們有一個大致的印象，即泄露的對象是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的實現細節。