记一次 .NET 某汽贸店 CPU 爆高分析

一：背景

1. 讲故事

上周有位朋友在 github 上向我求助，说线程都被卡住了，让我帮忙看下，截图如下：

时隔两年 终于有人在上面提 Issue 了，看样子这块以后可以作为求助专区来使用，既然来求助，必须得免费帮忙解决，从朋友这边拿到 dump 之后，接下来就可以分析了。
二：WinDbg 分析

1. 为什么有大量线程卡住

在朋友的文案描述中可以看到有一段 !syncblk 输出，格式有点乱，再用这个命令跑一下看看。

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

复制代码

从卦中看，貌似不是一个 dump，不过都有如下几个疑点。
1) MonitorHeld 为什么是偶数？

熟悉同步块表的朋友都知道，持有+1，等待+2，而这个居然是一个偶数，也就表明那个 +1 的线程已经退出了临界区，同时等待线程此时还没有进来，正处在这么一个时间差内。
2) 持有线程信息 为什么不显示？

正因为持有线程已经退出临界区，所以看不到持有线程信息，往细处说就是 AwareLock 类下的 m_HoldingThread 字段被抹掉了，同时用 AwareLock::LockState::InterlockedUnlock 函数解锁了 LockState 中的掩码，前者在 0000000013b666b8+0x8 的位置，后者在 0000000013b666b8+0x4 的位置。

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

复制代码

以多年的治疗经验来看，这是经典的 lock convoy 现象，这个病还会因为高频的上下文切换导致 cpu 爆高。
2. CPU真的爆高吗？

要验证 cpu 是否爆高，可以用 !tp 命令验证。

1. 0:000> !tp
2. CPU utilization: 100%
3. Worker Thread: Total: 336 Running: 336 Idle: 0 MaxLimit: 32767 MinLimit: 16
4. Work Request in Queue: 915
5.     Unknown Function: 000007fef97715cc  Context: 0000000026d95968
6.     Unknown Function: 000007fef97715cc  Context: 0000000026d98b78
7.     Unknown Function: 000007fef97715cc  Context: 0000000026d9bd88
8.     ...
9.     Unknown Function: 000007fef97715cc  Context: 000000002aab0368
10.     Unknown Function: 000007fef97715cc  Context: 000000001d62ed00
11. --------------------------------------
12. Number of Timers: 0
13. --------------------------------------
14. Completion Port Thread:Total: 1 Free: 1 MaxFree: 32 CurrentLimit: 1 MaxLimit: 1000 MinLimit: 16

复制代码

从卦中看，果然是 cpu 爆高，而且还堆积了 915 个待处理的任务，既然有堆积，那就说明下游处理不及，接下来用 ~*e !clrstack 观察下所有的线程，整理后如下：

1. 0:000> ~*e !clrstack
3. OS Thread Id: 0x4228 (404)
4.         Child SP               IP Call Site
5. 000000002417b8d8 00000000771b9e3a [HelperMethodFrame: 000000002417b8d8] System.Threading.Monitor.Enter(System.Object)
6. 000000002417b9d0 000007fe9a6c2bd9 System.ComponentModel.PropertyDescriptorCollection.Find(System.String, Boolean)
7. 000000002417ba40 000007fe9a6c26fc System.Data.XSDSchema.SetProperties(System.Object, System.Xml.XmlAttribute[])
8. 000000002417bab0 000007fe9a6c7b0f System.Data.XSDSchema.HandleElementColumn(System.Xml.Schema.XmlSchemaElement, System.Data.DataTable, Boolean)
9. 000000002417bba0 000007fe9a6c71fa System.Data.XSDSchema.HandleParticle(System.Xml.Schema.XmlSchemaParticle, System.Data.DataTable, System.Collections.ArrayList, Boolean)
10. 000000002417bc70 000007fe9a6c6bf5 System.Data.XSDSchema.HandleComplexType(System.Xml.Schema.XmlSchemaComplexType, System.Data.DataTable, System.Collections.ArrayList, Boolean)
11. 000000002417bcf0 000007fe9a6c3edf System.Data.XSDSchema.InstantiateTable(System.Xml.Schema.XmlSchemaElement, System.Xml.Schema.XmlSchemaComplexType, Boolean)
12. 000000002417bde0 000007fe9a6c383a System.Data.XSDSchema.HandleTable(System.Xml.Schema.XmlSchemaElement)
13. 000000002417be60 000007fe9a6bf0d8 System.Data.XSDSchema.LoadSchema(System.Xml.Schema.XmlSchemaSet, System.Data.DataSet)
14. 000000002417bee0 000007fe9a698c25 System.Data.DataSet.ReadXmlSchema(System.Xml.XmlReader, Boolean)
15. 000000002417bf80 000007fe9a915b45 System.Data.DataTable.DeserializeDataTable(System.Runtime.Serialization.SerializationInfo, System.Runtime.Serialization.StreamingContext, Boolean, System.Data.SerializationFormat)
16. 000000002417bfe0 000007fe9a915981 System.Data.DataTable..ctor(System.Runtime.Serialization.SerializationInfo, System.Runtime.Serialization.StreamingContext)
17. ...
18. 000000002417ce40 000007fe9a781af3 xxx.Cache.Utils.MemcachedProvider.GetDataTable(System.String)
19. ...
20. 000000002417d5a0 000007fe9a7743a9 System.Web.Mvc.ControllerActionInvoker.InvokeAction(System.Web.Mvc.ControllerContext, System.String)
21. 000000002417d600 000007fe9a773110 System.Web.Mvc.Controller.ExecuteCore()
22. ...
23. 000000002417e380 000007fe9a8d5aae DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, System.Web.RequestNotificationStatus ByRef)
24. 000000002417e440 000007fe9a8c0231 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
25. 000000002417e5f0 000007fe9a8bf854 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)

