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

  • 记一次 .NET 某物流API系统 CPU爆高分析已关闭评论
  • 119 次浏览
  • A+
所属分类：.NET技术
摘要

前段时间有位朋友找到我，说他程序CPU直接被打满了，让我帮忙看下怎么回事，截图如下：
便宜好用的国外VPS推荐

一：背景

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 FilesdotnetsharedMicrosoft.NETCore.App6.0.12System.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:testdump1.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 FilesdotnetsharedMicrosoft.NETCore.App6.0.12System.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 FilesdotnetsharedMicrosoft.NETCore.App6.0.12System.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时间所致，降低批量条数，通过小步快跑的方式尽可能的降低运行线程的积压，应该就能解决这个问题。

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

便宜好用的国外VPS推荐