记一次 .NET游戏站程序的 CPU 爆高分析

商务办公
现在的码农都精怪精怪的,基本不会傻傻的写出个死循环,绝大部分都是遇到某种 资源密集型 或 计算密集型 场景下导致非托管的 GC 出了问题。

 [[394550]]

一:背景

1. 讲故事

上个月有个老朋友找到我,说他的站点晚高峰 CPU 会突然爆高,发了两份 dump 文件过来,如下图:

又是经典的 CPU 爆高问题,到目前为止,对这种我还是有一些经验可循的。

  • 抓 2-3 个 dump

第一个:有利于算两份 dump 中的线程时间差,从而推算最耗时线程。

第二个:有时候你抓的dump刚好线程都处理完了,cpu 还未真实回落,所以分析这种dump意义不大,我是吃了不少亏??????。

  • 优先推测是否为 GC 捣鬼

现在的码农都精怪精怪的,基本不会傻傻的写出个死循环,绝大部分都是遇到某种 资源密集型 或 计算密集型 场景下导致非托管的 GC 出了问题。

好了,有了这个先入为主的思路,接下来就可以用 windbg 去占卜了。

二:windbg 分析

1. GC 捣鬼分析

GC 捣鬼的本质是 GC 出现了回收压力,尤其是对 大对象堆 的分配和释放,大家应该知道 大对象堆 采用的是链式管理法,不到万不得已 GC 都不敢回收它,所以在它上面的分配和释放都是一种 CPU密集型 操作,不信你可以去 StackOverflow 上搜搜 LOH 和 HighCPU 的关联关系??????。

2. 使用 x 命令搜索

在 windbg 中有一个快捷命令 x ,可用于在非托管堆上检索指定关键词,检索之前先看看这个 dump 是什么 Framework 版本,决定用什么关键词。

  1. 0:050> lmv 
  2. start    end        module name 
  3. 00b80000 00b88000   w3wp       (pdb symbols)          c:\mysymbols\w3wp.pdb\0CED8B2D5CB84AEB91307A0CE6BF528A1\w3wp.pdb 
  4.     Loaded symbol image file: w3wp.exe 
  5.     Image path: C:\Windows\SysWOW64\inetsrv\w3wp.exe 
  6.     Image name: w3wp.exe 
  7. 71510000 71cc0000   clr        (pdb symbols)          c:\mysymbols\clr.pdb\9B2B2A02EC2D43899F87AC20F11B82DF2\clr.pdb 
  8.     Loaded symbol image file: clr.dll 
  9.     Image path: C:\Windows\Microsoft.NET\Framework\v4.0.30319\clr.dll 
  10.     Image name: clr.dll 
  11.     Browse all global symbols  functions  data 
  12.     Timestamp:        Thu Sep  3 03:30:58 2020 (5F4FF2F2) 
  13.     CheckSum:         007AC92B 
  14.     ImageSize:        007B0000 
  15.     File version:     4.8.4261.0 
  16.     Product version:  4.0.30319.0 

从 File version 上可以看出当前是基于 Net Framework 4.8 的,好了,用 x clr!SVR::gc_heap::trigger* 看看有没有触发 gc 的操作。

  1. 0:050> x clr!SVR::gc_heap::trigger
  2. 71930401          clr!SVR::gc_heap::trigger_ephemeral_gc (protected: int __thiscall SVR::gc_heap::trigger_ephemeral_gc(enum gc_reason)) 
  3. 71665cf9          clr!SVR::gc_heap::trigger_gc_for_alloc (protected: void __thiscall SVR::gc_heap::trigger_gc_for_alloc(int,enum gc_reason,struct SVR::GCDebugSpinLock *,bool,enum SVR::msl_take_state)) 
  4. 71930a08          clr!SVR::gc_heap::trigger_full_compact_gc (protected: int __thiscall SVR::gc_heap::trigger_full_compact_gc(enum gc_reason,enum oom_reason *,bool)) 

从输出信息看,gc 果然在高速运转,开心哈,接下来看一下是哪一个线程触发了gc,可以用 !eestack 把所有线程的托管和非托管堆栈打出来。

从图中可以看到当前 50 号线程的 GetUserLoginGameMapIds() 方法进行的大对象分配 try_allocate_more_space 触发了 clr!SVR::gc_heap::trigger_gc_for_alloc GC回收操作,最后 GC 通过 clr!SVR::GCHeap::GarbageCollectGeneration 进行回收,既然在回收,必然有很多线程正在卡死。

接下来再看看有几个线程正在共同努力调用 GetUserLoginGameMapIds() 方法。

到这里基本就能确定是 gc 捣的鬼。接下来的兴趣点就是 GetUserLoginGameMapIds() 到底在干嘛?

3. 分析 GetUserLoginGameMapIds() 方法

