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

Posted on by

一：背景

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[])
...

從棧信息看，大概有如下三點信息：

  • 正在用 EF 做批量插入操作 BulkInsert。
  • 用瞭 Z.EntityFramework 插件。
  • 大量的 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中找到瞭問題代碼。

以上就是.NET CPU爆高事故事故分析某供應鏈WEB網站的詳細內容，更多關於.NET WEB網站CPU爆高的資料請關註WalkonNet其它相關文章！

推薦閱讀：