记一次 .NET 某物流API系统 CPU爆高分析

这篇具有很好参考价值的文章主要介绍了记一次 .NET 某物流API系统 CPU爆高分析。希望对大家有所帮助。如果存在错误或未考虑完全的地方,请大家不吝赐教,您也可以点击"举报违法"按钮提交疑问。

一:背景

1. 讲故事

前段时间有位朋友找到我,说他程序CPU直接被打满了,让我帮忙看下怎么回事,截图如下:

记一次 .NET 某物流API系统 CPU爆高分析

看了下是两个相同的程序,既然被打满了那就抓一个 dump 看看到底咋回事。

二:为什么会打满

1. 真的被打满了吗

凡事都要用数据说话,我们使用 !tp 命令观察一下。


0:014> !tp
logStart: 62
logSize: 200
CPU utilization: 100 %
Worker Thread: Total: 16 Running: 0 Idle: 16 MaxLimit: 32767 MinLimit: 8
Work Request in Queue: 0
--------------------------------------
Number of Timers: 8
--------------------------------------
Completion Port Thread:Total: 9 Free: 2 MaxFree: 16 CurrentLimit: 9 MaxLimit: 1000 MinLimit: 8

从卦象看果然是被打满了,那为什么会满呢?一般来说CPU高是线程抬起来的,接下来我们就从线程入手。

2. 线程都在做什么事情

要想观察每个线程都在做什么,可以使用 ~*e !clrstack 命令,打完所有的线程栈后,明显发现有 6 处在 System.Text.RegularExpressions.RegexReplacement.Replace 正则替换这里,截图如下:

记一次 .NET 某物流API系统 CPU爆高分析


