記一次 .NET 某資訊論壇 CPU爆高分析
大概有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
從圖中看，這個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 摁下去了，一切都恢復了平靜!
本文轉載自微信公眾號「一線碼農聊技術」，可以通過以下二維碼關注。轉載本文請聯系一線碼農聊技術公眾號。
