記一次 .NET 某資訊論壇 CPU爆高分析
大概有11天沒發(fā)文了，真的不是因?yàn)閼校鞠肭皫滋斐榭諏懀恢罏樯蹲罱笾呐笥驯容^多，一天都能拿到2-3個(gè)求助dump，晚上回來就是一頓分析，有點(diǎn)意思的是大多朋友自己都分析了幾遍或者公司多年的牛皮蘚問題，真的是心太累，不過也好，累那是走上坡路??????。
再回到正題，在一個(gè)月前，有位朋友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: 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% 指的是當(dāng)前機(jī)器而不是程序，言外之意就是當(dāng)機(jī)器的CPU 100% 時(shí)，并不一定是你所dump的程序造成的。
2. 是否為 GC 觸發(fā)
面對這陌生的dump，先進(jìn)行一些經(jīng)驗(yàn)性排查，比如說是否為 GC 觸發(fā)導(dǎo)致? 那怎么去驗(yàn)證這個(gè)假設(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: 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
從輸出看，尼瑪果然有，那就表明確實(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_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 看看哪一個(gè)線程觸發(fā)了 CLR 中的 GarbageCollectGeneration 方法。
從圖中可以看到是 53 號線程觸發(fā)了，切到53號線程后換用 !clrstack。
從線程棧看，程序做了一個(gè) 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í)行了一個(gè)存儲過程 xxxProperty_GetAll , 然后把獲取到數(shù)據(jù)的 reader 和 xxxPropertyTreeInfo 做了一個(gè) 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
從圖中看，這個(gè)size并不大，那為什么會導(dǎo)致gc頻繁觸發(fā)呢?就算做了 反射 產(chǎn)生了很多的小對象，應(yīng)該也沒多大影響哈。。。這又讓我陷入了沉思。。。
4. 尋找問題根源
經(jīng)過一頓查找，我發(fā)現(xiàn)了幾個(gè)疑點(diǎn)。
有24個(gè)線程正在執(zhí)行 XXX.GetALL() 方法。
托管堆中發(fā)現(xiàn)了 123 個(gè) list，大的size 也有 1298，所以合計(jì)起來也不小哈。。。
- 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
從內(nèi)存地址就能判斷當(dāng)前程序是 32bit，這就意味著它的 segment 段會很小，也就意味著更多的GC回收。
三：總結(jié)
本次事故是由于：
多個(gè)線程頻繁重復(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ù)了平靜!
本文轉(zhuǎn)載自微信公眾號「一線碼農(nóng)聊技術(shù)」，可以通過以下二維碼關(guān)注。轉(zhuǎn)載本文請聯(lián)系一線碼農(nóng)聊技術(shù)公眾號。