0:021> ~14s
ntdll!NtWaitForSingleObject+0x14:
00007ff9`c5d4fa74 c3              ret
0:014> !clrstack
OS Thread Id: 0x6ee0 (14)
        Child SP               IP Call Site
000000AC6CBF99C8 00007ff9c5d4fa74 [HelperMethodFrame: 000000ac6cbf99c8] 
000000AC6CBF9AC0 00007ff942416c05 System.String.Create[[System.Text.SegmentStringBuilder, System.Text.RegularExpressions]](Int32, System.Text.SegmentStringBuilder, System.Buffers.SpanAction`2<Char,System.Text.SegmentStringBuilder>) 
000000AC6CBF9B20 00007ff942416aeb System.Text.SegmentStringBuilder.ToString()
000000AC6CBF9BA0 00007ff9422e62ac System.Text.RegularExpressions.RegexReplacement.Replace(System.Text.RegularExpressions.Regex, System.String, Int32, Int32)
000000AC6CBF9C70 00007ff9422e4ec6 System.Text.RegularExpressions.Regex.Replace(System.String, System.String, System.String, System.Text.RegularExpressions.RegexOptions) 
000000AC6CBF9CD0 00007ff941e157aa SqlSugar.UtilMethods.ReplaceSqlParameter(System.String, SqlSugar.SugarParameter, System.String)
000000AC6CBF9F80 00007ff941e42990 SqlSugar.SqlSugarProvider+d__245`1[[System.Int32, System.Private.CoreLib]].MoveNext()
000000AC6CBFA300 00007ff94190e93c System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[[System.__Canon, System.Private.CoreLib]](System.__Canon ByRef)
000000AC6CBFA360 00007ff941e420bd SqlSugar.SqlSugarProvider.SaveQueuesProviderAsync[[System.Int32, System.Private.CoreLib]](Boolean, System.Func`3<System.String,System.Collections.Generic.List`1<SqlSugar.SugarParameter>,System.Threading.Tasks.Task`1>)
000000AC6CBFA3D0 00007ff941e41a52 SqlSugar.SqlSugarProvider+d__224.MoveNext()
000000AC6CBFA480 00007ff94190e93c System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[[System.__Canon, System.Private.CoreLib]](System.__Canon ByRef)
000000AC6CBFA4E0 00007ff941e418f4 SqlSugar.SqlSugarProvider.SaveQueuesAsync(Boolean)
000000AC6CBFA550 00007ff941e417fe SqlSugar.SqlSugarClient.SaveQueuesAsync(Boolean)
000000AC6CBFA5A0 00007ff941e4177e SqlSugar.SqlSugarScope.SaveQueuesAsync(Boolean)
000000AC6CBFA5F0 00007ff941e40fce xxx.Repository.BaseRepository`1+d__76[[System.__Canon, System.Private.CoreLib]].MoveNext()
...
000000AC6D4FAAF0 00007ff9422c9d0c xxx.xxxService+d__15.MoveNext()
...

从上面的 MoveNext 和 AsyncMethodBuilder 来看,这里用的是全异步写法,分析起来那是一个头大哈。。。不过仔细观察是 SqlSugar 在替换sql参数的时候引发的,一般来说和 Regular 有关的操作都是蛮耗 CPU 的,然后顺手看了下cpu配置也才 8 核,难怪 CPU 直接 100% 了。


0:014> !cpuid
CP  F/M/S  Manufacturer     MHz
 0  6,85,7  <unavailable>   2500
 1  6,85,7  <unavailable>   2500
 2  6,85,7  <unavailable>   2500
 3  6,85,7  <unavailable>   2500
 4  6,85,7  <unavailable>   2500
 5  6,85,7  <unavailable>   2500
 6  6,85,7  <unavailable>   2500
 7  6,85,7  <unavailable>   2500


3. SqlSugar 到底在做什么

要想知道做什么,逆向一下代码就好,截图如下:

记一次 .NET 某物流API系统 CPU爆高分析

这种写法好不好我就不评价了,至少简单粗暴,那为什么会很耗时呢?这就要扒一下 ReplaceSqlParameter 方法中的三个参数,尤其是 itemSql 字段,然后使用 !clrstack -a


0:014> !clrstack -a
OS Thread Id: 0x6ee0 (14)
        Child SP               IP Call Site
000000AC6CBF9CD0 00007ff941e157aa SqlSugar.UtilMethods.ReplaceSqlParameter(System.String, SqlSugar.SugarParameter, System.String)
    PARAMETERS:
        itemSql (0x000000AC6CBF9F80) = 0x0000023d802e1020
        itemParameter (0x000000AC6CBF9F88) = 0x0000023c4bd3ae58
        newName (0x000000AC6CBF9F90) = 0x0000023ca9dd3328
    LOCALS:
        0x000000AC6CBF9F68 = 0x0000000000000000

0:014> !do 0x0000023d802e1020
Name:        System.String
MethodTable: 00007ff93caad698
EEClass:     00007ff93ca89d60
Tracked Type: false
Size:        21391508(0x1466894) bytes
File:        C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.12\System.Private.CoreLib.dll
String:      <String is invalid or too large to print>

Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ff93ca99480  40002f2        8         System.Int32  1 instance         10695743 _stringLength
00007ff93c9fea10  40002f3        c          System.Char  1 instance               49 _firstChar
00007ff93caad698  40002f1       e8        System.String  0   static 0000023c3f5613a0 Empty

0:014> ?0n21391508 /0x400
Evaluate expression: 20890 = 00000000`0000519a

从卦中看,简直是吓一跳,这个 sql 居然高达 20M,🐂👃,难怪处理起来比较慢,很好奇这 20M 到底是个啥?我估计 SqlSugar 也没考虑到有这么大的 SQL 吧,那如何导出这 20M 数据呢?可以使用 .writemem 即可。


0:014> .writemem D:\testdump\1.txt 0x0000023d802e1020+0xc L?0x1466894
Writing 1466894 bytes......

这里稍微提醒下,大文本最好用 LogView 这种便捷工具,然后使用 Utf-16 的方式打开,截图如下:

记一次 .NET 某物流API系统 CPU爆高分析

看卦中信息看,应该是 batch insert 的时候 SqlSugar 在替换参数,在正则上出不来,那到底是 SqlSugar考虑不周还是使用者问题 ?

4. 到底是谁的问题

要想知道是谁的问题就需要看下是什么操作引发的批量提交,我们回头仔细研读下调用栈,通过逆向 xxx.xxxService+d__15.MoveNext 方法,简化后的逻辑如下:


        public async Task<bool> Savexxx(xxxRequest requestModel)
        {
            List<xxxDetailModel> list = new List<xxxDetailModel>();

            for (int i = 0; i < requestModel.xxxDetailList.Length; i++)
            {
                _xxxService.AddQueue(list);  //5w
            }

            return await _xxxService.SaveQueuesAsync() > 0;
        }

