天天看點

記一次某網站生産環境CPU忽高忽低故障解決過程

感謝

感謝【一級碼農】 的幫助,之前也讀了大佬的好多文章,一直在學習中,也沒有實際操作過。

這次的過程也是在大佬的指點下完成的。

現象描述

從周六上午開始,陸續收到伺服器CPU高的報警短信,到下午已經累計三十多條報警了,看來确實得分析一下原因了。

打開雲監控,與實際情況一緻,CPU居高不下

記一次某網站生産環境CPU忽高忽低故障解決過程

通過程序,很快鎖定是哪個應用,是一個car系統造成的

記一次某網站生産環境CPU忽高忽低故障解決過程

car系統的版本是.net 4.0

記一次某網站生産環境CPU忽高忽低故障解決過程

分析過程

通過以下指令,抓包,指令解釋,當CPU超過50%時,持續三秒,抓兩個包。程序ID是6100。程序ID在任務管理器中可以看到。

procdump -ma -c 50 -s 3 -n 2 6100
           

遇到如下錯誤

記一次某網站生産環境CPU忽高忽低故障解決過程

出現以上錯誤是因為沒有用管理者運作CMD,重新用管理者打開即可。

記一次某網站生産環境CPU忽高忽低故障解決過程

很快抓包完成。從伺服器down到本地。

# 加載sos和clr檔案
0:016> .load C:\Windows\Microsoft.NET\Framework\v4.0.30319\sos.dll
0:016> .load C:\Windows\Microsoft.NET\Framework\v4.0.30319\clr.dll

0:062> !runaway
 User Mode Time
  Thread       Time
  16:dc4       0 days 0:13:12.593
  15:2be4      0 days 0:13:06.390
  17:2404      0 days 0:13:06.328
  18:bb4       0 days 0:12:45.953
  39:3294      0 days 0:04:10.500
  44:320       0 days 0:04:07.281
  38:3b24      0 days 0:04:06.156
  43:176c      0 days 0:04:00.218
  46:1118      0 days 0:03:55.359
  50:2a3c      0 days 0:03:54.921
  40:1aac      0 days 0:03:50.531
  51:2fb4      0 days 0:03:49.421
  47:2508      0 days 0:03:48.718

           

!runaway發現前幾個線程時間很長,那麼他們在幹什麼呢?

切到 16 号線程~16s

0:016> !clrstack
PDB symbol for clr.dll not loaded
Failed to load data access DLL, 0x80004005
Verify that 1) you have a recent build of the debugger (6.2.14 or newer)
            2) the file mscordacwks.dll that matches your version of clr.dll is 
                in the version directory or on the symbol path
            3) or, if you are debugging a dump file, verify that the file 
                mscordacwks_<arch>_<arch>_<version>.dll is on your symbol path.
            4) you are debugging on supported cross platform architecture as 
                the dump file. For example, an ARM dump file must be debugged
                on an X86 or an ARM machine; an AMD64 dump file must be
                debugged on an AMD64 machine.

You can also run the debugger command .cordll to control the debugger's
load of mscordacwks.dll.  .cordll -ve -u -l will do a verbose reload.
If that succeeds, the SOS command should work on retry.

If you are debugging a minidump, you need to make sure that your executable
path is pointing to clr.dll as well.
           

上面不是提示sos clr檔案不對嗎,在伺服器上分析是沒有報這個錯的,是以我從伺服器上弄了兩個回來

.load D:\soft\WinDbg+procdump\procdump\car\sos.dll

.load D:\soft\WinDbg+procdump\procdump\car\clr.dll

0:018> .load D:\soft\WinDbg+procdump\procdump\car\sos.dll
0:018> .load D:\soft\WinDbg+procdump\procdump\car\clr.dll
0:018> !clrstack
PDB symbol for clr.dll not loaded
OS Thread Id: 0xbb4 (18)
Unable to walk the managed stack. The current thread is likely not a 
managed thread. You can run !threads to get a list of managed threads in
the process
Failed to start stack walk: 80070057

           

OK,現在不提示配置問題了。繼續分析

0:016> !clrstack
OS Thread Id: 0xdc4 (16)
Unable to walk the managed stack. The current thread is likely not a 
managed thread. You can run !threads to get a list of managed threads in
the process
Failed to start stack walk: 80070057
0:016> ~15s
eax=00000000 ebx=00000000 ecx=00000000 edx=00000000 esi=00000000 edi=0000053c
eip=76f2c0bc esp=1af3fbfc ebp=1af3fc6c iopl=0         nv up ei pl nz na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000206
ntdll!NtWaitForSingleObject+0xc:
76f2c0bc c20c00          ret     0Ch

           

前四個線程,都提示not a managed thread

記一次某網站生産環境CPU忽高忽低故障解決過程

請教了一下【一級碼農】大佬,這個方向可能是錯誤的。那我們就隻能換一個方向。

