.NET对象与Windows句柄(三):句柄泄露实例分析

在上篇文章.NET对象与Windows句柄(二):句柄分类和.NET句柄泄露的例子中,我们有一个句柄泄露的例子。例子中多次创建和Dispose了DataReceiver和DataAnalyzer对象,但由于忘记调用DataAnalyzer的Stop方法,导致产生句柄泄露。本文假定我们已经发现了泄露现象但还不知道原因,讨论如何在这种情况下分析问题。

一、发现问题

在程序运行约一个小时以后,通过任务管理器发现句柄数超过5000,线程数也超过1000。对于一段只需要并行接收和分析数据的简易代码来说,这显然太不正常了,我们可以判断程序已经产生了泄露。

.NET对象与Windows句柄(三):句柄泄露实例分析

通过任务管理器可以非常方便的查看程序实时的资源占用情况,但无法了解到历史数据和趋势。程序是一开始就需要分配和使用这么多资源,还是长时间运行的结果?如果是后者,那么是运行过程中平稳持续的增长,还是在某个时间节点之后的突然增长?弄清楚这些问题是必要的,我们可以借此初步判断出内存泄露是与用户的特定操作相关,或者与特定时间点上产生的事件相关;是跟程序的初始化有关,还是跟某些从始至终运行的后台任务相关。

性能监视器可以很直观的显示这一趋势,其中内置了很多有用的计数器,我们可以从图形化界面中观察这些计数器值的变化规律,了解系统和进程的运行状况。使用Win + R组合键打开“运行”窗口,输入perfmon打开性能监视器。点击绿色加号按钮打开“添加计数器”对话框,选择Process中的Handle Count和Thread Count,然后选择LeakExample进程作为实例,添加这两个计数器。

接下来观察这些数值的变化。在这期间,我们像往常一样的使用程序,可以重复进行一些可能造成内存泄露的操作。在运行过一段时间后,得到了如下的图表。句柄数和线程数在持续的增长,很容易猜测到跟Timer有关,因为Timer定期触发,并且每次触发都需要使用线程。即便如此,仍然需要确切的定位究竟是什么对象产生了泄露,因为实际的项目中可能用到的Timer或者后台线程的代码远远不止一两处。

.NET对象与Windows句柄(三):句柄泄露实例分析

二、分析运行中的进程

首先应该找出5000多个句柄究竟代表什么对象。利用Process Explorer查看该进程,在下方面板中检查句柄列表,发现有大量的Event句柄和Thread句柄,更进一步的,我们想知道到底有多少Event和Thread。

.NET对象与Windows句柄(三):句柄泄露实例分析

在这个列表中难以看出各种句柄的数量。可以按下Ctrl+A组合键,将Process Explorer中的进程列表和选中进程的句柄列表保存为文本文件,而后利用你所习惯使用的文本查看工具统计其中特定句柄的数量,我们这里使用Chrome浏览器的搜索功能看到约有4063个Event句柄和1008个Thread句柄(注:也可以使用Windbg的!handle命令查看句柄统计信息)。

.NET对象与Windows句柄(三):句柄泄露实例分析

到这里,我们有一个大致的印象,即泄露的对象是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的实现细节。

上一篇:Java之字符串替换replace()


下一篇:python3.4连接mysql数据库的方法