記一次.NET某旅行社Web站CPU爆高分析
本文轉載自微信公眾號「一線碼農聊技術」，作者一線碼農聊技術。轉載本文請聯系一線碼農聊技術公眾號。
一：背景
1. 講故事
前幾天有位朋友wx求助，它的程序內存經常飆升，cpu 偶爾飆升，沒找到原因，希望幫忙看一下。
可惜發過來的 dump 只有區區2G，能在這里面找到內存溢出那真有兩把刷子。。。??????，所以我還是希望他的程序內存漲到 5G+ 的時候再給我看看，既然內存看不了，那就看看這個偶爾飆升的CPU是個啥情況?老辦法，上windbg說話。
二：windbg 分析
1. CPU 到底是多少
要想查看這個快照生成時機器的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
本以為一個簡單的命令，結果屏幕上呼啦啦的一堆。。。有點意外，從上面的卦象看：當前CPU利用率是 93%，沒毛病，確實是CPU飆升，比較驚訝的是，線程池上限800個線程全部被打滿，太悲壯了。。。可更悲壯的是線程池隊列中還有 3203 個待處理的任務，可以猜測程序不僅高CPU，還有掛死現象。。。
接下來的問題是：這800個壯士到底怎么啦，程序現在正是用人之際，要想找出答案，還是按照我的慣性思維，查看同步塊表。
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
我去，又是呼啦啦的一堆，從上面的卦象可以看出兩點信息：
- MonitorHeld: 1
表示當前有一個線程正在持有鎖。
- ASP.global_asax , System.Web.HttpApplicationStateLock
表示當前線程持有的對象。
不過綜合來看有點奇怪，除了第一個線程持有 HttpApplicationStateLock，后面所有的線程持有的 ASP.global_asax 對象都有不同的內存地址:0000000301210038,00000000ff8c5e10，感覺lock的對象不是線程共享式的 static，更像是一個 instance，蠻有意思的，接下來抽兩個線程看看它的線程棧，比如這里的：715,695。
3. 查看線程棧
要想查看線程棧，可以用 !clrstack 命令。
從這兩個線程棧上看，分別是卡在 xxx.MvcApplication.Session_Start 方法中的 System.Threading.Monitor.Enter(System.Object) 和 System.Threading.Monitor.ObjWait ，總的來說這里的 Session_Start 方法肯定是有問題的，所以得想辦法把源碼導出來看一看。
4. 查看問題代碼
要想導出 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 反編譯工具查看，由于比較敏感，我就多模糊一點，請大家見諒!
看完上面的代碼，我其實有一點不解，既然是往 Application 中賦值，為啥不提取到 Application_Start 中呢?我猜測開發人員也是無所謂，怎么方便怎么來，接下來看一下 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);
- }
- }
- }
代碼有點長，但總的來說這里的代碼不簡單，Application 通過 lock 自己封裝了一個 讀寫鎖，不簡單歸不簡單，但這里有什么問題呢 ? 就算寫錯了地方貌似也不會造成 cpu 爆高吧?
其實這里涉及到了一個概念：那就是 lock convoys (鎖護送)
5. lock convoys (鎖護送)
關于什么是 lock convoys ，這里我截一張圖，大家仔細品品。
這也是 無鎖編程 一直在抨擊的現象。
三：總結
我看了下這個 Session_Start 方法中，大概有 105 個 Application[xxx]，也就意味著有 105 個 lock 等著當前線程去闖關。。。而此時有近800個線程已進入到此方法中，合計一下不少于 8W個鎖等著這些線程去闖，在配上被迫的海量cpu時間片切換，喚醒再休眠，休眠再喚醒，大家相互交錯一起把 cpu 給抬起來了。
解決方法很簡單，盡最大努力降低這些 串行lock 的個數，能降到一個甚至沒有就更好了 ??????。
- 對 Application 的賦值全部提取到 Application_Start 中，畢竟程序啟用時無人競爭。
- 盡量將 單行賦值 改成 批量賦值。
