记一次 .NET 某资讯论坛 CPU爆高分析

商务办公
虽然dump中的问题千奇百怪,但如果要汇成大类,还是有一些规律可循的,比如:gc频繁触发,大量锁 等等,详细汇总可以观摩我的星球,好了,既然分析不下去,那就上 windbg。

[[431414]]

大概有11天没发文了,真的不是因为懒,本想前几天抽空写,不知道为啥最近求助的朋友比较多,一天都能拿到2-3个求助dump,晚上回来就是一顿分析,有点意思的是大多朋友自己都分析了几遍或者公司多年的牛皮藓问题,真的是心太累,不过也好,累那是走上坡路??????。

再回到正题,在一个月前,有位朋友wx找到我,他最近也在学习如何分析dump,可能经验不是很丰富,分析不下去了,截图如下:

虽然dump中的问题千奇百怪,但如果要汇成大类,还是有一些规律可循的,比如:gc频繁触发,大量锁 等等,详细汇总可以观摩我的星球,好了,既然分析不下去,那就上 windbg。

二:Windbg 分析

1. 查看CPU利用率

既然报过来说cpu过高,我得用数据验证下不是,老命令 !tp 。

  1. 0:057> !tp 
  2. CPU utilization: 100% 
  3. Worker Thread: Total: 51 Running: 30 Idle: 0 MaxLimit: 400 MinLimit: 4 
  4. Work Request in Queue: 11 
  5.     Unknown Function: 6a0bbb30  Context: 1b4ca258 
  6.     Unknown Function: 6a0bbb30  Context: 1b4ca618 
  7.     Unknown Function: 6a0bbb30  Context: 1b4ca758 
  8.     Unknown Function: 6a0bbb30  Context: 1cb88d60 
  9.     Unknown Function: 6a0bbb30  Context: 1b4ca798 
  10.     Unknown Function: 6a0bbb30  Context: 1b5a54d0 
  11.     AsyncTimerCallbackCompletion TimerInfo@01f6e530 
  12.     Unknown Function: 6a0bbb30  Context: 1b5a5a50 
  13.     Unknown Function: 6a0bbb30  Context: 1cb892a0 
  14.     Unknown Function: 6a0bbb30  Context: 1b4ca8d8 
  15.     Unknown Function: 6a0bbb30  Context: 1cb88da0 
  16. -------------------------------------- 
  17. Number of Timers: 1 
  18. -------------------------------------- 
  19. Completion Port Thread:Total: 1 Free: 1 MaxFree: 8 CurrentLimit: 1 MaxLimit: 400 MinLimit: 4 

我去,cpu打满了,对了,这里稍微提醒下, CPU utilization: 100% 指的是当前机器而不是程序,言外之意就是当机器的CPU 100% 时,并不一定是你所dump的程序造成的。

2. 是否为 GC 触发

面对这陌生的dump,先进行一些经验性排查,比如说是否为 GC 触发导致? 那怎么去验证这个假设呢?为了让结果更准确一点,用 !t -special 导出线程列表,看看是否有 GC SuspendEE 字样。

  1. 0:057> !t -special 
  2. ThreadCount:      109 
  3. UnstartedThread:  0 
  4. BackgroundThread: 74 
  5. PendingThread:    0 
  6. DeadThread:       35 
  7. Hosted Runtime:   no 
  8.  
  9.           OSID Special thread type 
  10.        14 2594 DbgHelper  
  11.        15 2be4 GC SuspendEE  
  12.        16  dc4 GC  
  13.        17 2404 GC  
  14.        18  bb4 GC  
  15.        19 2498 Finalizer  
  16.        20 312c ProfilingAPIAttach  
  17.        21  858 Timer  
  18.        22 3a78 ADUnloadHelper  
  19.        27 290c GC  
  20.        28 2e24 GC  
  21.        29 28b0 GC  
  22.        30 1e64 GC  
  23.        38 3b24 ThreadpoolWorker  
  24.        ... 
  25.        90 2948 Gate  

