大概有11天沒發(fā)文了，真的不是因為懶，本想前幾天抽空寫，不知道為啥最近求助的朋友比較多，一天都能拿到2-3個求助dump，晚上回來就是一頓分析，有點意思的是大多朋友自己都分析了幾遍或者公司多年的牛皮蘚問題，真的是心太累，不過也好，累那是走上坡路??????。
再回到正題，在一個月前，有位朋友wx找到我，他最近也在學(xué)習(xí)如何分析dump，可能經(jīng)驗不是很豐富，分析不下去了，截圖如下：
雖然dump中的問題千奇百怪，但如果要匯成大類，還是有一些規(guī)律可循的，比如：gc頻繁觸發(fā)，大量鎖 等等，詳細匯總可以觀摩我的星球，好了，既然分析不下去，那就上 windbg。
二：Windbg 分析
1. 查看CPU利用率
既然報過來說cpu過高，我得用數(shù)據(jù)驗證下不是，老命令 !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 觸發(fā)
面對這陌生的dump，先進行一些經(jīng)驗性排查，比如說是否為 GC 觸發(fā)導(dǎo)致? 那怎么去驗證這個假設(shè)呢?為了讓結(jié)果更準確一點，用 !t -special 導(dǎo)出線程列表，看看是否有 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觸發(fā)所致，如果你還不相信的話，可以參考下 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 看看哪一個線程觸發(fā)了 CLR 中的 GarbageCollectGeneration 方法。
從圖中可以看到是 53 號線程觸發(fā)了，切到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);
- }
- }
- }
從源碼邏輯看：它執(zhí)行了一個存儲過程 xxxProperty_GetAll , 然后把獲取到數(shù)據(jù)的 reader 和 xxxPropertyTreeInfo 做了一個 mapping 映射，在映射的過程中觸發(fā)了GC。
3. 是否為數(shù)據(jù)過大導(dǎo)致?
按照以往經(jīng)驗，應(yīng)該是從數(shù)據(jù)庫中獲取了過多數(shù)據(jù)導(dǎo)致，那本次dump是不是呢?要想尋找答案， 先用 !dso 命令導(dǎo)出線程棧所有變量，然后用 !do xxx 查看 List
從圖中看，這個size并不大，那為什么會導(dǎo)致gc頻繁觸發(fā)呢?就算做了 反射 產(chǎn)生了很多的小對象，應(yīng)該也沒多大影響哈。。。這又讓我陷入了沉思。。。
4. 尋找問題根源
經(jīng)過一頓查找，我發(fā)現(xiàn)了幾個疑點。
有24個線程正在執(zhí)行 XXX.GetALL() 方法。
托管堆中發(fā)現(xiàn)了 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
從內(nèi)存地址就能判斷當前程序是 32bit，這就意味著它的 segment 段會很小，也就意味著更多的GC回收。
三：總結(jié)
本次事故是由于：
多個線程頻繁重復(fù)的調(diào)用 size=1298 的 GetALL() 方法。
使用低效的 反射方式 進行model映射，映射過程中產(chǎn)生了不少的小對象。
過小的 segment (32M)
三者結(jié)合造成GC頻繁的觸發(fā)。
改進方法也很簡單。
- 最簡單粗暴的方法：將數(shù)據(jù)庫的查詢結(jié)果緩存一份。
- 稍微正規(guī)一點方法：用 Dapper 替換低效的 手工反射，將程序改成 64bit 。
和朋友溝通了解，采用了第一種方法，終于把 CPU 摁下去了，一切都恢復(fù)了平靜!
原文鏈接：https://mp.weixin.qq.com/s/i6cJHTrIPweDIplzzfHnVQ
