一:背景 1. 講故事 前幾天有位朋友找到我,說他們的API服務程式跑著跑著CPU滿了降不下去,讓我幫忙看下怎麼回事,現在貌似民間只有我一個人專註dump分析,還是申明一下我dump分析是免費的,如果想學習.NET高級調試的分析技術,可以來我的訓練營看看,話不多說,dump分析走起! 二:WinDb ...
一:背景
1. 講故事
前幾天有位朋友找到我,說他們的API服務程式跑著跑著CPU滿了降不下去,讓我幫忙看下怎麼回事,現在貌似民間只有我一個人專註dump分析,還是申明一下我dump分析是免費的,如果想學習.NET高級調試的分析技術,可以來我的訓練營看看,話不多說,dump分析走起!
二:WinDbg分析
1. CPU 真的爆高嗎
昨天錄了一個小視頻,大意就是作為分析師,不要過分的相信客戶說的話,他們往往會把你帶偏,你要有自己的分析思路和前進方向,所以需要以數據說話,首先用 !tp
觀察下線程池。
0:030> !tp
CPU utilization: 60%
Worker Thread: Total: 18 Running: 3 Idle: 15 MaxLimit: 32767 MinLimit: 4
Work Request in Queue: 0
--------------------------------------
Number of Timers: 3
--------------------------------------
Completion Port Thread:Total: 3 Free: 1 MaxFree: 8 CurrentLimit: 1 MaxLimit: 1000 MinLimit: 4
從卦中可以看到當前的 CPU=60%
,這個值說高也不高,說低也不低,接下來觀察下這台機器的cpu核心數,可以用 !cpuid
觀察。
0:030> !cpuid
CP F/M/S Manufacturer MHz
0 6,63,2 <unavailable> 2295
1 6,63,2 <unavailable> 2295
2 6,63,2 <unavailable> 2295
3 6,63,2 <unavailable> 2295
真的是無語,做游戲的不都是有錢的主,難道都在降本增效嗎?既然到了 60%,說明有兩個線程估計脫軌了,接下來就需要觀察下那2個托軌線程都在做什麼?
2. 脫軌線程在幹嘛
要想觀察每個線程都在做什麼,可以使用 ~*e !clrstack
命令即可。
0:030> ~*e !clrstack
OS Thread Id: 0x3eec (30)
Child SP IP Call Site
0000001f8fbad610 00007ffd958535c3 System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)
0000001f8fbad680 00007ffd95372933 System.Web.HttpCookieCollection.EnsureKeyValidated(System.String, System.String)
0000001f8fbad6c0 00007ffd9483fa8d System.Web.HttpCookieCollection.Get(System.String)
0000001f8fbad700 00007ffd3d12b3da xxx.CookieHelper.Read(System.String)
...
OS Thread Id: 0x5cf0 (31)
Child SP IP Call Site
0000001f8d27d330 00007ffd958535b8 System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)
0000001f8d27d3a0 00007ffd95372933 System.Web.HttpCookieCollection.EnsureKeyValidated(System.String, System.String)
0000001f8d27d3e0 00007ffd9483fa8d System.Web.HttpCookieCollection.Get(System.String)
0000001f8d27d420 00007ffd3e2ab6da xxx.CookieHelper.Read(System.String)
...
仔細琢磨了一下卦象後,發現有兩個線程都停在 HashSet
上,而且這個集合還是來自於底層的 System.Web
,對一般人來說這個是比較奇葩的現象,但對於我這種有300+分析經驗的熟手來說,一眼就看出來了什麼問題,對,就是多線程操控 HashSet 導致的死迴圈,接下來的問題是如何去驗證呢?畢竟空口無憑。。。
3. 真的死迴圈了嗎
要想瞭解有沒有真的死迴圈,需要你對 HashSet 的底層有一個瞭解,比如說 HashSet 掛鏈的時候在內部是如何組織的,其實這個我在.NET高級訓練營
裡面也做過講解,也做過演示,接下來切到 31 號線程觀察下它的 HashSet 結構。
0:031> !mdso
Thread 31:
Location Object Type
------------------------------------------------------------
RCX: 000000200054ffc0 System.Collections.Generic.HashSet`1+Slot[[System.String, mscorlib]][]
RSI: 000000200054ff58 System.Collections.Generic.HashSet`1[[System.String, mscorlib]]
...
0:031> !mdt 000000200054ff58
000000200054ff58 (System.Collections.Generic.HashSet`1[[System.String, mscorlib]])
m_buckets:000000200054ff98 (System.Int32[], Elements: 3)
m_slots:000000200054ffc0 (System.Collections.Generic.HashSet`1+Slot[[System.String, mscorlib]][], Elements: 3, ElementMT=00007ffd95555230)
m_count:0x0 (System.Int32)
m_lastIndex:0x0 (System.Int32)
m_freeList:0xffffffff (System.Int32)
m_comparer:00000022003d3380 (System.OrdinalComparer)
m_version:0x6 (System.Int32)
m_siInfo:NULL (System.Runtime.Serialization.SerializationInfo)
...
0:031> !mdt -e:2 000000200054ffc0
000000200054ffc0 (System.Collections.Generic.HashSet`1+Slot[[System.String, mscorlib]][], Elements: 3, ElementMT=00007ffd95555230)
[0] (System.Collections.Generic.HashSet`1+Slot[[System.String, mscorlib]]) VALTYPE (MT=00007ffd95555230, ADDR=000000200054ffd0)
hashCode:0xffffffff (System.Int32)
next:0x0 (System.Int32)
value:NULL (System.__Canon)
[1] (System.Collections.Generic.HashSet`1+Slot[[System.String, mscorlib]]) VALTYPE (MT=00007ffd95555230, ADDR=000000200054ffe0)
hashCode:0x3eb5808c (System.Int32)
next:0xffffffff (System.Int32)
value:000000200054f8f0 (System.String) Length=6, String="xxx"
[2] (System.Collections.Generic.HashSet`1+Slot[[System.String, mscorlib]]) VALTYPE (MT=00007ffd95555230, ADDR=000000200054fff0)
hashCode:0x7e225883 (System.Int32)
next:0x1 (System.Int32)
value:000000200054fba0 (System.String) Length=12, String="xxx"
熟悉 HashSet底層的朋友,從上面的卦信息一眼就能看出問題,對,就是這個 next:0x0
,在hashset的掛鏈中,最後一個節點永遠是 -1,如果是 0 的話就相當於指向數組的首元素,最後就是無情死迴圈了,知道了前因後果之後,接下來就要尋找下到底是什麼聖神代碼。
4. 到底是什麼奇葩代碼
這個比較簡單,觀察下線程棧的托管層代碼,然後看源碼即可,為了保護客戶隱私,我就多註釋一點,輸出如下:
0:031> !clrstack
OS Thread Id: 0x5cf0 (31)
Child SP IP Call Site
0000001f8d27d330 00007ffd958535b8 System.Collections.Generic.HashSet`1[[System.__Canon, mscorlib]].Contains(System.__Canon)
0000001f8d27d3a0 00007ffd95372933 System.Web.HttpCookieCollection.EnsureKeyValidated(System.String, System.String)
0000001f8d27d3e0 00007ffd9483fa8d System.Web.HttpCookieCollection.Get(System.String)
0000001f8d27d420 00007ffd3e2ab6da xxx.CookieHelper.Read(System.String)
...
雖然信息比較少,但卦還是很明朗的,客戶寫了一個 CookieHelper 封裝了 Request.Cookies 操作,那到底怎麼封裝的呢?仔細閱讀代碼之後終於發現了,截圖如下:
我去,這代碼還是挺奇葩的,居然將 Cookies 給了靜態變數,靜態變數可是一個進程小緩存呢,水落石出之後改發也比較簡單,把 static 去掉即可。
三:總結
這種將Request.Cookies
賦給靜態變數的奇葩操作其實蘊含著巨大的安全隱患,會導致多個用戶之間串cookie,但以伺服器自爆的方式來避免客戶端串cookie,真的是不幸中的萬幸,哈哈,同時用bug去抑制另一個bug的神操作也真的是大自然的鬼斧神工!