技術文章 » 記一次 .NET 某券商論壇系統 卡死分析

記一次 .NET 某券商論壇系統 卡死分析

2023-11-14 15:01:46

一：背景

1. 講故事

前幾個月有位朋友找到我，說他們的的web程式沒有響應了，而且監控發現執行緒數特別高，記憶體也特別大，讓我幫忙看一下怎麼回事，現在回過頭來幾經波折，回味價值太濃了。

二：程式到底經歷了什麼

1. 線上程上找原因

這個程式記憶體高，執行緒高，無響應，尼瑪是一個複合態問題，那怎麼入手呢？按經驗推測，大概率是由於高執行緒數引發的，相信大家都知道每個執行緒都有自己的棧空間，所以眾人拾柴火焰高，可以用 !address -summary 觀察下執行緒棧空間。


0:000> !address -summary

--- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
Free                                    329     7df9`d4b93000 ( 125.976 TB)           98.42%
<unknown>                               994      205`2ae2e000 (   2.020 TB)  99.81%    1.58%
Stack                                  7215        0`e0d00000 (   3.513 GB)   0.17%    0.00%
Heap                                    956        0`1695f000 ( 361.371 MB)   0.02%    0.00%
Image                                  1468        0`07b34000 ( 123.203 MB)   0.01%    0.00%
TEB                                    2405        0`012ca000 (  18.789 MB)   0.00%    0.00%
Other                                    10        0`001d1000 (   1.816 MB)   0.00%    0.00%
PEB                                       1        0`00001000 (   4.000 kB)   0.00%    0.00%
...

--- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_FREE                                329     7df9`d4b93000 ( 125.976 TB)           98.42%
MEM_RESERVE                            3132      203`e925c000 (   2.015 TB)  99.56%    1.57%
MEM_COMMIT                             9917        2`42201000 (   9.033 GB)   0.44%    0.01%

從卦中可以清晰的看到，提交記憶體是9G，同時Stack吃掉了3.5G，一般來說 Stack 不會有這麼大，所以此事必有妖，在 TEB 中可以看到執行緒數高達 2405 個，這個確實不少哈，可以用 !t 做一個驗證。


0:000> !t
ThreadCount:      2423
UnstartedThread:  0
BackgroundThread: 2388
PendingThread:    0
DeadThread:       34
Hosted Runtime:   no
                                                                                                            Lock  
 DBG   ID     OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
   0    1     3344 00000032972B2D90  202a020 Preemptive  0000000000000000:0000000000000000 0000003297125a30 -00001 MTA 
  11    2     1d28 00000037A43B9140    2b220 Preemptive  000000364BC5AD90:000000364BC5C328 0000003297125a30 -00001 MTA (Finalizer) 
  12    5     2a00 00000037A52BF4D0  102a220 Preemptive  00000036527EBDE8:00000036527EDD90 0000003297125a30 -00001 MTA (Threadpool Worker) 
  13    7     3168 00000037A52C1B40  302b220 Preemptive  00000034D1136688:00000034D1137FD0 0000003297125a30 -00001 MTA (Threadpool Worker) 
  15   14     13b8 00000037A542EA50  202b220 Preemptive  00000036527EBCA8:00000036527EBD90 0000003297125a30 -00001 MTA 
...

有了這個入口點，接下來觀察每一個執行緒的執行緒棧，使用 ~*e !clrstack發現有大量的執行緒在 PostMethod 方法中的 Task.Result 上等待，看樣子是在做網路請求，這裡做了一下提前截斷，截圖如下：

由於是知名券商，這裡就儘量模糊了哈。。。請見諒，知道了在 Task.Result 上，一下子就開心起來了，自此也被誤入歧途。。。。

2. 誤入歧途

  1. 是上下文導致的嗎？

過往經驗告訴我，很多時候的 Task.Result 卡死是因為上下文的關係所致，所以重點看下是不是 Asp.NET 的程式，使用 !eeversion 觀察便知。


0:000> !eeversion
6.0.422.16404 free
6,0,422,16404 @Commit: be98e88c760526452df94ef452fff4602fb5bded
Server mode with 8 gc heaps
SOS Version: 7.0.8.30602 retail build

從卦中資料看當前是 .net6 寫的程式，就不存在上下文一說了，這個情況可以排除，只能繼續尋找其他突破口。。。

  1. 下游處理過慢導致的嗎？

是不是下游處理過慢，一個突破點就是觀察下 執行緒池佇列 是不是有任務積壓，這個可以用 !tp 觀察下佇列即可。

從卦中資料看當前佇列無任何積壓，說明也不是下游處理過慢導致的，我去，太難了。。。

  1. 代理或者伺服器有問題嗎？

既然無上下文，無積壓，接下來只能懷疑是不是server方有問題或者用了什麼代理軟體？要想找這個資訊，需要用 !dso 觀察執行緒棧中的物件。


0:000> ~34s
ntdll!NtWaitForMultipleObjects+0xa:
00007ffe`115c0cba c3              ret
0:034> !dso
OS Thread Id: 0x1ef4 (34)
RSP/REG          Object           Name
00000037B56AC688 000000351f9e4918 System.Threading.Thread
00000037B56AC700 0000003317bb6160 System.Net.Http.DiagnosticsHandler
00000037B56AC708 000000351f9e4918 System.Threading.Thread
00000037B56AC748 0000003617b743c8 System.Net.Http.HttpWindowsProxy
...
00000037B56AD0D0 00000034c8283750 System.String    http://xxx/Article/xxx
00000037B56ACF30 0000003317bb5ad8 System.Net.Http.HttpClient
...

