记一次 .NET 某供应链WEB网站 CPU 爆高事故分析

一:背景

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 -aBulkInsert 方法的 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, Configurebanlance 操作都能解释的通,而且还发现这个所谓的预热并没有做到串行化,而是10个线程一起来,直到预热结束,CPU 下降。

三:总结

总的来说,这次CPU阶段性爆高的事故是由于 w3wp 进程的意外重启,导致多线程并发对 Z.EntityFramework 预热,在预热的过程中导致了多次 GC 触发,至于 w3wp 为什么被意外终止,这就是另外一个话题了,不过好消息是朋友在后续的几天中从抓取的 crash dump 中找到了问题代码。

图片名称

原文链接:https://www.cnblogs.com/huangxincheng/p/15928029.html

更多内容