技術文章 » 記一次 .NET 某汽貿店 CPU 爆高分析

記一次 .NET 某汽貿店 CPU 爆高分析

2023-05-23 06:01:34

一：背景

1. 講故事

上週有位朋友在 github 上向我求助，說執行緒都被卡住了，讓我幫忙看下，截圖如下：

時隔兩年 終於有人在上面提 Issue 了，看樣子這塊以後可以作為求助專區來使用，既然來求助，必須得免費幫忙解決，從朋友這邊拿到 dump 之後，接下來就可以分析了。

二：WinDbg 分析

1. 為什麼有大量執行緒卡住

在朋友的文案描述中可以看到有一段 !syncblk 輸出，格式有點亂，再用這個命令跑一下看看。


0:000> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock Owner
49755 0000000013b666b8          602         0 0000000000000000     none    00000001bfc5f0b0 System.ComponentModel.PropertyDescriptorCollection
-----------------------------
Total           207053
CCW             22
RCW             4
ComClassFactory 0
Free            0

從卦中看，貌似不是一個 dump，不過都有如下幾個疑點。

1) MonitorHeld 為什麼是偶數？

熟悉同步塊表的朋友都知道，持有+1，等待+2，而這個居然是一個偶數，也就表明那個 +1 的執行緒已經退出了臨界區，同時等待執行緒此時還沒有進來，正處在這麼一個時間差內。

2) 持有執行緒資訊 為什麼不顯示？

正因為持有執行緒已經退出臨界區，所以看不到持有執行緒資訊，往細處說就是 AwareLock 類下的 m_HoldingThread 欄位被抹掉了，同時用 AwareLock::LockState::InterlockedUnlock 函數解鎖了 LockState 中的掩碼，前者在 0000000013b666b8+0x8 的位置，後者在 0000000013b666b8+0x4 的位置。