看了下卦中的請求地址：http://xxx/Article/xxx， 同時在 HttpWindowsProxy 和 HttpClient 中也沒有看到所謂的代理IP，這就陷入了迷茫。

事已至此，只能懷疑是網路的問題，讓朋友在程式卡死的那個期間段用 wireshark 或者 tcpdump 去抓下包，看看是不是網路出了問題，tcp握手揮手怎麼樣，事情也就這樣不了了之了。

3. 迷途知返

前些天在給訓練營的朋友準備課件時，優化了一個例子來演示 執行緒池佇列 的堆積情況，結果意外發現 sos 吐出來的資料是假的，尼媽，如夢初醒，分析dump已經夠難了，為什麼 sos 還要欺騙我，天真的塌下來了。。。

其實在分析 .net core 的dump時，每每發現執行緒池佇列都是 0 ，雖然有一絲奇怪，但也不敢懷疑sos吐出來的資料權威性。

既然 sos 吐出來的資料是假的，只能自己去執行緒池中把佇列挖出來，即 ThreadPoolWorkQueue.workItems 欄位，如下所示：


0:034> !DumpObj /d 0000003517b9c1c0
Name:        System.Threading.ThreadPoolWorkQueue
MethodTable: 00007ffd8416d260
EEClass:     00007ffd84196ab8
Tracked Type: false
Size:        168(0xa8) bytes
File:        C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.4\System.Private.CoreLib.dll
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ffd83ddbf28  4000c61       18       System.Boolean  1 instance                0 loggingEnabled
00007ffd83ddbf28  4000c62       19       System.Boolean  1 instance                0 _dispatchTimeSensitiveWorkFirst
00007ffd8416dc78  4000c63        8 ...Private.CoreLib]]  0 instance 0000003517b9c268 workItems
00007ffd8416e458  4000c64       10 ...Private.CoreLib]]  0 instance 0000003517b9eea0 timeSensitiveWorkQueue
00007ffd8416d1f0  4000c65       20 ...acheLineSeparated  1 instance 0000003517b9c1e0 _separated

...

0:034> !ext dcq 0000003517b9c268
System.Collections.Concurrent.ConcurrentQueue<System.Object>
   1 - dumpobj 0x00000032c93b7ce0
   2 - dumpobj 0x00000032c93b8ae8
   3 - dumpobj 0x00000032c93b98d8
   ...
54346 - dumpobj 0x00000034d12fb2e8
54347 - dumpobj 0x0000003652805b40
---------------------------------------------
54347 items

從卦中資料看當前執行緒池堆積了 5.3w 的任務，很顯然是屬於第二種情況，即下游處理不及，既然處理不急，是不是遇到了什麼高峰期呢？這個可以用 .time 觀察下當前時段。

從卦中資料看，看樣子是快到 收盤時間 了，結合今年的大盤形式，看樣子是出現了暴跌，股民們在發洩情緒，哈哈。。。

找到了問題的根，解決方案就比較多了。

  • 做 PostMethod 請求的非同步化，不要用 Result 去硬等待。

  • 儘量做批次化提交，降低請求介面的單次時間。

三：總結

這次生產事故的分析峰迴路轉，本來是一個很容易就能定位出的問題，可我認為權威的sos居然吐出了假資料欺騙了我，讓我誤入歧途，浪費了很多的人力物力，真的很無語。。。再也不相信 sos 了！

圖片名稱