大概有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
- WorkRequestinQueue:11
- UnknownFunction:6a0bbb30Context:1b4ca258
- UnknownFunction:6a0bbb30Context:1b4ca618
- UnknownFunction:6a0bbb30Context:1b4ca758
- UnknownFunction:6a0bbb30Context:1cb88d60
- UnknownFunction:6a0bbb30Context:1b4ca798
- UnknownFunction:6a0bbb30Context:1b5a54d0
- AsyncTimerCallbackCompletionTimerInfo@01f6e530
- UnknownFunction:6a0bbb30Context:1b5a5a50
- UnknownFunction:6a0bbb30Context:1cb892a0
- UnknownFunction:6a0bbb30Context:1b4ca8d8
- UnknownFunction:6a0bbb30Context:1cb88da0
- --------------------------------------
- NumberofTimers:1
- --------------------------------------
- CompletionPortThread:Total:1Free: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(unsignedintgen,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() 操作，一看這名字就蠻恐怖的，接下來我們再看看這塊源碼，到底做了什么操作，簡化后的源碼如下：
-
publicstaticList
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);
- }
- }
- returnlist;
- }
- publicvirtualvoidLoadDataReader(MethodBasemethod,objectobj,IDataReaderreader)
- {
- Hashtablehashtable=newHashtable();
-
for(inti=0;i
- {
- hashtable.Add(reader.GetName(i).ToLower(),reader.GetValue(i));
- }
- HashtablefieldProperties=GetFieldProperties(method,FieldType.DBField);
- foreach(objectkeyinfieldProperties.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
從圖中看，這個size并不大，那為什么會導致gc頻繁觸發呢?就算做了 反射 產生了很多的小對象，應該也沒多大影響哈。。。這又讓我陷入了沉思。。。
4. 尋找問題根源
經過一頓查找，我發現了幾個疑點。
有24個線程正在執行 XXX.GetALL() 方法。
托管堆中發現了 123 個 list，大的size 也有 1298，所以合計起來也不小哈。。。
- 0:053>!dumpheap-mt1b9eadd0
- AddressMTSize
- 02572a9c1b9eadd024
- 026eca581b9eadd024
- 0273d2a01b9eadd024
- ...
- Statistics:
- MTCountTotalSizeClassName
- 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:
- MTFieldOffsetTypeVTAttrValueName
- 6e6ff32c40018914System.__Canon[]0instance23710638_items
- 6e6f1bc04001892cSystem.Int321instance1298_size
- 6e6f1bc0400189310System.Int321instance1298_version
- 6e6f010040018948System.Object0instance00000000_syncRoot
- 6e6ff32c40018954System.__Canon[]0static<noinformation>
程序是 32bit
從內存地址就能判斷當前程序是 32bit，這就意味著它的 segment 段會很小，也就意味著更多的GC回收。
三：總結
本次事故是由于：
多個線程頻繁重復的調用 size=1298 的 GetALL() 方法。
使用低效的 反射方式 進行model映射，映射過程中產生了不少的小對象。
過小的 segment (32M)
三者結合造成GC頻繁的觸發。
改進方法也很簡單。
- 最簡單粗暴的方法：將數據庫的查詢結果緩存一份。
- 稍微正規一點方法：用 Dapper 替換低效的 手工反射，將程序改成 64bit 。
和朋友溝通了解，采用了第一種方法，終于把 CPU 摁下去了，一切都恢復了平靜!
原文鏈接：https://mp.weixin.qq.com/s/i6cJHTrIPweDIplzzfHnVQ
