大概有11天没发文了，真的不是因为懒，本想前几天抽空写，不知道为啥最近求助的朋友比较多，一天都能拿到2-3个求助dump，晚上回来就是一顿分析，有点意思的是大多朋友自己都分析了几遍或者公司多年的牛皮藓问题，真的是心太累，不过也好，累那是走上坡路??????。
再回到正题，在一个月前，有位朋友wx找到我，他最近也在学习如何分析dump，可能经验不是很丰富，分析不下去了，截图如下：
虽然dump中的问题千奇百怪，但如果要汇成大类，还是有一些规律可循的，比如：gc频繁触发，大量锁 等等，详细汇总可以观摩我的星球，好了，既然分析不下去，那就上 windbg。
二：Windbg 分析
1. 查看CPU利用率
既然报过来说cpu过高，我得用数据验证下不是，老命令 !tp 。
- 0:057> !tp
- CPU utilization: 100%
- Worker Thread: Total: 51 Running: 30 Idle: 0 MaxLimit: 400 MinLimit: 4
- Work Request in Queue: 11
- Unknown Function: 6a0bbb30 Context: 1b4ca258
- Unknown Function: 6a0bbb30 Context: 1b4ca618
- Unknown Function: 6a0bbb30 Context: 1b4ca758
- Unknown Function: 6a0bbb30 Context: 1cb88d60
- Unknown Function: 6a0bbb30 Context: 1b4ca798
- Unknown Function: 6a0bbb30 Context: 1b5a54d0
- AsyncTimerCallbackCompletion TimerInfo@01f6e530
- Unknown Function: 6a0bbb30 Context: 1b5a5a50
- Unknown Function: 6a0bbb30 Context: 1cb892a0
- Unknown Function: 6a0bbb30 Context: 1b4ca8d8
- Unknown Function: 6a0bbb30 Context: 1cb88da0
- --------------------------------------
- Number of Timers: 1
- --------------------------------------
- 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 字样。
- 0:057> !t -special
- ThreadCount: 109
- UnstartedThread: 0
- BackgroundThread: 74
- PendingThread: 0
- DeadThread: 35
- Hosted Runtime: no
- OSID Special thread type
- 14 2594 DbgHelper
- 15 2be4 GC SuspendEE
- 16 dc4 GC
- 17 2404 GC
- 18 bb4 GC
- 19 2498 Finalizer
- 20 312c ProfilingAPIAttach
- 21 858 Timer
- 22 3a78 ADUnloadHelper
- 27 290c GC
- 28 2e24 GC
- 29 28b0 GC
- 30 1e64 GC
- 38 3b24 ThreadpoolWorker
- ...
- 90 2948 Gate
从输出看，尼玛果然有，那就表明确实是GC触发所致，如果你还不相信的话，可以参考下 coreclr 源码。
- size_t
- GCHeap::GarbageCollectGeneration(unsigned int gen, gc_reason reason)
- {
- dprintf (2, ("triggered a GC!"));
- gc_heap::gc_started = TRUE;
- {
- init_sync_log_stats();
- #ifndef MULTIPLE_HEAPS
- cooperative_mode = gc_heap::enable_preemptive ();
- dprintf (2, ("Suspending EE"));
- 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<xxxx> GetAll()
- {
- string text = "xxxProperty_GetAll";
- SqlDatabase val = new SqlDatabase(m_strConnectionString);
- xxxPropertyTreeInfo xxxPropertyTreeInfo = null;
- List<xxxPropertieInfo> list = new List<xxxPropertieInfo>();
- DbCommand storedProcCommand = ((Database)val).GetStoredProcCommand(text);
- using (IDataReader reader = ((Database)val).ExecuteReader(storedProcCommand))
- {
- while (DataBase.DataReaderMoveNext(reader))
- {
- xxxPropertyTreeInfo = new xxxPropertyTreeInfo();
- xxxPropertyTreeInfo.LoadDataReader(reader);
- list.Add(xxxPropertyTreeInfo);
- }
- }
- return list;
- }
- public virtual void LoadDataReader(MethodBase method, object obj, IDataReader reader)
- {
- Hashtable hashtable = new Hashtable();
- for (int i = 0; i < reader.FieldCount; i++)
- {
- hashtable.Add(reader.GetName(i).ToLower(), reader.GetValue(i));
- }
- Hashtable fieldProperties = GetFieldProperties(method, FieldType.DBField);
- foreach (object key in fieldProperties.Keys)
- {
- PropertyInfo p = (PropertyInfo)fieldProperties[key];
- object v = null;
- if (hashtable.Contains(key))
- {
- v = hashtable[key];
- }
- if (v != null)
- {
- SetPropertieValue(ref obj, ref p, ref v);
- }
- }
- }
从源码逻辑看：它执行了一个存储过程 xxxProperty_GetAll , 然后把获取到数据的 reader 和 xxxPropertyTreeInfo 做了一个 mapping 映射，在映射的过程中触发了GC。
3. 是否为数据过大导致?
按照以往经验，应该是从数据库中获取了过多数据导致，那本次dump是不是呢?要想寻找答案， 先用 !dso 命令导出线程栈所有变量，然后用 !do xxx 查看 List
从图中看，这个size并不大，那为什么会导致gc频繁触发呢?就算做了 反射 产生了很多的小对象，应该也没多大影响哈。。。这又让我陷入了沉思。。。
4. 寻找问题根源
经过一顿查找，我发现了几个疑点。
有24个线程正在执行 XXX.GetALL() 方法。
托管堆中发现了 123 个 list，大的size 也有 1298，所以合计起来也不小哈。。。
- 0:053> !dumpheap -mt 1b9eadd0
- Address MT Size
- 02572a9c 1b9eadd0 24
- 026eca58 1b9eadd0 24
- 0273d2a0 1b9eadd0 24
- ...
- Statistics:
- MT Count TotalSize Class Name
- 1b9eadd0 123 2952 System.Collections.Generic.List`1[[xxxPropertieInfo, xxx.Model]]
- 0:053> !DumpObj /d 28261894
- 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:
- MT Field Offset Type VT Attr Value Name
- 6e6ff32c 4001891 4 System.__Canon[] 0 instance 23710638 _items
- 6e6f1bc0 4001892 c System.Int32 1 instance 1298 _size
- 6e6f1bc0 4001893 10 System.Int32 1 instance 1298 _version
- 6e6f0100 4001894 8 System.Object 0 instance 00000000 _syncRoot
- 6e6ff32c 4001895 4 System.__Canon[] 0 static <no information>
程序是 32bit
从内存地址就能判断当前程序是 32bit，这就意味着它的 segment 段会很小，也就意味着更多的GC回收。
三：总结
本次事故是由于：
多个线程频繁重复的调用 size=1298 的 GetALL() 方法。
使用低效的 反射方式 进行model映射，映射过程中产生了不少的小对象。
过小的 segment (32M)
三者结合造成GC频繁的触发。
改进方法也很简单。
- 最简单粗暴的方法：将数据库的查询结果缓存一份。
- 稍微正规一点方法：用 Dapper 替换低效的 手工反射，将程序改成 64bit 。
和朋友沟通了解，采用了第一种方法，终于把 CPU 摁下去了，一切都恢复了平静!
本文转载自微信公众号「一线码农聊技术」，可以通过以下二维码关注。转载本文请联系一线码农聊技术公众号。
