記一次 .NET 某電商交易平臺Web站 CPU爆高分析

一線碼農發表於2021-05-28
Web

一：背景

1. 講故事

已經連續寫了幾篇關於記憶體暴漲的真實案例，有點麻木了，這篇換個口味，分享一個 CPU爆高 的案例,前段時間有位朋友在 wx 上找到我，說他的一個老專案經常收到 CPU > 90% 的告警資訊，挺尷尬的。

既然找到我，那就用 windbg 分析唄，還能怎麼辦。

二： windbg 分析

1. 勘探現場

既然說 CPU > 90%，那我就來驗證一下是否真的如此？


0:359> !tp
CPU utilization: 100%
Worker Thread: Total: 514 Running: 514 Idle: 0 MaxLimit: 2400 MinLimit: 32
Work Request in Queue: 1
    Unknown Function: 00007ff874d623fc  Context: 0000003261e06e40
--------------------------------------
Number of Timers: 2
--------------------------------------
Completion Port Thread:Total: 2 Free: 2 MaxFree: 48 CurrentLimit: 2 MaxLimit: 2400 MinLimit: 32

從卦象看，真壯觀，CPU直接被打滿，執行緒池裡 514 個執行緒也正在滿負荷奔跑，那到底都奔跑個啥呢？ 首先我得懷疑一下這些執行緒是不是被什麼鎖給定住了。

2. 檢視同步塊表

觀察鎖情況，優先檢視同步塊表，畢竟大家都喜歡用 lock 玩多執行緒同步，可以用 !syncblk 命令檢視。


0:359> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock Owner
   53 000000324cafdf68          498         0 0000000000000000     none    0000002e1a2949b0 System.Object
-----------------------------
Total           1025
CCW             3
RCW             4
ComClassFactory 0
Free            620

我去，這卦看起來很奇怪， MonitorHeld=498 是什麼鬼？？？ 教科書上都說: owner + 1 , waiter + 2，所以你肉眼看到的總會是一個奇數，那偶數又是個啥意思？ 查了下神奇的 StackOverflow，大概總結成如下兩種情況：

  • 記憶體損壞

這種情況比中彩還難，我也堅信不會走這種天羅運。。。

  • lock convoy (鎖護送)

前段時間我分享了一篇真實案例： 記一次 .NET 某旅行社Web站 CPU爆高分析 ，它就是因為 lock convoy 造成的 CPU 爆高，果然世界真小，又遇到了。。。為了方便大家理解，我還是把那張圖貼上吧。

看完這張圖你應該就明白了，一個執行緒在時間片內頻繁的爭搶鎖，所以就很容易的出現一個持有鎖的執行緒剛退出，那些等待鎖的執行緒此時還沒有一個真正的持有鎖，剛好抓到的dump就是這麼一個時間差，換句話說，當前的 498 全部是 waiter 執行緒的計數，也就是 249 個 waiter 執行緒，接下來就可以去驗證了，把所有執行緒的執行緒棧調出來，再檢索下 Monitor.Enter 關鍵詞。

從圖中可以看出當前有 220 個執行緒正卡在 Monitor.Enter 處，貌似丟了29個，不管了，反正大量執行緒卡住就對了，從堆疊上看貌似是在 xxx.Global.PreProcess方法中設定上下文後卡住的，為了滿足好奇心，我就把問題程式碼給匯出來。

3. 檢視問題程式碼

還是用老命令 !ip2md + !savemodule 。


0:359> !ip2md 00007ff81ae98854
MethodDesc:   00007ff819649fa0
Method Name:  xxx.Global.PreProcess(xxx.JsonRequest, System.Object)
Class:        00007ff81966bdf8
MethodTable:  00007ff81964a078
mdToken:      0000000006000051
Module:       00007ff819649768
IsJitted:     yes
CodeAddr:     00007ff81ae98430
Transparency: Critical
0:359> !savemodule 00007ff819649768 E:\dumps\PreProcess.dll
3 sections in file
section 0 - VA=2000, VASize=b6dc, FileAddr=200, FileSize=b800
section 1 - VA=e000, VASize=3d0, FileAddr=ba00, FileSize=400
section 2 - VA=10000, VASize=c, FileAddr=be00, FileSize=200

然後用 ILSpy 開啟問題程式碼，截圖如下：

尼瑪，果然每個 DataContext.SetContextItem() 方法中都有一個 lock 鎖，完美命中 lock convoy。

4. 真的就這樣結束了嗎？

