句柄泄露实例分析
在上篇文章.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: TimerLeakTimerLeakForm1.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的实现细节。