_xxxService.SaveQueuesAsync 的内部就是通过 SqlSugarProvider 进行的批量提交,接下来的问题是 list 到底有多少记录呢?

0:021> !dso
OS Thread Id: 0x51f8 (21)
          SP/REG           Object Name
    00ac6cefae38     023c73d9c8a8 System.Collections.Generic.List<xxx.xxxDetailModel>
0:021> !do 023c73d9c8a8
Name:        System.Collections.Generic.List`1[[xxx.xxxDetailModel]]
MethodTable: 00007ff93e12a2f8
EEClass:     00007ff93cb65668
Tracked Type: false
Size:        32(0x20) bytes
File:        C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.12\System.Private.CoreLib.dll
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ff93cc6d000  4002095        8     System.__Canon[]  0 instance 0000023c52b36f18 _items
00007ff93ca99480  4002096       10         System.Int32  1 instance            30708 _size
00007ff93ca99480  4002097       14         System.Int32  1 instance            30708 _version
00007ff93cc6d000  4002098        8     System.__Canon[]  0   static dynamic statics NYI                 s_emptyArray

从卦中看当前是 3w 多,我发现在其他线程中也有 6w 的,比如下面这个。


0:014> !dumpobj /d 23c49e90300
Name:        System.Collections.Generic.List`1[[xxx.xxxDetailModel]]
MethodTable: 00007ff93e12a2f8
EEClass:     00007ff93cb65668
Tracked Type: false
Size:        32(0x20) bytes
File:        C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.12\System.Private.CoreLib.dll
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ff93cc6d000  4002095        8     System.__Canon[]  0 instance 0000023c1042fca8 _items
00007ff93ca99480  4002096       10         System.Int32  1 instance            63532 _size
00007ff93ca99480  4002097       14         System.Int32  1 instance            63532 _version
00007ff93cc6d000  4002098        8     System.__Canon[]  0   static dynamic statics NYI                 s_emptyArray

有了这些前因后果,建议朋友一次性少提交一点,比如 5000 条一次观察下效果如何。

三:总结

这次CPU爆高事故,主要还是因为 批量提交记录多 导致 SqlSugar 在做参数的正则替换上耗费了大量CPU时间所致,降低批量条数,通过小步快跑的方式尽可能的降低运行线程的积压,应该就能解决这个问题。文章来源地址https://www.toymoban.com/news/detail-618012.html

记一次 .NET 某物流API系统 CPU爆高分析

到了这里,关于记一次 .NET 某物流API系统 CPU爆高分析的文章就介绍完了。如果您还想了解更多内容,请在右上角搜索TOY模板网以前的文章或继续浏览下面的相关文章,希望大家以后多多支持TOY模板网!

本文来自互联网用户投稿,该文观点仅代表作者本人,不代表本站立场。本站仅提供信息存储空间服务,不拥有所有权,不承担相关法律责任。如若转载,请注明出处: 如若内容造成侵权/违法违规/事实不符,请点击违法举报进行投诉反馈,一经查实,立即删除!

领支付宝红包 赞助服务器费用