本來準備彙報了，但想著500多個執行緒棧都調出來了，閒著也是閒著，乾脆掃掃看吧，結果我去，意外發現有 134 個執行緒卡在 ReaderWriterLockSlim.TryEnterReadLockCore 處，如下圖所示：

從名字上可以看出，這是一個優化版的讀寫鎖： ReaderWriterLockSlim，為啥有 138 個執行緒都卡在這裡呢？ 真的很好奇，再次匯出問題。



internal class LocalMemoryCache : ICache
{
    private string CACHE_LOCKER_PREFIX = "xx_xx_";

    private static readonly NamedReaderWriterLocker _namedRwlocker = new NamedReaderWriterLocker();

    public T GetWithCache<T>(string cacheKey, Func<T> getter, int cacheTimeSecond, bool absoluteExpiration = true) where T : class
    {
        T val = null;
        ReaderWriterLockSlim @lock = _namedRwlocker.GetLock(cacheKey);
        try
        {
            @lock.EnterReadLock();
            val = (MemoryCache.Default.Get(cacheKey) as T);
            if (val != null)
            {
                return val;
            }
        }
        finally
        {
            @lock.ExitReadLock();
        }
        try
        {
            @lock.EnterWriteLock();
            val = (MemoryCache.Default.Get(cacheKey) as T);
            if (val != null)
            {
                return val;
            }
            val = getter();
            CacheItemPolicy cacheItemPolicy = new CacheItemPolicy();
            if (absoluteExpiration)
            {
                cacheItemPolicy.AbsoluteExpiration = new DateTimeOffset(DateTime.Now.AddSeconds(cacheTimeSecond));
            }
            else
            {
                cacheItemPolicy.SlidingExpiration = TimeSpan.FromSeconds(cacheTimeSecond);
            }
            if (val != null)
            {
                MemoryCache.Default.Set(cacheKey, val, cacheItemPolicy);
            }
            return val;
        }
        finally
        {
            @lock.ExitWriteLock();
        }
    }

看了下上面的程式碼大概想實現一個對 MemoryCache 的 GetOrAdd 操作，而且貌似為了安全起見，每一個 cachekey 都配了一個 ReaderWriterLockSlim，這邏輯就有點奇葩了，畢竟 MemoryCache 本身就帶了實現此邏輯的執行緒安全方法，比如：


public class MemoryCache : ObjectCache, IEnumerable, IDisposable
{
    public override object AddOrGetExisting(string key, object value, DateTimeOffset absoluteExpiration, string regionName = null)
    {
        if (regionName != null)
        {
            throw new NotSupportedException(R.RegionName_not_supported);
        }
        CacheItemPolicy cacheItemPolicy = new CacheItemPolicy();
        cacheItemPolicy.AbsoluteExpiration = absoluteExpiration;
        return AddOrGetExistingInternal(key, value, cacheItemPolicy);
    }
}

5. 用 ReaderWriterLockSlim 有什麼問題嗎？

哈哈，肯定有很多朋友這麼問？???，確實，這有什麼問題呢？首先看一下 _namedRwlocker 集合中目前到底有多少個 ReaderWriterLockSlim ? 想驗證很簡單，上託管堆搜一下即可。


0:359> !dumpheap -type System.Threading.ReaderWriterLockSlim -stat
Statistics:
              MT    Count    TotalSize Class Name
00007ff8741631e8    70234      6742464 System.Threading.ReaderWriterLockSlim

可以看到當前託管堆有 7w+ 的 ReaderWriterLockSlim，這又能怎麼樣呢？？？ 不要忘啦， ReaderWriterLockSlim 之所以帶一個 Slim ，是因為它可以實現使用者態 自旋，那 自旋 就得吃一點CPU，如果再放大幾百倍？ CPU能不被抬起來嗎？

三：總結

總的來說，這個 Dump 所反應出來的 CPU打滿 有兩個原因。

  • lock convoy 造成的頻繁爭搶和上下文切換給了 CPU 一頓暴擊。
  • ReaderWriterLockSlim 的百倍 使用者態自旋 又給了 CPU 一頓暴擊。

知道原因後，應對方案也就簡單了。

  • 批量操作，降低序列化的 lock 個數，不要去玩鎖內卷。
  • 去掉 ReaderWriterLockSlim，使用 MemoryCache 自帶的執行緒安全方法。

更多高質量乾貨：參見我的 GitHub: dotnetfly

圖片名稱

相關文章