記一次.NET某旅行社Web站CPU爆高分析
本文轉(zhuǎn)載自微信公眾號(hào)「一線碼農(nóng)聊技術(shù)」，作者一線碼農(nóng)聊技術(shù)。轉(zhuǎn)載本文請(qǐng)聯(lián)系一線碼農(nóng)聊技術(shù)公眾號(hào)。
一：背景
1. 講故事
前幾天有位朋友wx求助，它的程序內(nèi)存經(jīng)常飆升，cpu 偶爾飆升，沒找到原因，希望幫忙看一下。
可惜發(fā)過來的 dump 只有區(qū)區(qū)2G，能在這里面找到內(nèi)存溢出那真有兩把刷子。。。??????，所以我還是希望他的程序內(nèi)存漲到 5G+ 的時(shí)候再給我看看，既然內(nèi)存看不了，那就看看這個(gè)偶爾飆升的CPU是個(gè)啥情況?老辦法，上windbg說話。
二：windbg 分析
1. CPU 到底是多少
要想查看這個(gè)快照生成時(shí)機(jī)器的cpu使用率，可以使用 !tp 命令。
- 0:033> !tp
- CPU utilization: 93%
- Worker Thread: Total: 800 Running: 800 Idle: 0 MaxLimit: 800 MinLimit: 320
- Work Request in Queue: 3203
- Unknown Function: 000007fefb551500 Context: 000000002a198480
- Unknown Function: 000007fefb551500 Context: 0000000028a70780
- Unknown Function: 000007fefb551500 Context: 000000002a182610
- Unknown Function: 000007fefb551500 Context: 00000000262a2700
本以為一個(gè)簡(jiǎn)單的命令，結(jié)果屏幕上呼啦啦的一堆。。。有點(diǎn)意外，從上面的卦象看：當(dāng)前CPU利用率是 93%，沒毛病，確實(shí)是CPU飆升，比較驚訝的是，線程池上限800個(gè)線程全部被打滿，太悲壯了。。?？筛瘔训氖蔷€程池隊(duì)列中還有 3203 個(gè)待處理的任務(wù)，可以猜測(cè)程序不僅高CPU，還有掛死現(xiàn)象。。。
接下來的問題是：這800個(gè)壯士到底怎么啦，程序現(xiàn)在正是用人之際，要想找出答案，還是按照我的慣性思維，查看同步塊表。
2. 線程同步塊表
要想查看同步塊表，可以使用 !synblk 命令。
- 0:033> !syncblk
- Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner
- 188 0000000010defc28 1 1 000000001e8fb400 9f4 715 00000003ff1e3d80 System.Web.HttpApplicationStateLock
- 126159 000000001e424e28 1 1 0000000023425e00 1f14 695 0000000301210038 ASP.global_asax
- 126173 00000000281acaf8 1 1 0000000024b8ea70 24ec 785 00000000ff8c5e10 ASP.global_asax
- 126289 00000000247a4068 1 1 0000000027ee93c0 808 413 0000000306aca288 ASP.global_asax
- 126368 0000000027180dd8 1 1 0000000028005cb0 1e7c 650 00000002008d6280 ASP.global_asax
- 126489 0000000027211dd8 1 1 0000000026862420 ec4 220 000000030611a290 ASP.global_asax
- 126788 00000000247924b8 1 1 0000000021871ff0 2784 529 00000004039901a8 ASP.global_asax
- 126843 00000000285b8d28 1 1 000000001cbd6710 2170 456 00000004007ec748 ASP.global_asax
- 126934 0000000021b212b8 1 1 0000000026ca7590 16cc 472 000000030090e810 ASP.global_asax
- 127251 0000000024769188 1 1 000000002831eaf0 2b68 648 0000000207051038 ASP.global_asax
- ...
- -----------------------------
- Total 141781
- CCW 2
- RCW 4
- ComClassFactory 0
- Free 140270
我去，又是呼啦啦的一堆，從上面的卦象可以看出兩點(diǎn)信息：
- MonitorHeld: 1
表示當(dāng)前有一個(gè)線程正在持有鎖。
- ASP.global_asax , System.Web.HttpApplicationStateLock
表示當(dāng)前線程持有的對(duì)象。
不過綜合來看有點(diǎn)奇怪，除了第一個(gè)線程持有 HttpApplicationStateLock，后面所有的線程持有的 ASP.global_asax 對(duì)象都有不同的內(nèi)存地址:0000000301210038,00000000ff8c5e10，感覺lock的對(duì)象不是線程共享式的 static，更像是一個(gè) instance，蠻有意思的，接下來抽兩個(gè)線程看看它的線程棧，比如這里的：715,695。
3. 查看線程棧
要想查看線程棧，可以用 !clrstack 命令。
從這兩個(gè)線程棧上看，分別是卡在 xxx.MvcApplication.Session_Start 方法中的 System.Threading.Monitor.Enter(System.Object) 和 System.Threading.Monitor.ObjWait ，總的來說這里的 Session_Start 方法肯定是有問題的，所以得想辦法把源碼導(dǎo)出來看一看。
4. 查看問題代碼
要想導(dǎo)出 Session_Start 方法，使用組合命令 !ip2md + !savemodule 即可。
- ||2:2:1781> !ip2md 000007fe99c6f0c5
- MethodDesc: 000007fe990fe080
- Method Name: xxx.xxx.xxx.MvcApplication.Session_Start(System.Object, System.EventArgs)
- Class: 000007fe991ae0c0
- MethodTable: 000007fe990fe238
- mdToken: 0000000006000119
- Module: 000007fe990fd750
- IsJitted: yes
- CodeAddr: 000007fe99c6e1f0
- Transparency: Critical
- ||2:2:1781> !savemodule 000007fe990fd750 E:\dumps\Session_Start.dll
- 3 sections in file
- section 0 - VA=2000, VASize=17538, FileAddr=200, FileSize=17600
- section 1 - VA=1a000, VASize=3ac, FileAddr=17800, FileSize=400
- section 2 - VA=1c000, VASize=c, FileAddr=17c00, FileSize=200
然后借助 ILSpy 反編譯工具查看，由于比較敏感，我就多模糊一點(diǎn)，請(qǐng)大家見諒!
看完上面的代碼，我其實(shí)有一點(diǎn)不解，既然是往 Application 中賦值，為啥不提取到 Application_Start 中呢?我猜測(cè)開發(fā)人員也是無所謂，怎么方便怎么來，接下來看一下 Application 的源碼。
- public sealed class HttpApplicationState : NameObjectCollectionBase
- {
- private HttpApplicationStateLock _lock = new HttpApplicationStateLock();
- public void Set(string name, object value)
- {
- _lock.AcquireWrite();
- try
- {
- BaseSet(name, value);
- }
- finally
- {
- _lock.ReleaseWrite();
- }
- }
- }
- internal class HttpApplicationStateLock : ReadWriteObjectLock
- {
- internal override void AcquireWrite()
- {
- int currentThreadId = SafeNativeMethods.GetCurrentThreadId();
- if (_threadId == currentThreadId)
- {
- _recursionCount++;
- return;
- }
- base.AcquireWrite();
- _threadId = currentThreadId;
- _recursionCount = 1;
- }
- internal override void ReleaseWrite()
- {
- int currentThreadId = SafeNativeMethods.GetCurrentThreadId();
- if (_threadId == currentThreadId && --_recursionCount == 0)
- {
- _threadId = 0;
- base.ReleaseWrite();
- }
- }
- }
- internal class ReadWriteObjectLock
- {
- internal virtual void AcquireWrite()
- {
- lock (this)
- {
- while (_lock != 0)
- {
- try
- {
- Monitor.Wait(this);
- }
- catch (ThreadInterruptedException)
- {
- }
- }
- _lock = -1;
- }
- }
- internal virtual void ReleaseWrite()
- {
- lock (this)
- {
- _lock = 0;
- Monitor.PulseAll(this);
- }
- }
- }
代碼有點(diǎn)長(zhǎng)，但總的來說這里的代碼不簡(jiǎn)單，Application 通過 lock 自己封裝了一個(gè) 讀寫鎖，不簡(jiǎn)單歸不簡(jiǎn)單，但這里有什么問題呢 ? 就算寫錯(cuò)了地方貌似也不會(huì)造成 cpu 爆高吧?
其實(shí)這里涉及到了一個(gè)概念：那就是 lock convoys (鎖護(hù)送)
5. lock convoys (鎖護(hù)送)
關(guān)于什么是 lock convoys ，這里我截一張圖，大家仔細(xì)品品。
這也是 無鎖編程 一直在抨擊的現(xiàn)象。
三：總結(jié)
我看了下這個(gè) Session_Start 方法中，大概有 105 個(gè) Application[xxx]，也就意味著有 105 個(gè) lock 等著當(dāng)前線程去闖關(guān)。。。而此時(shí)有近800個(gè)線程已進(jìn)入到此方法中，合計(jì)一下不少于 8W個(gè)鎖等著這些線程去闖，在配上被迫的海量cpu時(shí)間片切換，喚醒再休眠，休眠再喚醒，大家相互交錯(cuò)一起把 cpu 給抬起來了。
解決方法很簡(jiǎn)單，盡最大努力降低這些 串行l(wèi)ock 的個(gè)數(shù)，能降到一個(gè)甚至沒有就更好了 ??????。
- 對(duì) Application 的賦值全部提取到 Application_Start 中，畢竟程序啟用時(shí)無人競(jìng)爭(zhēng)。
- 盡量將 單行賦值 改成 批量賦值。
