技術文章 » 記一次 .NET 某RFID標籤管理系統 CPU 暴漲分析

記一次 .NET 某RFID標籤管理系統 CPU 暴漲分析

2022-07-22 12:06:19

一：背景

1. 講故事

前段時間有位朋友說他的程式 CPU 出現了暴漲現象，由於程式是買來的，所以問題就比較棘手了，那既然找到我，就想辦法幫朋友找出來吧，分析下來，問題比較經典，有必要和大家做一下分享。

二：WinDbg 分析

1. CPU 真的爆高嗎

一直關注這個系列的朋友應該知道，用 !tp 驗證即可。


0:161> !tp
CPU utilization: 81%
Worker Thread: Total: 486 Running: 486 Idle: 0 MaxLimit: 8191 MinLimit: 24
Work Request in Queue: 0
--------------------------------------
Number of Timers: 1
--------------------------------------
Completion Port Thread:Total: 6 Free: 1 MaxFree: 48 CurrentLimit: 6 MaxLimit: 1000 MinLimit: 24

果然 CPU =81% ，並且當前的 481 個工作執行緒全部打滿，以經驗看可能是遇到鎖什麼的，不過還是先從是否觸發 GC 看起。

2. 是觸發 GC 了嗎？

要檢視是否觸發 GC，可以用 !t -special 看看是否有 SuspendEE 字樣。


0:161> !t -special
ThreadCount:      604
UnstartedThread:  0
BackgroundThread: 587
PendingThread:    0
DeadThread:       11
Hosted Runtime:   no
                          
         OSID Special thread type
       29 2e74 DbgHelper 
       30 1014 GC SuspendEE 
       31 4a84 GC 
       32 4a48 GC 
       ...
       52 37c0 GC 
       53 47a0 GC 
       54 4620 Finalizer 
       55 1aa4 ProfilingAPIAttach
       ...

從卦中看，30號執行緒果然掛了 SuspendEE，並且還是一個 GC 執行緒，接下來切過去看看此時 GC 正在做什麼？


0:161> ~~[1014]s
eax=00000000 ebx=0724fc10 ecx=00000000 edx=00000000 esi=00000000 edi=0724fc10
eip=77ddf02c esp=0724fbd0 ebp=0724fc34 iopl=0         nv up ei pl nz ac po nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000212
ntdll!NtDelayExecution+0xc:
77ddf02c c20800          ret     8
0:030> k
 # ChildEBP RetAddr      
00 0724fc34 758345da     ntdll!NtDelayExecution+0xc
01 0724fc34 738a74eb     KERNELBASE!SleepEx+0x8a
02 0724fc78 73a0f710     clr!EESleepEx+0x59
03 0724fc78 73a0f809     clr!SVR::gc_heap::mark_steal+0x27c
04 0724fcd0 73a17930     clr!SVR::gc_heap::mark_phase+0x3d0
05 0724fd0c 73a17dc9     clr!SVR::gc_heap::gc1+0xf2
06 0724fd5c 73a174a1     clr!SVR::gc_heap::garbage_collect+0x746
07 0724fd78 73a10d7e     clr!SVR::gc_heap::gc_thread_function+0x14a
08 0724fd98 73a10d0f     clr!SVR::gc_heap::gc_thread_stub+0x72
09 0724fdac 750e62c4     clr!GCThreadStub+0x1f
0a 0724fdc0 77dd1f69     kernel32!BaseThreadInitThunk+0x24
0b 0724fe08 77dd1f34     ntdll!__RtlUserThreadStart+0x2f
0c 0724fe18 00000000     ntdll!_RtlUserThreadStart+0x1b

從卦中的 gc_thread_function 函數看，這是一個阻塞版的 GC 執行緒，當前正處於 mark_phase 標記階段，並且還在搶其他 GC 執行緒的活，有點意思。。。

既然是觸發了 GC ，那就看下觸發了哪一代以及什麼原因觸發的。


0:030> x clr!*gc_heap::settings*
73f15da8          clr!WKS::gc_heap::settings = <no type information>
73f13520          clr!SVR::gc_heap::settings = <no type information>
0:030> dp 73f13520 
73f13520  00002df0 00000002 00000001 00000001
73f13530  00000000 00000000 00000000 00000000
73f13540  00000000 00000000 00000000 00000000
73f13550  00000000 00000000 00000005 00000001
73f13560  00000000 00000000 00000000 00000001
73f13570  00000000 0000005a 00000000 00000001
73f13580  05f71b40 86b2ee2e 00040000 00000001
73f13590  00000002 00002000 00000002 00000000

從卦中的 00000002 和 00000005 可知，當前觸發的是 2代 GC，原因是 5，那 5 是什麼意思？ 可以看下 clr 中的 gc_reason 即可。


enum gc_reason
{
    reason_alloc_soh = 0,
    reason_induced = 1,
    reason_lowmemory = 2,
    reason_empty = 3,
    reason_alloc_loh = 4,
    reason_oos_soh = 5,
    reason_oos_loh = 6,
    reason_induced_noforce = 7, // it's an induced GC and doesn't have to be blocking.
    reason_gcstress = 8,        // this turns into reason_induced & gc_mechanisms.stress_induced = true
    reason_lowmemory_blocking = 9,
    reason_induced_compacting = 10,
    reason_lowmemory_host = 11,
    reason_pm_full_gc = 12, // provisional mode requested to trigger full GC
    reason_lowmemory_host_blocking = 13,
    reason_bgc_tuning_soh = 14,
    reason_bgc_tuning_loh = 15,
    reason_bgc_stepping = 16,
    reason_max
};