从输出看,尼玛果然有,那就表明确实是GC触发所致,如果你还不相信的话,可以参考下 coreclr 源码。

  1. size_t 
  2. GCHeap::GarbageCollectGeneration(unsigned int gen, gc_reason reason) 
  3.     dprintf (2, ("triggered a GC!")); 
  4.  
  5.     gc_heap::gc_started = TRUE
  6.  
  7.     { 
  8.         init_sync_log_stats(); 
  9.  
  10. #ifndef MULTIPLE_HEAPS 
  11.         cooperative_mode = gc_heap::enable_preemptive (); 
  12.  
  13.         dprintf (2, ("Suspending EE")); 
  14.         BEGIN_TIMING(suspend_ee_during_log); 
  15.         GCToEEInterface::SuspendEE(SUSPEND_FOR_GC); 
  16.         END_TIMING(suspend_ee_during_log); 
  17.         gc_heap::proceed_with_gc_p = gc_heap::should_proceed_with_gc(); 
  18.         gc_heap::disable_preemptive (cooperative_mode); 
  19.         if (gc_heap::proceed_with_gc_p) 
  20.             pGenGCHeap->settings.init_mechanisms(); 
  21.         else 
  22.             gc_heap::update_collection_counts_for_no_gc(); 
  23.  
  24. #endif //!MULTIPLE_HEAPS 
  25.     } 

看到上面的 SuspendEE 的吗,它的全称就是 Suspend CLR Execute Engine,接下来我们用 ~*e !dumpstack 看看哪一个线程触发了 CLR 中的 GarbageCollectGeneration 方法。

从图中可以看到是 53 号线程触发了,切到53号线程后换用 !clrstack。

