大概有11天没发文了，真的不是因为懒，本想前几天抽空写，不知道为啥最近求助的朋友比较多，一天都能拿到2-3个求助dump，晚上回来就是一顿分析，有点意思的是大多朋友自己都分析了几遍或者公司多年的牛皮藓问题，真的是心太累，不过也好，累那是走上坡路??????。
再回到正题，在一个月前，有位朋友wx找到我，他最近也在学习如何分析dump，可能经验不是很丰富，分析不下去了，截图如下：
虽然dump中的问题千奇百怪，但如果要汇成大类，还是有一些规律可循的，比如：gc频繁触发，大量锁 等等，详细汇总可以观摩我的星球，好了，既然分析不下去，那就上 windbg。
二：Windbg 分析
1. 查看 CPU 利用率
既然报过来说cpu过高，我得用数据验证下不是，老命令 !tp 。
0:057>!tp CPUutilization:100% WorkerThread:Total:51Running:30Idle:0MaxLimit:400MinLimit:4 Work Request in Queue:11 Unknown Function :6a0bbb30Context:1b4ca258 Unknown Function :6a0bbb30Context:1b4ca618 Unknown Function :6a0bbb30Context:1b4ca758 Unknown Function :6a0bbb30Context:1cb88d60 Unknown Function :6a0bbb30Context:1b4ca798 Unknown Function :6a0bbb30Context:1b5a54d0 AsyncTimerCallbackCompletionTimerInfo@01f6e530 Unknown Function :6a0bbb30Context:1b5a5a50 Unknown Function :6a0bbb30Context:1cb892a0 Unknown Function :6a0bbb30Context:1b4ca8d8 Unknown Function :6a0bbb30Context:1cb88da0 -------------------------------------- Number of Timers:1 -------------------------------------- CompletionPortThread:Total:1 Free :1MaxFree:8CurrentLimit:1MaxLimit:400MinLimit:4我去，cpu打满了，对了，这里稍微提醒下， CPU utilization: 100% 指的是当前机器而不是程序，言外之意就是当机器的CPU 100% 时，并不一定是你所dump的程序造成的。
2. 是否为 GC 触发
面对这陌生的dump，先进行一些经验性排查，比如说是否为 GC 触发导致? 那怎么去验证这个假设呢?为了让结果更准确一点，用 !t -special 导出线程列表，看看是否有 GC SuspendEE 字样。
0:057>!t-special ThreadCount:109 UnstartedThread:0 BackgroundThread:74 PendingThread:0 DeadThread:35 HostedRuntime: no OSIDSpecialthreadtype 142594DbgHelper 152be4GCSuspendEE 16dc4GC 172404GC 18bb4GC 192498Finalizer 20312cProfilingAPIAttach 21858Timer 223a78ADUnloadHelper 27290cGC 282e24GC 2928b0GC 301e64GC 383b24ThreadpoolWorker ... 902948Gate从输出看，尼玛果然有，那就表明确实是GC触发所致，如果你还不相信的话，可以参考下 coreclr 源码。
size_t GCHeap::GarbageCollectGeneration(unsigned int gen,gc_reasonreason) { dprintf(2,( "triggeredaGC!" )); gc_heap::gc_started= TRUE ; { init_sync_log_stats(); #ifndefMULTIPLE_HEAPS cooperative_mode=gc_heap::enable_preemptive(); dprintf(2,( "SuspendingEE" )); BEGIN_TIMING(suspend_ee_during_log); GCToEEInterface::SuspendEE(SUSPEND_FOR_GC); END_TIMING(suspend_ee_during_log); gc_heap::proceed_with_gc_p=gc_heap::should_proceed_with_gc(); gc_heap::disable_preemptive(cooperative_mode); if(gc_heap::proceed_with_gc_p) pGenGCHeap->settings.init_mechanisms(); else gc_heap::update_collection_counts_for_no_gc(); #endif//!MULTIPLE_HEAPS } }看到上面的 SuspendEE 的吗，它的全称就是 Suspend CLR Execute Engine，接下来我们用 ~*e !dumpstack 看看哪一个线程触发了 CLR 中的 GarbageCollectGeneration 方法。
从图中可以看到是 53 号线程触发了，切到53号线程后换用 !clrstack。
从线程栈看，程序做了一个 XXX.GetAll() 操作，一看这名字就蛮恐怖的，接下来我们再看看这块源码，到底做了什么操作，简化后的源码如下：
public static List GetAll() { stringtext= "xxxProperty_GetAll" ; SqlDatabaseval=newSqlDatabase(m_strConnectionString); xxxPropertyTreeInfoxxxPropertyTreeInfo= null ; List list=newList (); DbCommandstoredProcCommand=(( Database )val).GetStoredProcCommand(text); using(IDataReaderreader=(( Database )val).ExecuteReader(storedProcCommand)) { while( DataBase .DataReaderMoveNext(reader)) { xxxPropertyTreeInfo=newxxxPropertyTreeInfo(); xxxPropertyTreeInfo.LoadDataReader(reader); list. Add (xxxPropertyTreeInfo); } } return list; } public virtualvoidLoadDataReader(MethodBasemethod,objectobj,IDataReaderreader) { Hashtablehashtable=newHashtable(); for ( int i=0;i { hashtable. Add (reader.GetName(i).ToLower(),reader.GetValue(i)); } HashtablefieldProperties=GetFieldProperties(method,FieldType.DBField); foreach(object key in fieldProperties.Keys) { PropertyInfop=(PropertyInfo)fieldProperties[ key ]; objectv= null ; if(hashtable. Contains ( key )) { v=hashtable[ key ]; } if(v!= null ) { SetPropertieValue(refobj,refp,refv); } } }从源码逻辑看：它执行了一个存储过程 xxxProperty_GetAll , 然后把获取到数据的 reader 和 xxxPropertyTreeInfo 做了一个 mapping 映射，在映射的过程中触发了GC。
3. 是否为数据过大导致?
按照以往经验，应该是从数据库中获取了过多数据导致，那本次dump是不是呢?要想寻找答案， 先用 !dso 命令导出线程栈所有变量，然后用 !do xxx 查看 List list 的size，如下图所示：
从图中看，这个size并不大，那为什么会导致gc频繁触发呢?就算做了 反射 产生了很多的小对象，应该也没多大影响哈。。。这又让我陷入了沉思。。。
4. 寻找问题根源
经过一顿查找，我发现了几个疑点。
有24个线程正在执行 XXX.GetALL() 方法。
托管堆中发现了 123 个 list，大的size 也有 1298，所以合计起来也不小哈。。。
0:053>!dumpheap-mt1b9eadd0 AddressMT Size 02572a9c1b9eadd024 026eca581b9eadd024 0273d2a01b9eadd024 ... Statistics : MT Count TotalSizeClass Name 1b9eadd01232952System.Collections.Generic.List`1[[xxxPropertieInfo,xxx.Model]] 0:053>!DumpObj/d28261894 Name :System.Collections.Generic.List`1[[xxxPropertieInfo,xxx.Model]] MethodTable:1b9eadd0 EEClass:6e2c6f8c Size :24(0x18)bytes File:C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll Fields: MTFieldOffsetTypeVTAttrValue Name 6e6ff32c40018914System.__Canon[]0instance23710638_items 6e6f1bc04001892cSystem.Int321instance1298_size 6e6f1bc0400189310System.Int321instance1298_version 6e6f010040018948System.Object0instance00000000_syncRoot 6e6ff32c40018954System.__Canon[]0 static < no information>程序是 32bit
从内存地址就能判断当前程序是 32bit，这就意味着它的 segment 段会很小，也就意味着更多的GC回收。
三：总结
本次事故是由于：
多个线程频繁重复的调用 size=1298 的 GetALL() 方法。
使用低效的 反射方式 进行model映射，映射过程中产生了不少的小对象。
过小的 segment (32M)
三者结合造成GC频繁的触发。
改进方法也很简单。
最简单粗暴的方法：将数据库的查询结果缓存一份。 稍微正规一点方法：用 Dapper 替换低效的 手工反射，将程序改成 64bit 。和朋友沟通了解，采用了第一种方法，终于把 CPU 摁下去了，一切都恢复了平静!
原文链接：https://mp.weixin.qq.com/s/i6cJHTrIPweDIplzzfHnVQ
dy("nrwz");
查看更多关于记一次 .NET 某资讯论坛 CPU爆高分析的详细内容...