关于.net:记一次-NET-某医院HIS系统-CPU爆高分析

13次阅读

共计 6242 个字符，预计需要花费 16 分钟才能阅读完成。

前几天有位敌人加 wx 埋怨他的程序在高峰期总是莫名其妙的 cpu 爆高，求助如何剖析？

和这位敌人沟通下来，据说这问题困扰了他们几年😂，还请了微软的工程师过去解决，无疾而终，应该还是没找对微软的大佬。。。

对于程序 CPU 爆高的问题，老读者应该晓得我都写了好几篇了，基本上归为两类：

GC 触发
大量 lock 锁

少部分就是各种莫名其妙的问题了，无奈一一列举 🤣🤣🤣，既然敌人找到我了，我得想方法给他解决，话不多聊，上 windbg。

遇到这种问题，首查 同步块表 曾经是我的惯性思维了，命令很简略 !syncblk。


0:000> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock Owner
-----------------------------
Total           20779
CCW             16
RCW             21
ComClassFactory 0
Free            16490

我去，扑了一个空，同步块表中啥也没有。。。既然和锁没关系，那就看看线程吧，毕竟线程就是靠 CPU 养着的。

要想查看零碎中的 托管线程，能够应用 !t 命令, 线程比拟多，略微简化一下。


0:000> !t
ThreadCount:      135
UnstartedThread:  0
BackgroundThread: 132
PendingThread:    0
DeadThread:       1
Hosted Runtime:   no
                                                                                                        Lock  
       ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
  34    1 25d4 000001ea28702130    28220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     Ukn 
  74    2 3ed0 000001ea286fa940    2b220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     MTA (Finalizer) 
  76    3 4a70 000001f4447d7810  102a220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     MTA (Threadpool Worker) 
  77    4 326c 000001f4447dbe60    21220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     Ukn 
  78    6 2dac 000001f4447d9750  1020220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     Ukn (Threadpool Worker) 
  79    7 1468 000001f444a2d6f0    21220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 1     Ukn (GC) 
  80    8   f0 000001f444a2cf20    21220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     Ukn 
  81    9 3118 000001f444a2f630    21220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     Ukn

先卖个关子，可有敌人看出这些线程有什么同样？？？对，线程 79 的最初一列有一个 Ukn (GC) 标记，我想你必定好奇，这阐明什么？因为底层 GC 的模式有些变更，但不管怎么说，它在肯定水平上通知你，你的程序触发了 GC，为了进一步验证，能够用 !t -special 看下 79 号线程到底属于什么类别以及更加具体的信息。


0:000> !t -special
ThreadCount:      135
UnstartedThread:  0
BackgroundThread: 132
PendingThread:    0
DeadThread:       1
Hosted Runtime:   no
                                                                                                        Lock  
       ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
  34    1 25d4 000001ea28702130    28220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 0     Ukn 
  79    7 1468 000001f444a2d6f0    21220 Preemptive  0000000000000000:0000000000000000 000001ea286ee080 1     Ukn (GC) 

OSID Special thread type
41 38d8 DbgHelper 
42 1c88 GC 
74 3ed0 Finalizer 
75 402c ProfilingAPIAttach 
76 4a70 Timer
79 1468 GC SuspendEE

从最初一行输入中能够看到，79 就是 GC 线程，前面还有一个奇怪的 SuspendEE 标记，你又好奇了，这又啥意思？

SuspendEE = Suspend CLR Execution Engine (EE)

也就是说，79 号线程把 CLR 执行引擎 给解冻了，目标很简略，就是为了不便其余31 个 GC 线程 打理以后的 托管堆，不过这老哥机器真🐂👃，32core，也不晓得哪家医院这么给力，补充一下，用 !cpuid 验证。


0:000> !cpuid
CP  F/M/S  Manufacturer     MHz
 0  6,62,4  <unavailable>   2600
 1  6,62,4  <unavailable>   2600
 2  6,62,4  <unavailable>   2600
 3  6,62,4  <unavailable>   2600
 xxx
31  6,62,4  <unavailable>   2600

既然预判到了是 GC 触发，下一步就能够把所有线程的托管和非托管堆栈全副调进去。

要想查看各个线程的托管和非托管栈很简略, 应用 !eestack 即可，而后能够检索关键词 WaitUntilGCComplete 来判断有多少线程在期待 GC 处理完毕。

从图中能够看出，以后有 40 个线程被阻塞了，真好，问题越来越清晰了，接下来再剖析到底是哪个线程做了什么不该做的事，导致 GC 触发，同样也能够搜 try_allocate_more_space 来判断哪些线程正在调配空间。

我去，能够很显著的看出以后 170 和 187 号线程正在调配大对象 gc_heap::allocate_large_object 触发了 GC，自身大对象堆是一个令人生畏的货色，对它的回收打扫都是十分耗 CPU 资源的，这也和敌人说到的 1 分钟左右 CPU 就降落了 的状况比拟吻合。

当初关注点就在这两个线程上了，我看了下这两个线程栈都是同一处办法，所以这里就挑一个 187 线程来剖析吧，能够用 !clrstack 看下它的托管栈。


0:187> !clrstack 
OS Thread Id: 0x1ef0 (187)
        Child SP               IP Call Site
