记一次 .NET 某券商论坛系统 卡死分析

刘星杰

一：背景

1. 讲故事

前几个月有位朋友找到我，说他们的的web程序没有响应了，而且监控发现线程数特别高，内存也特别大，让我帮忙看一下怎么回事，现在回过头来几经波折，回味价值太浓了。
二：程序到底经历了什么

1. 在线程上找原因

这个程序内存高，线程高，无响应，尼玛是一个复合态问题，那怎么入手呢？按经验推测，大概率是由于高线程数引发的，相信大家都知道每个线程都有自己的栈空间，所以众人拾柴火焰高，可以用 !address -summary 观察下线程栈空间。

1. 0:000> !address -summary
3. --- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
4. Free                                    329     7df9`d4b93000 ( 125.976 TB)           98.42%
5. <unknown>                               994      205`2ae2e000 (   2.020 TB)  99.81%    1.58%
6. Stack                                  7215        0`e0d00000 (   3.513 GB)   0.17%    0.00%
7. Heap                                    956        0`1695f000 ( 361.371 MB)   0.02%    0.00%
8. Image                                  1468        0`07b34000 ( 123.203 MB)   0.01%    0.00%
9. TEB                                    2405        0`012ca000 (  18.789 MB)   0.00%    0.00%
10. Other                                    10        0`001d1000 (   1.816 MB)   0.00%    0.00%
11. PEB                                       1        0`00001000 (   4.000 kB)   0.00%    0.00%
12. ...
14. --- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
15. MEM_FREE                                329     7df9`d4b93000 ( 125.976 TB)           98.42%
16. MEM_RESERVE                            3132      203`e925c000 (   2.015 TB)  99.56%    1.57%
17. MEM_COMMIT                             9917        2`42201000 (   9.033 GB)   0.44%    0.01%

复制代码

从卦中可以清晰的看到，提交内存是9G，同时Stack吃掉了3.5G，一般来说 Stack 不会有这么大，所以此事必有妖，在 TEB 中可以看到线程数高达 2405 个，这个确实不少哈，可以用 !t 做一个验证。

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

复制代码

有了这个入口点，接下来观察每一个线程的线程栈，使用 ~*e !clrstack发现有大量的线程在 PostMethod 方法中的 Task.Result 上等待，看样子是在做网络请求，这里做了一下提前截断，截图如下：

由于是知名券商，这里就尽量模糊了哈。。。请见谅，知道了在 Task.Result 上，一下子就开心起来了，自此也被误入歧途。。。。
2. 误入歧途

• 是上下文导致的吗？
  

过往经验告诉我，很多时候的 Task.Result 卡死是因为上下文的关系所致，所以重点看下是不是 Asp.NET 的程序，使用 !eeversion 观察便知。

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

复制代码

从卦中数据看当前是 .net6 写的程序，就不存在上下文一说了，这个情况可以排除，只能继续寻找其他突破口。。。

• 下游处理过慢导致的吗？
  

是不是下游处理过慢，一个突破点就是观察下 线程池队列 是不是有任务积压，这个可以用 !tp 观察下队列即可。

从卦中数据看当前队列无任何积压，说明也不是下游处理过慢导致的，我去，太难了。。。

• 代理或者服务器有问题吗？
  

既然无上下文，无积压，接下来只能怀疑是不是server方有问题或者用了什么代理软件？要想找这个信息，需要用 !dso 观察线程栈中的对象。

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

复制代码

看了下卦中的请求地址：http://xxx/Article/xxx， 同时在 HttpWindowsProxy 和 HttpClient 中也没有看到所谓的代理IP，这就陷入了迷茫。
事已至此，只能怀疑是网络的问题，让朋友在程序卡死的那个期间段用 wireshark 或者 tcpdump 去抓下包，看看是不是网络出了问题，tcp握手挥手怎么样，事情也就这样不了了之了。
3. 迷途知返

前些天在给训练营的朋友准备课件时，优化了一个例子来演示 线程池队列 的堆积情况，结果意外发现 sos 吐出来的数据是假的，尼妈，如梦初醒，分析dump已经够难了，为什么 sos 还要欺骗我，天真的塌下来了。。。
其实在分析 .net core 的dump时，每每发现线程池队列都是 0 ，虽然有一丝奇怪，但也不敢怀疑sos吐出来的数据权威性。
既然 sos 吐出来的数据是假的，只能自己去线程池中把队列挖出来，即 ThreadPoolWorkQueue.workItems 字段，如下所示：

1. 0:034> !DumpObj /d 0000003517b9c1c0
2. Name:        System.Threading.ThreadPoolWorkQueue
3. MethodTable: 00007ffd8416d260
4. EEClass:     00007ffd84196ab8
5. Tracked Type: false
6. Size:        168(0xa8) bytes
7. File:        C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.4\System.Private.CoreLib.dll
8. Fields:
9.               MT    Field   Offset                 Type VT     Attr            Value Name
10. 00007ffd83ddbf28  4000c61       18       System.Boolean  1 instance                0 loggingEnabled
11. 00007ffd83ddbf28  4000c62       19       System.Boolean  1 instance                0 _dispatchTimeSensitiveWorkFirst
12. 00007ffd8416dc78  4000c63        8 ...Private.CoreLib]]  0 instance 0000003517b9c268 workItems
13. 00007ffd8416e458  4000c64       10 ...Private.CoreLib]]  0 instance 0000003517b9eea0 timeSensitiveWorkQueue
14. 00007ffd8416d1f0  4000c65       20 ...acheLineSeparated  1 instance 0000003517b9c1e0 _separated
16. ...
18. 0:034> !ext dcq 0000003517b9c268
19. System.Collections.Concurrent.ConcurrentQueue<System.Object>
20.    1 - dumpobj 0x00000032c93b7ce0
21.    2 - dumpobj 0x00000032c93b8ae8
22.    3 - dumpobj 0x00000032c93b98d8
23.    ...
24. 54346 - dumpobj 0x00000034d12fb2e8
25. 54347 - dumpobj 0x0000003652805b40
26. ---------------------------------------------
27. 54347 items

复制代码

从卦中数据看当前线程池堆积了 5.3w 的任务，很显然是属于第二种情况，即下游处理不及，既然处理不急，是不是遇到了什么高峰期呢？这个可以用 .time 观察下当前时段。

从卦中数据看，看样子是快到 收盘时间 了，结合今年的大盘形式，看样子是出现了暴跌，股民们在发泄情绪，哈哈。。。
找到了问题的根，解决方案就比较多了。

• 做 PostMethod 请求的异步化，不要用 Result 去硬等待。
  
• 尽量做批量化提交，降低请求接口的单次时间。
  

三：总结

这次生产事故的分析峰回路转，本来是一个很容易就能定位出的问题，可我认为权威的sos居然吐出了假数据欺骗了我，让我误入歧途，浪费了很多的人力物力，真的很无语。。。再也不相信 sos 了！

来源:https://www.cnblogs.com/huangxincheng/archive/2023/11/14/17831401.html
免责声明：由于采集信息均来自互联网，如果侵犯了您的权益，请联系我们【E-Mail:cb@itdo.tech】 我们会及时删除侵权内容，谢谢合作！