一：背景
1. 講故事
大概有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<xxxPropertieInfo> list 的size，如下圖所示：
從圖中看，這個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 摁下去了，一切都恢復了平靜！