也就是上面的 reason_oos_soh，表示當前的小物件堆中的段空間滿了，那是不是呢？ 可以用 !eeheap -gc 看下託管堆。


0:030> !eeheap -gc
Number of GC Heaps: 24
------------------------------
Heap 0 (06d00138)
generation 0 starts at 0xe8a380ec
generation 1 starts at 0xe8a380e0
generation 2 starts at 0x07311000
ephemeral segment allocation context: (0xe8a380f8, 0xe8a38104)
 segment     begin  allocated      size
07310000  07311000  0830fd5c  0xffed5c(16772444)
a86a0000  a86a1000  a969fd10  0xffed10(16772368)
e8a10000  e8a11000  e8a380f8  0x270f8(159992)
Large object heap starts at 0x1f311000
 segment     begin  allocated      size
1f310000  1f311000  1f4cafb0  0x1b9fb0(1810352)
Heap Size:       Size: 0x21deb14 (35515156) bytes.
------------------------------
...
Heap 22 (06d76910)
generation 0 starts at 0xbfd5d228
generation 1 starts at 0xbfd5ce20
generation 2 starts at 0x1d311000
ephemeral segment allocation context: (0xbfd5d234, 0xbfd5d240)
 segment     begin  allocated      size
1d310000  1d311000  1e30fe64  0xffee64(16772708)
bed60000  bed61000  bfd5d234  0xffc234(16761396)
Large object heap starts at 0x2a311000
 segment     begin  allocated      size
2a310000  2a311000  2a311010  0x10(16)
Heap Size:       Size: 0x1ffb0a8 (33534120) bytes.
...
------------------------------
GC Heap Size:    Size: 0x2f6f6d18 (795831576) bytes.

可以看到，heap 上很多都是 segment=16M 打滿狀態，停。。。為什麼 segment 只有 16M ，出現了一個重大線索。

3. 重大線索解讀

一個 Server 版的 GC，擁有高達 24 個邏輯核，居然只有 16M 的 segment，這麼小的 segment，很容易被一些快進快出的大記憶體操作給打滿，也就更容易造成 GC 觸發，而且還是 Full GC，版本資訊如下：


0:030> !eeversion
4.7.3416.0 retail
Server mode with 24 gc heaps
SOS Version: 4.7.3416.0 retail build

接下來到執行緒棧上找找有沒有快進快出的大記憶體操作。

4. 尋找大記憶體操作

既然有快進快出的操作，在 GC 觸發時肯定還會躺在 託管堆 上，我們就從這裡入手。


0:030> !dumpheap -stat
Statistics:
      MT    Count    TotalSize Class Name
...
06cd1750   638727     15899642      Free
30361270   171401     19196912 xxxx.Entities.ProductInventoryLog
30360f90   537090     32225400 xxxx.Entities.ProductInventoryEpcDetail
30f9a148   171404     67875600 System.Data.Entity.Core.Objects.StateManagerValue[]
3036074c   694875     97282500 xxxx.Entities.ProductBorrow
727efd60  8419815    394836372 System.String
Total 14577631 objects
Fragmented blocks larger than 0.5 MB:
    Addr     Size      Followed by
9b0bf500    0.5MB         9b141878 System.Byte[]

從託管堆看，有不少的類物件，接下來抽一個 xxxx.Entities.ProductInventoryEpcDetail 看下參照，然後查根物件的 size。

0:161> !gcroot a8780ecc
Thread 40b8:
    df90d330 715d143a System.Linq.Enumerable+<JoinIterator>d__38`4[[System.__Canon, mscorlib],[System.__Canon, mscorlib],[System.__Canon, mscorlib],[System.__Canon, mscorlib]].MoveNext()
        esi: 
            ->  090eeba4 System.Linq.Enumerable+<JoinIterator>d__38`4[]
                ...
            ->  a8780e80 xxxx.Entities.ProductInventoryEpcDetail[]
            ->  a8780ecc xxxx.Entities.ProductInventoryEpcDetail

Found 1 unique roots (run '!GCRoot -all' to see all roots).

其實這個參照鏈特別長，用 !objsize 090eeba4 顯示物件大小，一直都是卡住中，size 肯定不小， 接下來我們切入到 40b8 看下這個方法，可以發現一個非常複雜的 EF 寫法，又是 outer，又是 inner，又要再關聯，截圖如下：

到這裡大物件操作終於找到了，我發現還有其他方法也有一些 EF 複雜操作，就不一一列舉了。

三：總結

這個 dump 給我們兩個教訓：

  1. 當 sql 很複雜時，千萬不要用 EF 去寫，這中間會產生多少個臨時物件你真的搞不清楚，你也hold不住，建議直接改成 sql，簡單粗暴。

  2. 程式儘量用 64bit 部署，否則你的 segment 會太小，太容易讓 GC 上頭了。

圖片名稱