从线程栈看,程序做了一个 XXX.GetAll() 操作,一看这名字就蛮恐怖的,接下来我们再看看这块源码,到底做了什么操作,简化后的源码如下:

  1. public static List<xxxx> GetAll() 
  2.         { 
  3.             string text = "xxxProperty_GetAll"
  4.             SqlDatabase val = new SqlDatabase(m_strConnectionString); 
  5.             xxxPropertyTreeInfo xxxPropertyTreeInfo = null
  6.             List<xxxPropertieInfo> list = new List<xxxPropertieInfo>(); 
  7.             DbCommand storedProcCommand = ((Database)val).GetStoredProcCommand(text); 
  8.             using (IDataReader reader = ((Database)val).ExecuteReader(storedProcCommand)) 
  9.             { 
  10.                 while (DataBase.DataReaderMoveNext(reader)) 
  11.                 { 
  12.                     xxxPropertyTreeInfo = new xxxPropertyTreeInfo(); 
  13.                     xxxPropertyTreeInfo.LoadDataReader(reader); 
  14.                     list.Add(xxxPropertyTreeInfo); 
  15.                 } 
  16.             } 
  17.             return list; 
  18.         } 
  19.  
  20.         public virtual void LoadDataReader(MethodBase method, object obj, IDataReader reader) 
  21.         { 
  22.             Hashtable hashtable = new Hashtable(); 
  23.             for (int i = 0; i < reader.FieldCount; i++) 
  24.             { 
  25.                 hashtable.Add(reader.GetName(i).ToLower(), reader.GetValue(i)); 
  26.             } 
  27.             Hashtable fieldProperties = GetFieldProperties(method, FieldType.DBField); 
  28.             foreach (object key in fieldProperties.Keys) 
  29.             { 
  30.                 PropertyInfo p = (PropertyInfo)fieldProperties[key]; 
  31.                 object v = null
  32.                 if (hashtable.Contains(key)) 
  33.                 { 
  34.                     v = hashtable[key]; 
  35.                 } 
  36.                 if (v != null
  37.                 { 
  38.                     SetPropertieValue(ref obj, ref p, ref v); 
  39.                 } 
  40.             } 
  41.         } 

从源码逻辑看:它执行了一个存储过程 xxxProperty_GetAll , 然后把获取到数据的 reader 和 xxxPropertyTreeInfo 做了一个 mapping 映射,在映射的过程中触发了GC。

3. 是否为数据过大导致?

按照以往经验,应该是从数据库中获取了过多数据导致,那本次dump是不是呢?要想寻找答案, 先用 !dso 命令导出线程栈所有变量,然后用 !do xxx 查看 List list 的size,如下图所示:

从图中看,这个size并不大,那为什么会导致gc频繁触发呢?就算做了 反射 产生了很多的小对象,应该也没多大影响哈。。。这又让我陷入了沉思。。。

4. 寻找问题根源

经过一顿查找,我发现了几个疑点。

有24个线程正在执行 XXX.GetALL() 方法。

托管堆中发现了 123 个 list,大的size 也有 1298,所以合计起来也不小哈。。。

  1. 0:053> !dumpheap -mt 1b9eadd0 
  2.  Address       MT     Size 
  3. 02572a9c 1b9eadd0       24      
  4. 026eca58 1b9eadd0       24      
  5. 0273d2a0 1b9eadd0       24  
  6. ... 
  7.  
  8. Statistics
  9.       MT    Count    TotalSize Class Name 
  10. 1b9eadd0      123         2952 System.Collections.Generic.List`1[[xxxPropertieInfo, xxx.Model]] 
  11.  
  12. 0:053> !DumpObj /d 28261894 
  13. Name:        System.Collections.Generic.List`1[[xxxPropertieInfo, xxx.Model]] 
  14. MethodTable: 1b9eadd0 
  15. EEClass:     6e2c6f8c 
  16. Size:        24(0x18) bytes 
  17. File:        C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll 
  18. Fields: 
  19.       MT    Field   Offset                 Type VT     Attr    Value Name 
  20. 6e6ff32c  4001891        4     System.__Canon[]  0 instance 23710638 _items 
  21. 6e6f1bc0  4001892        c         System.Int32  1 instance     1298 _size 
  22. 6e6f1bc0  4001893       10         System.Int32  1 instance     1298 _version 
  23. 6e6f0100  4001894        8        System.Object  0 instance 00000000 _syncRoot 
  24. 6e6ff32c  4001895        4     System.__Canon[]  0   static  <no information> 

程序是 32bit

从内存地址就能判断当前程序是 32bit,这就意味着它的 segment 段会很小,也就意味着更多的GC回收。

三:总结

本次事故是由于:

多个线程频繁重复的调用 size=1298 的 GetALL() 方法。

使用低效的 反射方式 进行model映射,映射过程中产生了不少的小对象。

过小的 segment (32M)

三者结合造成GC频繁的触发。

改进方法也很简单。

  • 最简单粗暴的方法:将数据库的查询结果缓存一份。
  • 稍微正规一点方法:用 Dapper 替换低效的 手工反射,将程序改成 64bit 。

和朋友沟通了解,采用了第一种方法,终于把 CPU 摁下去了,一切都恢复了平静!

本文转载自微信公众号「一线码农聊技术」,可以通过以下二维码关注。转载本文请联系一线码农聊技术公众号。

 

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

2022-10-24 07:48:37

.NETCPUGC

2021-05-17 07:43:06

Web站 CPU.NET

2023-05-12 17:42:22

CPUMES系统

2024-03-15 15:15:53

.NETCPU系统

2023-07-31 22:29:20

CPU.NETAPI

2021-04-21 07:38:41

CPU游戏站程序

2023-11-01 10:46:12

.NET线程同步

2022-02-23 10:12:58

CPUWeb.NET

2023-04-06 10:52:18

2024-03-28 12:56:36

2023-06-26 00:12:46

2022-10-25 14:17:01

.NET代码程序

2023-05-15 11:15:50

.NET门诊语句

2022-01-17 21:28:36

管理系统.NET

2023-10-07 13:28:53

.NET软件账本

2023-06-29 17:55:00

.NET日志WinDbg

2022-10-13 18:40:05

.NETOA后端

2023-07-06 10:11:38

.NET模式dump

2023-09-27 07:23:10

.NET监控软件

2024-03-26 00:44:53

.NETCIM系统
点赞
收藏

51CTO技术栈公众号