0:000> dp 0000000013b666b8
00000000`13b666b8  00000000`0000025a 00000000`00000000

以多年的治療經驗來看，這是經典的 lock convoy 現象，這個病還會因為高頻的上下文切換導致 cpu 爆高。

2. CPU真的爆高嗎？

要驗證 cpu 是否爆高，可以用 !tp 命令驗證。


0:000> !tp
CPU utilization: 100%
Worker Thread: Total: 336 Running: 336 Idle: 0 MaxLimit: 32767 MinLimit: 16
Work Request in Queue: 915
    Unknown Function: 000007fef97715cc  Context: 0000000026d95968
    Unknown Function: 000007fef97715cc  Context: 0000000026d98b78
    Unknown Function: 000007fef97715cc  Context: 0000000026d9bd88
    ...
    Unknown Function: 000007fef97715cc  Context: 000000002aab0368
    Unknown Function: 000007fef97715cc  Context: 000000001d62ed00
--------------------------------------
Number of Timers: 0
--------------------------------------
Completion Port Thread:Total: 1 Free: 1 MaxFree: 32 CurrentLimit: 1 MaxLimit: 1000 MinLimit: 16

從卦中看，果然是 cpu 爆高，而且還堆積了 915 個待處理的任務，既然有堆積，那就說明下游處理不及，接下來用 ~*e !clrstack 觀察下所有的執行緒，整理後如下：


0:000> ~*e !clrstack

OS Thread Id: 0x4228 (404)
        Child SP               IP Call Site
000000002417b8d8 00000000771b9e3a [HelperMethodFrame: 000000002417b8d8] System.Threading.Monitor.Enter(System.Object)
000000002417b9d0 000007fe9a6c2bd9 System.ComponentModel.PropertyDescriptorCollection.Find(System.String, Boolean)
000000002417ba40 000007fe9a6c26fc System.Data.XSDSchema.SetProperties(System.Object, System.Xml.XmlAttribute[])
000000002417bab0 000007fe9a6c7b0f System.Data.XSDSchema.HandleElementColumn(System.Xml.Schema.XmlSchemaElement, System.Data.DataTable, Boolean)
000000002417bba0 000007fe9a6c71fa System.Data.XSDSchema.HandleParticle(System.Xml.Schema.XmlSchemaParticle, System.Data.DataTable, System.Collections.ArrayList, Boolean)
000000002417bc70 000007fe9a6c6bf5 System.Data.XSDSchema.HandleComplexType(System.Xml.Schema.XmlSchemaComplexType, System.Data.DataTable, System.Collections.ArrayList, Boolean)
000000002417bcf0 000007fe9a6c3edf System.Data.XSDSchema.InstantiateTable(System.Xml.Schema.XmlSchemaElement, System.Xml.Schema.XmlSchemaComplexType, Boolean)
000000002417bde0 000007fe9a6c383a System.Data.XSDSchema.HandleTable(System.Xml.Schema.XmlSchemaElement)
000000002417be60 000007fe9a6bf0d8 System.Data.XSDSchema.LoadSchema(System.Xml.Schema.XmlSchemaSet, System.Data.DataSet)
000000002417bee0 000007fe9a698c25 System.Data.DataSet.ReadXmlSchema(System.Xml.XmlReader, Boolean)
000000002417bf80 000007fe9a915b45 System.Data.DataTable.DeserializeDataTable(System.Runtime.Serialization.SerializationInfo, System.Runtime.Serialization.StreamingContext, Boolean, System.Data.SerializationFormat)
000000002417bfe0 000007fe9a915981 System.Data.DataTable..ctor(System.Runtime.Serialization.SerializationInfo, System.Runtime.Serialization.StreamingContext)
...
000000002417ce40 000007fe9a781af3 xxx.Cache.Utils.MemcachedProvider.GetDataTable(System.String)
...
000000002417d5a0 000007fe9a7743a9 System.Web.Mvc.ControllerActionInvoker.InvokeAction(System.Web.Mvc.ControllerContext, System.String)
000000002417d600 000007fe9a773110 System.Web.Mvc.Controller.ExecuteCore()
...
000000002417e380 000007fe9a8d5aae DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, System.Web.RequestNotificationStatus ByRef)
000000002417e440 000007fe9a8c0231 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
000000002417e5f0 000007fe9a8bf854 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)

從卦中資訊看，當時有一個 http 請求，然後在 MemCached 中獲取一條資料再將獲取到的資料轉成 DataTable 的過程中被鎖等待。

接下來檢索下 GetDataTable 方法高達 336 處，也就表示當前有 336 個執行緒在搶這個鎖，高頻的進入和退出導致的 CPU 爆高。

3. 問題程式碼在哪裡

仔細觀察程式碼會發現將 Byte[] 轉成 DataTable 內部的邏輯不簡單，會大量使用反射，然後在反射中又會大量的使用鎖，接下來仔細觀察呼叫棧，最終定位到了上層 GetxxxSite() 函數呼叫，簡化後的程式碼如下：


public static DataTable GetxxxSite()
{
    string text = HttpContext.Current.Request.Url.ToStr();
    string xxxDomain = GetxxxDomain();

    DataTable dataTable = CacheHelper.GetDataTable("xxxSite_" + xxxDomain, -1, 0);

    if (dataTable.HasRecord())
    {
        return dataTable;
    }

    dataTable = GetxxxSiteInfo(xxxDomain);

    if (dataTable.HasRecord())
    {
        _xxxSite = dataTable;
        CacheHelper.AddCache("xxxSite_" + xxxDomain, dataTable, -1, 0);
    }
    return dataTable;
}

有朋友可能有疑問，這程式碼怎麼可能會出現 lock convoy 呢？ 你可以這麼想一想，本來 CacheHelper.GetDataTable 函數只需 10ms 就能執行完，但需要執行 100 次 lock，然而在這 10ms 之內，又來了一個請求，也需要 100 次 lock，因為反序列成 DataTable 底層是共用的 lock，導致上一次 100 的lock 和這次 100 的 lock 要進行鎖競爭，導致大家的執行時間由 10ms 延長到了 15ms。

可氣的是，這 15ms 之間又來了100個執行緒，導致 100*100 =10000 個鎖競爭，執行時間由原來的 15ms 延長到了 1min，以此類推，最終導致本該 10ms 執行的函數，結果要幾分鐘才能執行完。

知道了原理之後，緩解措施就簡單了。

  1. 在 CacheHelper.GetDataTable 加序列鎖

這個只能治標，也是最簡單的方式，可以將原來的 平方鎖 降成 線性鎖，來緩解鎖競爭，CPU爆高的問題也就迎刃而解。

  1. 不要轉成 DataTable

本質的問題是轉成 DataTable 的過程中有大量的鎖，如果直接轉成 List 自然就繞過去了，在現代程式設計中也是極力推薦的。

三：總結

這次 CPU 爆高事故，主要就是將 byte[] 轉成 DataTable 的過程中出現的 lock convoy 現象，治標治本的方案也說了，希望給後來人少踩一些坑吧。

圖片名稱