這裡大佬已經告訴我是拖管線程的問題,如果是我們首次分析,可能還需要先判斷是拖管還是非拖管的問題。這個後面再慢慢消化加上去。

我們這裡走一個捷徑,直接查拖管線程,有時候你也可以假裝碰碰運氣,說不定就能找到原因了呢。

~*e !clrstack 發現觸發了GC回收

記一次某網站生産環境CPU忽高忽低故障解決過程

記一次某網站生産環境CPU忽高忽低故障解決過程

!dumpstack 顯示目前調用棧上的所有托管對象的資訊,

記一次某網站生産環境CPU忽高忽低故障解決過程

發現這個Volcker.Autotrader.ProductPropertieData.GetAll()方法出現多次,明顯有多個線程卡在這裡了。那這個方法是幹啥的呢,

檢視一下源碼就知道了。

當然,如果有時候你手裡沒有源碼,或者伺服器運作的和本地代碼差異比較大,那就導出源代碼

0:053> !ip2md 1c15f4bd
MethodDesc:   1b9ec174
Method Name:  Volcker.Autotrader.ProductPropertieData.GetAll()
Class:        1bd668a4
MethodTable:  1b9ec19c
mdToken:      06000088
Module:       1b9ebbd4
IsJitted:     yes
CodeAddr:     1c15f420
Transparency: Critical
0:053> !savemodule 1b9ebbd4 D:\dumps\car-cpu\GetAll.dll
3 sections in file
section 0 - VA=2000, VASize=1714c, FileAddr=200, FileSize=17200
section 1 - VA=1a000, VASize=3e8, FileAddr=17400, FileSize=400
section 2 - VA=1c000, VASize=c, FileAddr=17800, FileSize=200
           

需要提前建立好目錄 D:\dumps\car-cpu,找到上面的方法

記一次某網站生産環境CPU忽高忽低故障解決過程

這一行代碼是幹啥的呢,解釋一下,其實是個通用的将資料庫表轉換為實體類的方法。

/// <summary>
        /// 根據IDataReader對屬性進行指派
        /// </summary>
        /// <param name="reader">
        new public void LoadDataReader(IDataReader reader)
        {
            LoadDataReader(MethodBase.GetCurrentMethod(), this, reader);
        }
        
        /// <summary>
        /// 根據DataReader為對象屬性指派
        /// </summary>
        /// <param name="method">所屬類MethodBase對象
        /// <param name="obj">
        /// <param name="reader">設定其屬性 (Property) 值的對象
        /// <returns></returns>
        virtual public void LoadDataReader(MethodBase method, Object obj,IDataReader reader)
        {
            Hashtable cols = new Hashtable();
            for (var i = 0; i < reader.FieldCount; i++)
            {
                cols.Add(reader.GetName(i).ToLower(), reader.GetValue(i));	//裝入資料到hashtable中
            }
            Hashtable h = GetFieldProperties(method, FieldType.DBField);	//擷取屬性的Hasttable
            foreach (var o in h.Keys)
            {
                PropertyInfo p = (PropertyInfo)h[o];
                Object v = null;

                if (cols.Contains(o))
                {
                    v = cols[o];
                }               

                if (v != null)
                {
                    SetPropertieValue(ref obj, ref p, ref v);
                }
            }
        }
           

這裡用了一個反射,通過上面的分析得到,問題出在這一行

Hashtable h = GetFieldProperties(method, FieldType.DBField); //擷取屬性的Hasttable

可能是這個類或者方法的屬性太多吧,或者其他原因造成的。

可能一開始寫這個反射方法用法沒有錯,但是防不住後面有人在類中或者方法中加了其他的東東,造成反射有問題了。

我以前也寫過類似的方法,沒有這個智能,但也從來沒出過問題。

有時候,太智能了也沒有啥必要,

最簡單的代碼效率最高,搞這麼複雜有必要嗎?

不說這個了,解決問題先

由于代碼曆史太悠久,相關細節完全不清楚,是以也不敢改動太大

目前的辦法就是加緩存,這個其實是個字典表,理論上變化不會很大,是以加了24小時的緩存,24小時請求一次。

改一下代碼,更新一下看看。

效果很明顯啊,再觀察幾天看看。

記一次某網站生産環境CPU忽高忽低故障解決過程

總結

上面的分析過程基本上比較詳細了,但有些步驟可能沒有啥邏輯,原因就是靠經驗,或者運氣。經曆的越多,可能猜一下就大概知道原因在哪

再次感謝【一線碼農】的幫助,下面是大佬的總結

記一次某網站生産環境CPU忽高忽低故障解決過程

參考文章

一線碼農的github

教你配置windows上的windbg,linux上的lldb,打入clr内部這一篇就夠了​

記一次某網站生産環境CPU忽高忽低故障解決過程

繼續閱讀