相关文章

  • 记一次 某智能制造MES系统CPU 爆高分析

    前段时间有位朋友找到我,说他 docker 中的web服务深夜cpu被打满,让我帮忙看一下,很多朋友问docker中怎么抓dump,我一般都推荐使用 procdump 这款自动化工具,谁用谁知道,有了 dump 之后,接下来就是分析了。 有很多朋友问 linux 上的dump可以用 windbg 分析吗?这里统一回复下,

    2024年02月04日
    浏览(83)
  • 记一次 .NET 某工厂无人车调度系统 线程爆高分析

    前些天有位朋友找到我,说他程序中的线程数爆高,让我帮忙看下怎么回事,这种线程数爆高的情况找问题相对比较容易,就让朋友丢一个dump给我,看看便知。 别人说的话不一定是真,得自己拿数据出来说话,可以用 !t 命令观察一下便知。 从卦中信息看确实有 4600+ 的线程

    2024年02月06日
    浏览(57)
  • 用 perfcollect 洞察 Linux 上.NET程序 CPU爆高

    如果要分析 Linux上的 .NET程序 CPU 爆高,按以往的个性我肯定是抓个 dump 下来做事后分析,这种分析模式虽然不重但也不轻,还需要一定的底层知识,那有没有傻瓜式的 CPU 爆高分析方式呢? 相信有很多朋友知道 B站713事件 ,最终就是用 perf 找到了那个让 cpu 100% 的 lua 函数,截

    2024年02月16日
    浏览(47)
  • 记一次 .NET某防伪验证系统 崩溃分析

    昨晚给训练营里面的一位朋友分析了一个程序崩溃的故障,因为看小伙子昨天在群里问了一天也没搞定,干脆自己亲自上阵吧,抓取的dump也是我极力推荐的用 procdump 注册 AEDebug 的方式,省去了很多沟通成本。 windbg有一个非常强大的点就是当你双击打开后,会自动帮你切换到

    2024年03月28日
    浏览(63)
  • 记一次 .NET 某企业内部系统 崩溃分析

    前些天有位朋友找到我,说他的程序跑着跑着就崩溃了,让我看下怎么回事,其实没怎么回事,抓它的 crash dump 就好,具体怎么抓也是被问到的一个高频问题,这里再补一下链接: [.NET程序崩溃了怎么抓 Dump ? 我总结了三种方案] https://www.cnblogs.com/huangxincheng/p/14811953.html ,采用

    2024年02月10日
    浏览(53)
  • 记一次 .NET某报关系统 非托管泄露分析

    前段时间有位朋友找到我,说他的程序内存会出现暴涨,让我看下是怎么事情?而且还告诉我是在 Linux 环境下,说实话在Linux上分析.NET程序难度会很大,难度大的原因在于Linux上的各种开源工具主要是针对 C/C++, 和 .NET 一毛钱关系都没有,说到底微软在 Linux 上的调试领域支持

    2024年02月14日
    浏览(50)
  • 记一次 .NET 某券商论坛系统 卡死分析

    前几个月有位朋友找到我,说他们的的web程序没有响应了,而且监控发现线程数特别高,内存也特别大,让我帮忙看一下怎么回事,现在回过头来几经波折,回味价值太浓了。 这个程序内存高,线程高,无响应,尼玛是一个复合态问题,那怎么入手呢?按经验推测,大概率是

    2024年02月05日
    浏览(64)
  • 记一次 .NET 某工控视觉系统 卡死分析

    前段时间有位朋友找到我,说他们的工业视觉软件僵死了,让我帮忙看下到底是什么情况,哈哈,其实卡死的问题相对好定位,无非就是看主线程栈嘛,然后就是具体问题具体分析,当然难度大小就看运气了。 前几天看一篇文章说现在的 .NET程序员 不需要学习 WinDbg ,理由就

    2024年02月12日
    浏览(48)
  • 记一次 .NET 某电力系统 内存暴涨分析

    前些天有位朋友找到我,说他生产上的程序有内存暴涨情况,让我帮忙看下怎么回事,最简单粗暴的方法就是让朋友在内存暴涨的时候抓一个dump下来,看一看大概就知道咋回事了。 这个问题说的再多也不为过,一定要看清楚这个程序是如何个性化发展的,可以使用 !address

    2024年02月08日
    浏览(47)
  • 记一次 .NET某列控连锁系统 崩溃分析

    过年喝了不少酒,脑子不灵光了,停了将近一个月没写博客,今天就当新年开工写一篇吧。 去年年初有位朋友找到我,说他们的系统会偶发性崩溃,在网上也发了不少帖子求助,没找到自己满意的答案,让我看看有没有什么线索,看样子这是一个牛皮藓的问题,既然对方有了

    2024年02月21日
    浏览(55)

觉得文章有用就打赏一下文章作者

支付宝扫一扫打赏

博客赞助

微信扫一扫打赏

请作者喝杯咖啡吧~博客赞助

支付宝扫一扫领取红包,优惠每天领

二维码1

领取红包

二维码2

领红包