记一次 .NET 某电子厂OA系统 非托管内存泄露分析

  • 记一次 .NET 某电子厂OA系统 非托管内存泄露分析已关闭评论
  • 26 次浏览
  • A+
所属分类:.NET技术
摘要

这周有个朋友找到我,说他的程序出现了内存缓慢增长,没有回头的趋势,让我帮忙看下到底怎么回事,据朋友说这个问题已经困扰他快一周了,还是没能找到最终的问题,看样子这个问题比较刁钻,不管怎么说,先祭出 WinDbg。


一:背景

1.讲故事

这周有个朋友找到我,说他的程序出现了内存缓慢增长,没有回头的趋势,让我帮忙看下到底怎么回事,据朋友说这个问题已经困扰他快一周了,还是没能找到最终的问题,看样子这个问题比较刁钻,不管怎么说,先祭出 WinDbg。

二:WinDbg 分析

1. 托管还是非托管泄露

一直关注这个系列的朋友都知道,托管和非托管的排查是两个体系,分析方式完全不一样,所以要鉴定是哪一块的内存问题,首先要用 !address -summary 观察进程的 虚拟内存 布局。

 0:000> !address -summary  --- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal Free                                    710     7d93`20465000 ( 125.575 TB)           98.11% <unknown>                              7547      240`9bea8000 (   2.252 TB)  92.87%    1.76% Stack                                 33363       2c`1fae0000 ( 176.495 GB)   7.11%    0.13% Heap                                   1179        0`126d3000 ( 294.824 MB)   0.01%    0.00% Image                                  2988        0`0c274000 ( 194.453 MB)   0.01%    0.00% TEB                                   11121        0`056e2000 (  86.883 MB)   0.00%    0.00% Other                                    11        0`001d9000 (   1.848 MB)   0.00%    0.00% PEB                                       1        0`00001000 (   4.000 kB)   0.00%    0.00%  --- Type Summary (for busy) ------ RgnCount ----------- Total Size -------- %ofBusy %ofTotal MEM_MAPPED                             7302      200`071b1000 (   2.000 TB)  82.47%    1.56% MEM_PRIVATE                           45920       6c`cc766000 ( 435.195 GB)  17.52%    0.33% MEM_IMAGE                              2988        0`0c274000 ( 194.453 MB)   0.01%    0.00%  --- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal MEM_FREE                                710     7d93`20465000 ( 125.575 TB)           98.11% MEM_RESERVE                           12136      26c`84ccf000 (   2.424 TB)  99.94%    1.89% MEM_COMMIT                            44074        0`5aebc000 (   1.421 GB)   0.06%    0.00%  

从卦中看,当前进程的提交内存是 MEM_COMMIT= 1.4G, NT堆的内存占用是 Heap=294M,乍一看应该是托管内存泄露,接下来用 !eeheap -gc 观察托管堆。

 0:000> !eeheap -gc Number of GC Heaps: 12 ------------------------------ Heap 0 (0000028577D73020) generation 0 starts at 0x00000285B7000020 generation 1 starts at 0x00000285B6C00020 generation 2 starts at 0x0000028590800020 ephemeral segment allocation context: none ... ------------------------------ GC Allocated Heap Size:    Size: 0x9598958 (156862808) bytes. GC Committed Heap Size:    Size: 0xea1c7e0 (245483488) bytes.  

从卦中看很奇怪,托管堆也就 GC Committed Heap Size= 245M 的内存占用,说明问题不在托管堆上。

2. 到底是哪里的泄露

这就是本篇文章的亮点之处,毕竟没有按照以前的套路出牌,接下来问题在哪里呢? 还是得回头看下 虚拟内存布局,终于你会发现 Stack 处很奇怪,内存占用高达 TotalSize =176G, 内存段高达 RgnCount=3.3w,截图如下:

记一次 .NET 某电子厂OA系统 非托管内存泄露分析

这两个蛛丝马迹已经告诉我们当前开启了非常多的线程,可以用 !address: -f:Stack 观察线程数和线程栈信息。

 0:000> !address -f:Stack          BaseAddress      EndAddress+1        RegionSize     Type       State                 Protect             Usage --------------------------------------------------------------------------------------------------------------------------       c0`80000000       c0`8104b000        0`0104b000 MEM_PRIVATE MEM_RESERVE                                    Stack      [~139; 323a8.320a4]       c0`8104b000       c0`8104e000        0`00003000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE | PAGE_GUARD        Stack      [~139; 323a8.320a4]       c0`8104e000       c0`81050000        0`00002000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE                     Stack      [~139; 323a8.320a4]       c0`81050000       c0`8209b000        0`0104b000 MEM_PRIVATE MEM_RESERVE                                    Stack      [~140; 323a8.316b8]       c0`8209b000       c0`8209e000        0`00003000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE | PAGE_GUARD        Stack      [~140; 323a8.316b8]       c0`8209e000       c0`820a0000        0`00002000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE                     Stack      [~140; 323a8.316b8]       ...       ed`460d0000       ed`4711b000        0`0104b000 MEM_PRIVATE MEM_RESERVE                                    Stack      [~11119; 323a8.8b20]       ed`4711b000       ed`4711e000        0`00003000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE | PAGE_GUARD        Stack      [~11119; 323a8.8b20]       ed`4711e000       ed`47120000        0`00002000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE                     Stack      [~11119; 323a8.8b20]       ed`47120000       ed`4816b000        0`0104b000 MEM_PRIVATE MEM_RESERVE                                    Stack      [~11120; 323a8.9828]       ed`4816b000       ed`4816e000        0`00003000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE | PAGE_GUARD        Stack      [~11120; 323a8.9828]       ed`4816e000       ed`48170000        0`00002000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE                     Stack      [~11120; 323a8.9828]  

