記一次 .NET 某供應鏈WEB網站 CPU 爆高事故分析

一線碼農發表於2022-02-23
Web網站

一：背景

1. 講故事

年前有位朋友加微信求助，說他的程式出現了偶發性CPU爆高，尋求如何解決，截圖如下：

我建議朋友用 procdump 在 cpu 高的時候連抓兩個dump，這樣分析起來比較穩健，朋友也如期的成功抓到，接下來就用 windbg 一起來分析下吧。

二：Windbg 分析

1. 檢視CPU佔用率

先用 !tp 檢視兩個 dump 的cpu 利用率


0:112> !tp
CPU utilization: 100%
Worker Thread: Total: 138 Running: 128 Idle: 10 MaxLimit: 2000 MinLimit: 400
Work Request in Queue: 17
    Unknown Function: 00007ffe1a6617d0  Context: 000001fd9bcb20c8
    ...
--------------------------------------
Number of Timers: 2
--------------------------------------
Completion Port Thread:Total: 2 Free: 2 MaxFree: 16 CurrentLimit: 2 MaxLimit: 2000 MinLimit: 400


0:014> !tp
CPU utilization: 96%
Worker Thread: Total: 173 Running: 67 Idle: 106 MaxLimit: 2000 MinLimit: 400
Work Request in Queue: 1
    Unknown Function: 00007ffe1a6617d0  Context: 000001fda1a20be8
--------------------------------------
Number of Timers: 2
--------------------------------------
Completion Port Thread:Total: 7 Free: 7 MaxFree: 16 CurrentLimit: 7 MaxLimit: 2000 MinLimit: 400

果然如朋友所述，接下來就可以試探的看下是不是 GC 觸發導致 ？

2. 檢視是否 GC 觸發

乾脆一點就是用 ~*e !dumpstack 匯出所有執行緒的託管和非託管棧，然後搜尋 GarbageCollectGeneration 就好了。

果然是觸發了 GC，從呼叫棧資訊看，當前託管層可能正在高頻的 new 操作，導致只往某一個heap上狂寫資料從而致 heap 失衡，伺服器模式GC為了讓多 heap 均衡，做了 heap balance 操作，接下來的線索是為什麼有狂寫的情況？ 還得看下託管層，使用 !clrstack 命令。


0:112> !clrstack 
OS Thread Id: 0x3278 (112)
        Child SP               IP Call Site
