大概有11天沒發(fā)文了，真的不是因?yàn)閼?#xff0c;本想前幾天抽空寫，不知道為啥最近求助的朋友比較多，一天都能拿到2-3個求助dump，晚上回來就是一頓分析，有點(diǎn)意思的是大多朋友自己都分析了幾遍或者公司多年的牛皮蘚問題，真的是心太累，不過也好，累那是走上坡路😂😂😂。

再回到正題，在一個月前，有位朋友wx找到我，他最近也在學(xué)習(xí)如何分析dump，可能經(jīng)驗(yàn)不是很豐富，分析不下去了，截圖如下：

雖然dump中的問題千奇百怪，但如果要匯成大類，還是有一些規(guī)律可循的，比如：gc頻繁觸發(fā)，大量鎖 等等，詳細(xì)匯總可以觀摩我的星球，好了，既然分析不下去，那就上 windbg。

二：Windbg 分析

1. 查看CPU利用率

既然報(bào)過來說cpu過高，我得用數(shù)據(jù)驗(yàn)證下不是，老命令 !tp 。

0:057>?!tp CPU?utilization:?100% Worker?Thread:?Total:?51?Running:?30?Idle:?0?MaxLimit:?400?MinLimit:?4 Work?Request?in?Queue:?11Unknown?Function:?6a0bbb30??Context:?1b4ca258Unknown?Function:?6a0bbb30??Context:?1b4ca618Unknown?Function:?6a0bbb30??Context:?1b4ca758Unknown?Function:?6a0bbb30??Context:?1cb88d60Unknown?Function:?6a0bbb30??Context:?1b4ca798Unknown?Function:?6a0bbb30??Context:?1b5a54d0AsyncTimerCallbackCompletion?TimerInfo@01f6e530Unknown?Function:?6a0bbb30??Context:?1b5a5a50Unknown?Function:?6a0bbb30??Context:?1cb892a0Unknown?Function:?6a0bbb30??Context:?1b4ca8d8Unknown?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% 指的是當(dāng)前機(jī)器而不是程序，言外之意就是當(dāng)機(jī)器的CPU 100% 時，并不一定是你所dump的程序造成的。

2. 是否為 GC 觸發(fā)

面對這陌生的dump，先進(jìn)行一些經(jīng)驗(yàn)性排查，比如說是否為 GC 觸發(fā)導(dǎo)致? 那怎么去驗(yàn)證這個假設(shè)呢？為了讓結(jié)果更準(zhǔn)確一點(diǎn)，用 !t -special 導(dǎo)出線程列表，看看是否有 GC SuspendEE 字樣。

0:057>?!t?-special ThreadCount:??????109 UnstartedThread:??0 BackgroundThread:?74 PendingThread:????0 DeadThread:???????35 Hosted?Runtime:???noOSID?Special?thread?type14?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

從輸出看，尼瑪果然有，那就表明確實(shí)是GC觸發(fā)所致，如果你還不相信的話，可以參考下 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_HEAPScooperative_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();elsegc_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() 操作，一看這名字就蠻恐怖的，接下來我們再看看這塊源碼，到底做了什么操作，簡化后的源碼如下：

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);}}}

從源碼邏輯看：它執(zhí)行了一個存儲過程 xxxProperty_GetAll , 然后把獲取到數(shù)據(jù)的 reader 和 xxxPropertyTreeInfo 做了一個 mapping 映射，在映射的過程中觸發(fā)了GC。

3. 是否為數(shù)據(jù)過大導(dǎo)致？

按照以往經(jīng)驗(yàn)，應(yīng)該是從數(shù)據(jù)庫中獲取了過多數(shù)據(jù)導(dǎo)致，那本次dump是不是呢？要想尋找答案， 先用 !dso 命令導(dǎo)出線程棧所有變量，然后用 !do xxx 查看 List<xxxPropertieInfo> list 的size，如下圖所示：

從圖中看，這個size并不大，那為什么會導(dǎo)致gc頻繁觸發(fā)呢？就算做了 反射 產(chǎn)生了很多的小對象，應(yīng)該也沒多大影響哈。。。這又讓我陷入了沉思。。。

4. 尋找問題根源

經(jīng)過一頓查找，我發(fā)現(xiàn)了幾個疑點(diǎn)。

有24個線程正在執(zhí)行 XXX.GetALL() 方法。

托管堆中發(fā)現(xiàn)了 123 個 list，大的size 也有 1298，所以合計(jì)起來也不小哈。。。

0:053>?!dumpheap?-mt?1b9eadd0Address???????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

從內(nèi)存地址就能判斷當(dāng)前程序是 32bit，這就意味著它的 segment 段會很小，也就意味著更多的GC回收。

三：總結(jié)

本次事故是由于：

多個線程頻繁重復(fù)的調(diào)用 size=1298 的 GetALL() 方法。

使用低效的 反射方式 進(jìn)行model映射，映射過程中產(chǎn)生了不少的小對象。

過小的 segment （32M）

三者結(jié)合造成GC頻繁的觸發(fā)。

改進(jìn)方法也很簡單。

• 最簡單粗暴的方法：將數(shù)據(jù)庫的查詢結(jié)果緩存一份。

• 稍微正規(guī)一點(diǎn)方法：用 Dapper 替換低效的 手工反射，將程序改成 64bit 。

和朋友溝通了解，采用了第一種方法，終于把 CPU 摁下去了，一切都恢復(fù)了平靜！

總結(jié)

以上是生活随笔為你收集整理的记一次 .NET 某资讯论坛 CPU爆高分析的全部內(nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。