接下来把方法的源码导出来,使用 !name2ee 找到其所属 module,然后通过 !savemodule 导出该 module 的源码。

  1. 0:050> !name2ee *!xxx.GetUserLoginGameMapIds 
  2. Module:      1c870580 
  3. Assembly:    xxx.dll 
  4. Token:       0600000b 
  5. MethodDesc:  1c877504 
  6. Name:        xxx.GetUserLoginGameMapIds(xxx.GetUserLoginGameMapIdsDomainInput) 
  7. JITTED Code Address: 1d5a2030 
  8. 0:050> !savemodule  1c870580 E:\dumps\6.dll 
  9. 3 sections in file 
  10. section 0 - VA=2000, VASize=112b8, FileAddr=200, FileSize=11400 
  11. section 1 - VA=14000, VASize=3c8, FileAddr=11600, FileSize=400 
  12. section 2 - VA=16000, VASize=c, FileAddr=11a00, FileSize=200 

打开导出的 6.dll,为了最大保护隐私,我就把字段名隐藏一下, GetUserLoginGameMapIds() 大体逻辑如下。

  1. public GetUserLoginGameMapIdsDomainOutput GetUserLoginGameMapIds(GetUserLoginGameMapIdsDomainInput input) 
  2.  List<int> xxxQueryable = this._xxxRepository.Getxxx(); 
  3.  List<UserLoginGameEntity> list = this._userLoginGameRepository.Where((UserLoginGameEntity u) => u.xxx == input.xxx, null"").ToList<UserLoginGameEntity>(); 
  4.  List<int> userLoginGameMapIds = (from u in list select u.xxx).ToList<int>(); 
  5.  IEnumerable<GetUserLoginGameMapIdsDomainOutput.GetUserLoginGameMapIdsDataDomainOutput> source = (from mc in (from mc in this._mapCategoryRepository.AsQueryable().ToList<MapCategoryEntity>() 
  6.  where userLoginGameMapIds.Any((int mid) => mid == mc.xxx) && mapIdsQueryable.Any((int xxx) => xxx == mc.xxx) 
  7.  select mc).ToList<MapCategoryEntity>() 
  8.  join u in list on mc.xxx equals u.xxx 
  9.  select new GetUserLoginGameMapIdsDomainOutput.GetUserLoginGameMapIdsDataDomainOutput 
  10.  { 
  11.   xxx = mc.xxx, 
  12.   xxx = ((u != null) ? new DateTime?(u.xxx) : null).GetValueOrDefault(DateTime.Now) 
  13.  } into d 
  14.  group d by d.MapId).Select(delegate(IGrouping<int, GetUserLoginGameMapIdsDomainOutput.GetUserLoginGameMapIdsDataDomainOutput> g) 
  15.  { 
  16.   GetUserLoginGameMapIdsDomainOutput.GetUserLoginGameMapIdsDataDomainOutput getUserLoginGameMapIdsDataDomainOutput = new GetUserLoginGameMapIdsDomainOutput.GetUserLoginGameMapIdsDataDomainOutput(); 
  17.   getUserLoginGameMapIdsDataDomainOutput.xxx = g.Key
  18.   getUserLoginGameMapIdsDataDomainOutput.xxx = g.Max((GetUserLoginGameMapIdsDomainOutput.GetUserLoginGameMapIdsDataDomainOutput v) => v.xxxx); 
  19.   return getUserLoginGameMapIdsDataDomainOutput; 
  20.  }); 
  21.  return new GetUserLoginGameMapIdsDomainOutput 
  22.  { 
  23.   Data = source.ToList<GetUserLoginGameMapIdsDomainOutput.GetUserLoginGameMapIdsDataDomainOutput>() 
  24.  }; 

看的出来,这是一段EF读取DB的复杂写法,朋友说这段代码涉及到了多张表的关联操作,算是一个 资源密集型 的方法。

4. 到底持有什么大对象?

方法逻辑看完了,接下来看下 GetUserLoginGameMapIds() 方法到底分配了什么大对象触发了GC,可以探究下 50 线程的调用栈,使用 !clrstack -a 调出所有的 参数 + 局部 变量。

  1. 0:050> !clrstack -a 
  2. OS Thread Id: 0x11a0 (50) 
  3. Child SP       IP Call Site 
  4. 2501d350 7743c0bc [HelperMethodFrame: 2501d350]  
  5. 2501d3dc 704fbab5 System.Collections.Generic.List`1[[System.__Canon, mscorlib]].set_Capacity(Int32) 
  6.     PARAMETERS: 
  7.         this (<CLR reg>) = 0x08053f6c 
  8.         value = <no data> 
  9.     LOCALS: 
  10.         <no data> 
  11.  
  12. 2501d3ec 704fba62 System.Collections.Generic.List`1[[System.__Canon, mscorlib]].EnsureCapacity(Int32) 
  13.     PARAMETERS: 
  14.         this = <no data> 
  15.         min = <no data> 
  16.     LOCALS: 
  17.         <no data> 
  18.  
  19. 2501d3f8 70516799 System.Collections.Generic.List`1[[System.__Canon, mscorlib]].Add(System.__Canon) 
  20.     PARAMETERS: 
  21.         this (<CLR reg>) = 0x08053f6c 
  22.         item (<CLR reg>) = 0x2d7b07bc 
  23.     LOCALS: 
  24.         <no data> 

从调用栈上看,由于 EF 的读取逻辑需要向 List 中添加一条记录刚好触发了List的扩容机制,就是因为这个扩容导致了GC大对象分配。

那怎么看呢? 很简单,先把 this () = 0x08053f6c 中地址拿出来do一下 !do 0x08053f6c 调出 List。

  1. 0:050> !do 0x08053f6c 
  2. Name:        System.Collections.Generic.List`1[[xxx.MapCategoryEntity, xxx.Entities]] 
  3. MethodTable: 1e81eed0 
  4. EEClass:     70219c7c 
  5. Size:        24(0x18) bytes 
  6. File:        C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll 
  7. Fields: 
  8.       MT    Field   Offset                 Type VT     Attr    Value Name 
  9. 701546bc  40018a0        4     System.__Canon[]  0 instance 168792c0 _items 
  10. 701142a8  40018a1        c         System.Int32  1 instance    32768 _size 
  11. 701142a8  40018a2       10         System.Int32  1 instance    32768 _version 
  12. 70112734  40018a3        8        System.Object  0 instance 00000000 _syncRoot 
  13. 701546bc  40018a4        4     System.__Canon[]  0   static  <no information> 

