关于.net:记一次-NET-某供应链WEB网站-CPU-爆高事故分析

一：背景

1. 讲故事

年前有位敌人加微信求助，说他的程序呈现了偶发性CPU爆高，寻求如何解决，截图如下：

我倡议敌人用 procdump 在 cpu 高的时候连抓两个dump，这样剖析起来比拟持重，敌人也如期的胜利抓到，接下来就用 windbg 一起来剖析下吧。

二：Windbg 剖析

1. 查看CPU占用率

先用 !tp 查看两个 dump 的cpu 利用率

0:112> !tpCPU utilization: 100%Worker Thread: Total: 138 Running: 128 Idle: 10 MaxLimit: 2000 MinLimit: 400Work 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: 4000:014> !tpCPU utilization: 96%Worker Thread: Total: 173 Running: 67 Idle: 106 MaxLimit: 2000 MinLimit: 400Work 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 Site000000b4ddc79098 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 -aOS Thread Id: 0x3278 (112)        Child SP               IP Call Site000000b4ddc79b90 00007ffda7b31ee8 xxx.BLL.BaseService`1[[System.__Canon, mscorlib]].BulkInsert(System.__Canon[])    PARAMETERS:        this (0x000000b4ddc79d10) = 0x000001fa14bbb630        _tArr (0x000000b4ddc79d18) = 0x000001fa14c1a2f80:112> !do 0x000001fa14c1a2f8Name:        xxx.EntityModel.xxx[]MethodTable: 00007ffda9437968EEClass:     00007ffe02f556b0Size:        56(0x38) bytesArray:       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 中找到了问题代码。