000000b4ddc79098 00007ffe28b9fa74 [HelperMethodFrame: 000000b4ddc79098] 
000000b4ddc791a0 00007ffda6c229cb System.Data.Entity.ModelConfiguration.Utilities.EdmPropertyPath.System.Collections.Generic.IEnumerable<System.Data.Entity.Core.Metadata.Edm.EdmProperty>.GetEnumerator()
000000b4ddc79200 00007ffe01a179eb System.Linq.Enumerable.SequenceEqual[[System.__Canon, mscorlib]](System.Collections.Generic.IEnumerable`1<System.__Canon>, System.Collections.Generic.IEnumerable`1<System.__Canon>, System.Collections.Generic.IEqualityComparer`1<System.__Canon>)
000000b4ddc79280 00007ffda6c2297e System.Data.Entity.ModelConfiguration.Configuration.Mapping.EntityMappingConfiguration+c__DisplayClass14.b__11(System.Data.Entity.Core.Mapping.ColumnMappingBuilder)
000000b4ddc792b0 00007ffe01a13f8f System.Linq.Enumerable.SingleOrDefault[[System.__Canon, mscorlib]](System.Collections.Generic.IEnumerable`1<System.__Canon>, System.Func`2<System.__Canon,Boolean>)
000000b4ddc79330 00007ffda6c2087c System.Data.Entity.ModelConfiguration.Configuration.Mapping.EntityMappingConfiguration.Configure(System.Data.Entity.Core.Metadata.Edm.DbDatabaseMapping, System.Data.Entity.Core.Common.DbProviderManifest, System.Data.Entity.Core.Metadata.Edm.EntityType, System.Data.Entity.Core.Mapping.StorageEntityTypeMapping ByRef, Boolean, Int32, Int32)
000000b4ddc79520 00007ffda6c20128 System.Data.Entity.ModelConfiguration.Configuration.Types.EntityTypeConfiguration.ConfigureUnconfiguredType(System.Data.Entity.Core.Metadata.Edm.DbDatabaseMapping, System.Data.Entity.Core.Common.DbProviderManifest, System.Data.Entity.Core.Metadata.Edm.EntityType)
000000b4ddc795a0 00007ffda6c1ffaf System.Data.Entity.ModelConfiguration.Configuration.Types.EntityTypeConfiguration.ConfigureTablesAndConditions(System.Data.Entity.Core.Mapping.StorageEntityTypeMapping, System.Data.Entity.Core.Metadata.Edm.DbDatabaseMapping, System.Data.Entity.Core.Common.DbProviderManifest)
000000b4ddc79620 00007ffda6c055c0 System.Data.Entity.ModelConfiguration.Configuration.ModelConfiguration.ConfigureEntityTypes(System.Data.Entity.Core.Metadata.Edm.DbDatabaseMapping, System.Data.Entity.Core.Common.DbProviderManifest)
000000b4ddc79680 00007ffda6c05474 System.Data.Entity.ModelConfiguration.Configuration.ModelConfiguration.Configure(System.Data.Entity.Core.Metadata.Edm.DbDatabaseMapping, System.Data.Entity.Core.Common.DbProviderManifest)
000000b4ddc796d0 00007ffda69ae5c2 System.Data.Entity.DbModelBuilder.Build(System.Data.Entity.Core.Common.DbProviderManifest, System.Data.Entity.Infrastructure.DbProviderInfo)
000000b4ddc79740 00007ffda6649ccf System.Data.Entity.DbModelBuilder.Build(System.Data.Common.DbConnection)
000000b4ddc79780 00007ffda7b4b2d3 System.Data.Entity.Infrastructure.EdmxWriter.WriteEdmx(System.Data.Entity.DbContext, System.Xml.XmlWriter)
000000b4ddc797c0 00007ffda7b4acbe Class125.smethod_0(System.Data.Entity.DbContext)
000000b4ddc79820 00007ffda7b4aba4 Class617.smethod_22(System.Data.Entity.DbContext)
000000b4ddc79860 00007ffda7b4aa90 Class617.smethod_27(System.Data.Entity.DbContext)
000000b4ddc798c0 00007ffda7b3e9ec DbContextExtensions.GetModel(System.Data.Entity.DbContext)
000000b4ddc79910 00007ffda7b3e49b Class124.smethod_0(System.Data.Entity.DbContext, System.String)
000000b4ddc79950 00007ffda7b3d6c3 Class486.smethod_3[[System.__Canon, mscorlib]](System.Data.Entity.DbContext, Z.BulkOperations.BulkOperation`1<System.__Canon>, System.Collections.Generic.IEnumerable`1<System.__Canon>, System.Collections.Generic.List`1<System.Object>)
000000b4ddc79a00 00007ffda7b36871 DbContextExtensions.BulkInsert[[System.__Canon, mscorlib]](System.Data.Entity.DbContext, System.Collections.Generic.IEnumerable`1<System.__Canon>, System.Action`1<Z.EntityFramework.Extensions.EntityBulkOperation`1<System.__Canon>>)
000000b4ddc79ab0 00007ffda7b32c65 xxx.EFRepository`1[[System.__Canon, mscorlib]].BulkInsert(System.__Canon[])
...

從棧資訊看，大概有如下三點資訊：

  1. 正在用 EF 做批量插入操作 BulkInsert。
  2. 用了 Z.EntityFramework 外掛。
  3. 大量的 Build, Configure 字樣，貌似是在做什麼配置，構建啥的。

3. 是插入資料過多導致的嗎？

第一個能想到的就是 list 過大，為了驗證，可以用 !clrstack -a 把 BulkInsert 方法的 list 引數給匯出來。


0:112> !clrstack -a
OS Thread Id: 0x3278 (112)
        Child SP               IP Call Site
000000b4ddc79b90 00007ffda7b31ee8 xxx.BLL.BaseService`1[[System.__Canon, mscorlib]].BulkInsert(System.__Canon[])
    PARAMETERS:
        this (0x000000b4ddc79d10) = 0x000001fa14bbb630
        _tArr (0x000000b4ddc79d18) = 0x000001fa14c1a2f8

0:112> !do 0x000001fa14c1a2f8
Name:        xxx.EntityModel.xxx[]
MethodTable: 00007ffda9437968
EEClass:     00007ffe02f556b0
Size:        56(0x38) bytes
Array:       Rank 1, Number of elements 4, Type CLASS (Print Array)
Fields:
None

從輸出看，當前的list.length=4，這就很疑惑了，既然 heap 都在 balance ，那是不是有幾個執行緒在猛攻？ 為了驗證就用 DbContextExtensions.BulkInsert 在所有的託管執行緒棧上搜關鍵詞看看。

可以看到當前有 10 處在猛攻，依次看他們的list都不大，疑惑哈?。

4. 對問題的預判斷

有了這些思路，但總覺得觸發GC的由頭太怪了，不過可以肯定的是問題出在了 Z.EntityFramework 外掛上，按照 4S店的傳統經驗，只換不修肯定沒問題，由於我對 Z.EntityFramework 不熟悉，也只能這樣給到朋友了。

說來也奇怪，朋友第二天發現了一個奇怪現象，說每次 CPU 爆高之前都出現了一次 w3wp 的異常重啟，而重啟之後由於 Z.EntityFramework 需要預熱，導致後續請求阻塞引發的 CPU 階段性爆高。

從朋友的留言加上剛才的 dump 分析，問題基本就能定位了， Build, Configure 和 banlance 操作都能解釋的通，而且還發現這個所謂的預熱並沒有做到序列化，而是10個執行緒一起來，直到預熱結束，CPU 下降。

三：總結

總的來說，這次CPU階段性爆高的事故是由於 w3wp 程式的意外重啟，導致多執行緒併發對 Z.EntityFramework 預熱，在預熱的過程中導致了多次 GC 觸發，至於 w3wp 為什麼被意外終止，這就是另外一個話題了，不過好訊息是朋友在後續的幾天中從抓取的 crash dump 中找到了問題程式碼。

相關文章