一:背景
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%
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
,截图如下:
这两个蛛丝马迹已经告诉我们当前开启了非常多的线程,可以用 !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
从卦中看: DBG
和 ID
的编号相差无几,说明是大多是托管线程,从后面的 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
上,截图如下:
看样子和微软的控制台日志组件有关系,下一步就要观察源码。
4. 从源码中寻找答案
导出源码后,利用 ILSpy 的代码回溯功能,发现是 ConsoleLoggerProcessor
类的构造函数 new 出来的线程,截图如下:
结合海量的重复线程栈,大概可以猜测到是代码将 Singleton 的模式改成了 Transient,导致不断的 new,不断的产生新的 Thread 去处理队列。
接下来我也懒得细究代码了,让朋友重点看一下 Microsoft.Extensions.Logging.Console
组件,朋友也很给力,终于找到了是 AppService 类在不断的 new 造成的,截图如下:
三: 总结
这次事故如果朋友有专业的 APM 监控,相信很快就能发现 Thread 爆高的问题,从 dump 中用内存来反推线程爆高,确实有一点出乎意料。
这个 dump 的教训是:理解 Singleton 和 Transient 的利弊,尽量遵循官方文档的写法吧。
服务器托管,北京服务器托管,服务器租用 http://www.fwqtg.net
机房租用,北京机房租用,IDC机房托管, http://www.e1idc.net