00000054ce631e30 00007ffc4021bde2 System.String.FillStringChecked(System.String, Int32, System.String)
00000054ce631e70 00007ffc402222a8 System.String.ConcatArray(System.String[], Int32)
00000054ce631ed0 00007ffc40223528 System.String.Concat(System.String[])
00000054ce631f40 00007ffbe6dbdafb BLL.xxx.xxx.GetRowString(System.String, Boolean, Boolean, System.String, System.String, System.String, System.String, System.String, System.String, Int32, System.String, System.String, System.String, System.String, System.String, System.String, Int32, Int32, System.String, System.Nullable`1, System.Nullable`1, System.String, System.Nullable`1, System.Nullable`1, System.Nullable`1, System.Nullable`1, System.String, System.String, System.String, System.String, System.String ByRef)
00000054ce65cf40 00007ffbe6ab3187 BLL.xxx.xxx.ExpZB(System.String, Boolean, Boolean, System.String, System.String, System.String, System.String, Int32, System.String, System.String, System.String, Int32, System.String, System.String, System.String, System.String, System.String, System.String, Int32, Int32, System.String, System.Nullable`1, System.Nullable`1, System.String, System.Nullable`1, System.Nullable`1, System.Nullable`1, System.Nullable`1, System.String, System.String, System.String, System.String)

从堆栈上看，貌似是应用了 System.String.Concat 拼接 string 所致，好家伙，string 拼接这么多年不晓得被人鞭挞了多少次，还是有很多的人踩坑😓😓😓，为了进一步验证，能够应用 !clrstack -p + !da -details xxx 看看这个 System.String[] 到底是什么，简化如下：


0:187> !clrstack -p
OS Thread Id: 0x1ef0 (187)
00000054ce631e70 00007ffc402222a8 System.String.ConcatArray(System.String[], Int32)
    PARAMETERS:
        values (<CLR reg>) = 0x000001ea69e8d2f8
        totalLength = <no data>
0:187> !da -details 0x000001ea69e8d2f8
Name:        System.String[]
Size:        128(0x80) bytes
Array:       Rank 1, Number of elements 13, Type CLASS
Element Methodtable: 00007ffc403d6948
[0] 000001f2391a83f0
    Name:        System.String
    MethodTable: 00007ffc403d6948
    EEClass:     00007ffc3fcd50e0
    Size:        445950(0x6cdfe) bytes
    File:        C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
    String:      xxxxx

从输入信息中能够看到，String[] 外面有 13 个元素，其中最大的一个 string 是 445950 bytes = 445k，大于大对象的 85k 界定，所以这里的 Concat 就是症结所在，同样 170 线程也是如此，接下来我还得要解决的一个问题是：为什么会有如此大的字符串产生，代码外面到底做了什么？？？要想寻找答案，还得从 dump 中导出源码一探到底。

要想剖析问题代码，能够通过 !ip2md + !savemodule 导出 BLL.xxx.xxx.GetRowString 办法。


0:187> !ip2md 00007ffbe6dbdafb
MethodDesc:   00007ffbe5342118
Method Name:  BLL.xxx.xxx.GetRowString(System.String, Boolean, Boolean, System.String, System.String, System.String, System.String, System.String, System.String, Int32, System.String, System.String, System.String, System.String, System.String, System.String, Int32, Int32, System.String, System.Nullable`1<Int32>, System.Nullable`1<Int32>, System.String, System.Nullable`1<Single>, System.Nullable`1<Single>, System.Nullable`1<Single>, System.Nullable`1<Single>, System.String, System.String, System.String, System.String, System.String ByRef)
Class:        00007ffbe52fe328
MethodTable:  00007ffbe53421d8
mdToken:      0000000006000096
Module:       00007ffbe471a890
0:187> !savemodule  00007ffbe471a890 E:\dumps\RowString.dll
3 sections in file
section 0 - VA=2000, VASize=f7fcc, FileAddr=200, FileSize=f8000
section 1 - VA=fa000, VASize=3bc, FileAddr=f8200, FileSize=400
section 2 - VA=fc000, VASize=c, FileAddr=f8600, FileSize=200

而后祭出 ILSpy 反编译这段代码。

好家伙，这写法真🐂👃，有数的字符串拼接，我都感觉 gen 和 LOH 都来不及分配内存段了😥😥😥，真的是害死 GC 了。。。

其实这是一个教科书式的问题，也有教科书式的解决办法，而且我看了下这个办法有 600 多行的代码，基本上都是做 string 拼接的事，最初说一下解决方案。

重构该办法，尽量用 StringBuilder 代替 String，将因这种 GC 触发的次数降到最低。

最初的小彩蛋，貌似这个剖析后果和敌人的深度狐疑不谋而合。。。

更多高质量干货：参见我的 GitHub: dotnetfly

正文完

.net

发表至： .net

2021-05-14

0

关于.net:最新的NET-热重载介绍

关于.net:20212022-NET-中国开发者生态调查报告

关于.net:如何在-ASPNET-Core-5-中重载-Action-方法

关于.net:开源精品-NET-定时任务-FreeScheduler-支持-cron持久化可变定时设置

关于运维:不用再找啦环境部署还得靠他

关于.net:记一次-NET-某医院HIS系统-CPU爆高分析

一：背景

1. 讲故事

二：windbg 剖析

1. 查看同步块表

2. 查看线程

3. 查看各个线程栈

4. 寻找祸首

5. 查看问题代码

三：总结

站内搜索