从卦中看,当前线程高达 1.1w 个,有点吓人,终于算是找到源头了,

3. 为什么会有 1w+ 的线程

接下来就需要鉴定下这些线程是托管线程还是非托管线程,可以用 !t 观察。

 0:000> !t ThreadCount:      11104 UnstartedThread:  0 BackgroundThread: 11099 PendingThread:    0 DeadThread:       4 Hosted Runtime:   no                                                                                                             Lock    DBG   ID     OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception   20    1    32588 0000028577D0DB30  202a020 Preemptive  0000000000000000:0000000000000000 0000028577529fc0 -00001 MTA    35    2    3262c 0000028577F3D000    2b220 Preemptive  00000285C0002660:00000285C0004008 0000028577529fc0 -00001 MTA (Finalizer)    36    4    326b4 0000028577F941B0  102b220 Preemptive  0000000000000000:0000000000000000 0000028577529fc0 -00001 MTA (Threadpool Worker)    37    5    31848 000002857811A420  202b220 Preemptive  0000000000000000:0000000000000000 0000028577529fc0 -00001 MTA    ... 11116 11100     966c 000002C620A45300  202b220 Preemptive  00000285C86CB910:00000285C86CD868 0000028577529fc0 -00001 MTA  11117 11101     95b4 000002C61B928970  202b220 Preemptive  00000285996DF978:00000285996E18D0 0000028577529fc0 -00001 MTA  11118 11102     9630 000002C61B928FC0  202b220 Preemptive  00000285996E1978:00000285996E38D0 0000028577529fc0 -00001 MTA  11119 11103     8b20 000002C620A465F0  202b220 Preemptive  00000285B46B15C0:00000285B46B3518 0000028577529fc0 -00001 MTA  11120 11104     9828 000002C61E014CB0  202b220 Preemptive  00000285C86CD910:00000285C86CF868 0000028577529fc0 -00001 MTA   

从卦中看: DBGID 的编号相差无几,说明是大多是托管线程,从后面的 MTA 来看,这是一个 new Thread 出来的线程,接下来试探看下它有没有 Name,我们拿 ThreadOBJ=000002C61E014CB0 来看吧。

 0:000> dt coreclr!Thread 000002C61E014CB0    ...    +0x1c0 m_ExposedObject  : 0x00000285`7821d160 OBJECTHANDLE__    ...  0:000> !do poi(0x00000285`7821d160) Name:        System.Threading.Thread MethodTable: 00007ffa63844320 EEClass:     00007ffa6379af48 Tracked Type: false Size:        72(0x48) bytes File:        D:rootNewWFSystem.Private.CoreLib.dll Fields:               MT    Field   Offset                 Type VT     Attr            Value Name 00007ffa63a0d608  4000b0d        8 ....ExecutionContext  0 instance 00000285c0acf930 _executionContext 00007ffa64cbaa78  4000b0e       10 ...ronizationContext  0 instance 0000000000000000 _synchronizationContext 00007ffa637afd00  4000b0f       18        System.String  0 instance 0000028590888a78 _name  0:000> !DumpObj /d 0000028590888a78 Name:        System.String MethodTable: 00007ffa637afd00 EEClass:     00007ffa6379a6e0 Tracked Type: false Size:        98(0x62) bytes File:        D:rootNewWFSystem.Private.CoreLib.dll String:      Console logger queue processing thread  

经过抽检,发现线程名都是 Console logger queue processing thread,看样子和日志有关系,接下来使用 ~*e !clrstack 查看当前所有线程,发现线程都卡在 ConsoleLoggerProcessor.TryDequeue 上,截图如下:

记一次 .NET 某电子厂OA系统 非托管内存泄露分析

看样子和微软的控制台日志组件有关系,下一步就要观察源码。

4. 从源码中寻找答案

导出源码后,利用 ILSpy 的代码回溯功能,发现是 ConsoleLoggerProcessor 类的构造函数 new 出来的线程,截图如下:

记一次 .NET 某电子厂OA系统 非托管内存泄露分析

结合海量的重复线程栈,大概可以猜测到是代码将 Singleton 的模式改成了 Transient,导致不断的 new,不断的产生新的 Thread 去处理队列。

接下来我也懒得细究代码了,让朋友重点看一下 Microsoft.Extensions.Logging.Console 组件,朋友也很给力,终于找到了是 AppService 类在不断的 new 造成的,截图如下:

记一次 .NET 某电子厂OA系统 非托管内存泄露分析

三: 总结

这次事故如果朋友有专业的 APM 监控,相信很快就能发现 Thread 爆高的问题,从 dump 中用内存来反推线程爆高,确实有一点出乎意料。

这个 dump 的教训是:理解 Singleton 和 Transient 的利弊,尽量遵循官方文档的写法吧。