复制代码

从卦中信息看，当时有一个 http 请求，然后在 MemCached 中获取一条数据再将获取到的数据转成 DataTable 的过程中被锁等待。

接下来检索下 GetDataTable 方法高达 336 处，也就表示当前有 336 个线程在抢这个锁，高频的进入和退出导致的 CPU 爆高。
3. 问题代码在哪里

仔细观察代码会发现将 Byte[] 转成 DataTable 内部的逻辑不简单，会大量使用反射，然后在反射中又会大量的使用锁，接下来仔细观察调用栈，最终定位到了上层 GetxxxSite() 函数调用，简化后的代码如下：

1. public static DataTable GetxxxSite()
2. {
3.     string text = HttpContext.Current.Request.Url.ToStr();
4.     string xxxDomain = GetxxxDomain();
6.     DataTable dataTable = CacheHelper.GetDataTable("xxxSite_" + xxxDomain, -1, 0);
8.     if (dataTable.HasRecord())
9.     {
10.         return dataTable;
11.     }
13.     dataTable = GetxxxSiteInfo(xxxDomain);
15.     if (dataTable.HasRecord())
16.     {
17.         _xxxSite = dataTable;
18.         CacheHelper.AddCache("xxxSite_" + xxxDomain, dataTable, -1, 0);
19.     }
20.     return dataTable;
21. }

复制代码

有朋友可能有疑问，这代码怎么可能会出现 lock convoy 呢？ 你可以这么想一想，本来 CacheHelper.GetDataTable 函数只需 10ms 就能执行完，但需要执行 100 次 lock，然而在这 10ms 之内，又来了一个请求，也需要 100 次 lock，因为反序列成 DataTable 底层是共享的 lock，导致上一次 100 的lock 和这次 100 的 lock 要进行锁竞争，导致大家的执行时间由 10ms 延长到了 15ms。
可气的是，这 15ms 之间又来了100个线程，导致 100*100 =1000 个锁竞争，执行时间由原来的 15ms 延长到了 1min，以此类推，最终导致本该 10ms 执行的函数，结果要几分钟才能执行完。
知道了原理之后，缓解措施就简单了。

• 在 CacheHelper.GetDataTable 加串行锁
  

这个只能治标，也是最简单的方式，可以将原来的 平方锁 降成 线性锁，来缓解锁竞争，CPU爆高的问题也就迎刃而解。

• 不要转成 DataTable
  

本质的问题是转成 DataTable 的过程中有大量的锁，如果直接转成 List 自然就绕过去了，在现代编程中也是极力推荐的。
三：总结

这次 CPU 爆高事故，主要就是将 byte[] 转成 DataTable 的过程中出现的 lock convoy 现象，治标治本的方案也说了，希望给后来人少踩一些坑吧。

免责声明：如果侵犯了您的权益，请联系站长，我们会及时删除侵权内容，谢谢合作！

QWF  G GG

VEV   RR 3G