[[431414]]

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

再回到正題，在一個月前，有位朋友wx找到我，他最近也在學習如何分析dump，可能經驗不是很豐富，分析不下去了，截圖如下：

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

面對這陌生的dump，先進行一些經驗性排查，比如說是否為 GC 觸發(fā)導致? 那怎么去驗證這個假設呢?為了讓結果更準確一點，用 !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觸發(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 看看哪一個線程觸發(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 , 然后把獲取到數據的 reader 和 xxxPropertyTreeInfo 做了一個 mapping 映射，在映射的過程中觸發(fā)了GC。

3. 是否為數據過大導致?

按照以往經驗，應該是從數據庫中獲取了過多數據導致，那本次dump是不是呢?要想尋找答案， 先用 !dso 命令導出線程棧所有變量，然后用 !do xxx 查看 List list 的size，如下圖所示：

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

4. 尋找問題根源

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

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

托管堆中發(fā)現(xiàn)了 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頻繁的觸發(fā)。

改進方法也很簡單。

• 最簡單粗暴的方法：將數據庫的查詢結果緩存一份。
• 稍微正規(guī)一點方法：用 Dapper 替換低效的 手工反射，將程序改成 64bit 。

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

本文轉載自微信公眾號「一線碼農聊技術」，可以通過以下二維碼關注。轉載本文請聯(lián)系一線碼農聊技術公眾號。