上面的 _size = 32768 看到了吗?刚好是 2的15次方,由于再次新增必须要扩容,List 在底层需分配一个 System.__Canon[65536] 的数组来存储老内容,这个数组肯定大于 85000byte 这个大对象的界定值啦。

如果有兴趣,你可以看下 List 的扩容机制。

  1. // System.Collections.Generic.List<T> 
  2. private void EnsureCapacity(int min
  3.  if (_items.Length < min
  4.  { 
  5.   int num = (_items.Length == 0) ? 4 : (_items.Length * 2); 
  6.   if ((uint)num > 2146435071u) 
  7.   { 
  8.    num = 2146435071; 
  9.   } 
  10.   if (num < min
  11.   { 
  12.    num = min
  13.   } 
  14.   Capacity = num; 
  15.  } 
  16.  
  17. public int Capacity 
  18.  
  19.  get 
  20.  { 
  21.   return _items.Length; 
  22.  } 
  23.  set 
  24.  { 
  25.   if (value < _size) 
  26.   { 
  27.    ThrowHelper.ThrowArgumentOutOfRangeException(ExceptionArgument.value, ExceptionResource.ArgumentOutOfRange_SmallCapacity); 
  28.   } 
  29.   if (value == _items.Length) 
  30.   { 
  31.    return
  32.   } 
  33.   if (value > 0) 
  34.   { 
  35.    T[] array = new T[value];   //这里申请了一个 int[65536] 大小的数组 
  36.    if (_size > 0) 
  37.    { 
  38.     Array.Copy(_items, 0, array, 0, _size); 
  39.    } 
  40.    _items = array; 
  41.   } 
  42.   else 
  43.   { 
  44.    _items = _emptyArray; 
  45.   } 
  46.  } 

三:总结

知道了前因后果之后,大概提三点优化建议。

优化 GetUserLoginGameMapIds() 方法中的逻辑,这是最好的办法。

从 dump 上看也就 4核4G 的小机器,提升下机器配置,或许有点用。

  1. 0:017> !cpuid 
  2. CP  F/M/S  Manufacturer     MHz 
  3.  0  6,63,2  GenuineIntel    2295 
  4.  1  6,63,2  GenuineIntel    2295 
  5.  2  6,63,2  GenuineIntel    2295 
  6.  3  6,63,2  GenuineIntel    2295 
  7.  
  8.  0:017> !address -summary 
  9. --- Protect Summary (for commit) - RgnCount ----------- Total Size -------- %ofBusy %ofTotal 
  10. PAGE_READWRITE                          878          1eccd000 ( 492.801 MB)  29.61%   12.03% 

没有特殊原因的话,用 64bit 来跑程序,打破 32bit 的 4G 空间限制,这样也可以让gc拥有更大的堆分配空间。

参考网址:https://docs.microsoft.com/zh-cn/dotnet/standard/garbage-collection/fundamentals

 

责任编辑:武晓燕 来源: 一线码农聊技术
相关推荐

2021-05-17 07:43:06

Web站 CPU.NET

2021-10-27 07:30:32

.NETCPU论坛

2023-07-31 22:29:20

CPU.NETAPI

2022-10-24 07:48:37

.NETCPUGC

2024-03-15 15:15:53

.NETCPU系统

2023-05-12 17:42:22

CPUMES系统

2023-11-01 10:46:12

.NET线程同步

2022-02-23 10:12:58

CPUWeb.NET

2022-10-25 14:17:01

.NET代码程序

2021-04-29 07:33:40

内存API程序

2023-04-06 10:52:18

2023-06-26 00:12:46

2023-05-15 11:15:50

.NET门诊语句

2022-01-17 21:28:36

管理系统.NET

2023-06-29 17:55:00

.NET日志WinDbg

2023-10-07 13:28:53

.NET软件账本

2022-10-13 18:40:05

.NETOA后端

2023-03-26 20:24:50

ERP网站系统

2023-07-06 10:11:38

.NET模式dump

2023-09-27 07:23:10

.NET监控软件
点赞
收藏

51CTO技术栈公众号