[[431414]]

大概有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打滿了，對(duì)了，這里稍微提醒下， CPU utilization: 100% 指的是當(dāng)前機(jī)器而不是程序，言外之意就是當(dāng)機(jī)器的CPU 100% 時(shí)，并不一定是你所dump的程序造成的。

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

面對(duì)這陌生的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 號(hào)線程觸發(fā)了，切到53號(hào)線程后換用 !clrstack。

從線程棧看，程序做了一個(gè) XXX.GetAll() 操作，一看這名字就蠻恐怖的，接下來我們?cè)倏纯催@塊源碼，到底做了什么操作，簡(jiǎn)化后的源碼如下：

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è)存儲(chǔ)過程 xxxProperty_GetAll , 然后把獲取到數(shù)據(jù)的 reader 和 xxxPropertyTreeInfo 做了一個(gè) mapping 映射，在映射的過程中觸發(fā)了GC。

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

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

從圖中看，這個(gè)size并不大，那為什么會(huì)導(dǎo)致gc頻繁觸發(fā)呢?就算做了 反射 產(chǎn)生了很多的小對(duì)象，應(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 段會(huì)很小，也就意味著更多的GC回收。

三：總結(jié)

本次事故是由于：

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

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

過小的 segment (32M)

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

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

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

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

本文轉(zhuǎn)載自微信公眾號(hào)「一線碼農(nóng)聊技術(shù)」，可以通過以下二維碼關(guān)注。轉(zhuǎn)載本文請(qǐng)聯(lián)系一線碼農(nóng)聊技術(shù)公眾號(hào)。