关于.net:记一次-NET-车联网云端服务-CPU爆高分析

一：背景

1. 讲故事

前几天有位敌人wx求助，它的程序CPU常常飙满，没找到起因，心愿帮忙看一下。

这些天间断接到几个cpu爆高的dump，都看烦了，心愿前面再来几个其余方面的dump，从沟通上看，这位敌人体现的好惨，可能理论更惨，那既然找到我了，我就尽最大能力帮他找到幕后真凶，话不多说，上 windbg。

二： windbg 剖析

1. 查看托管线程

因为线程都是靠cpu养着，所以从线程上动手也是一个很好的思路，要想查看程序的所有托管线程，能够应用 !t 命令。

0:000> !tThreadCount:      38UnstartedThread:  0BackgroundThread: 34PendingThread:    0DeadThread:       3Hosted Runtime:   no                                                                                                        Lock         ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception   0    1 105c 000000000067f600    2a020 Preemptive  0000000000000000:0000000000000000 0000000000671ec0 0     MTA    2    2 13d0 00000000192c4f40    2b220 Preemptive  0000000000000000:0000000000000000 0000000000671ec0 0     MTA (Finalizer) ...XXXX   15    0 000000001bc64970  8039820 Preemptive  0000000000000000:0000000000000000 0000000000671ec0 0     MTA (Threadpool Completion Port)   24   23 1380 000000001bc660e0  8029220 Preemptive  0000000000000000:0000000000000000 0000000000671ec0 0     MTA (Threadpool Completion Port) XXXX   53    0 000000001bc63200  8039820 Preemptive  0000000000000000:0000000000000000 0000000000671ec0 0     MTA (Threadpool Completion Port) XXXX   27 10dc 000000001bd0dbf0  1029220 Preemptive  0000000002CB40F8:0000000002CB4108 0000000000671ec0 1     MTA (GC) (Threadpool Worker)

在卦象上看：程序有38个线程，死了3个，我去，有一个亮点，最初一行呈现了一个相熟的 MTA (GC) 字样，这什么意思呢？这示意以后线程触发了GC，但奇怪的是，这个触发GC的线程死了，你必定要问怎么看进去的，看行头的 XXXX，先不论了，死马当活马医，调出线程的所有托管和非托管栈，看看有没有 WaitUntilGCComplete 和 try_allocate_more_space 字样。

2. 查看线程栈

要想查看所有线程的线程栈，能够应用 ~*e !dumpstack 命令。

搜寻 WaitUntilGCComplete 关键字。

从图中看，嘿嘿，真的有18个线程在期待，而且还看到了 System.String.Concat ，是不是和我上上篇发的 his cpu爆高是一个套路？

搜寻 try_allocate_more_space 关键字。

我去，居然没有 try_allocate_more_space 关键词，这就和 his 不是一个套路了，有可能这个dump踩的不是特地好的机会，有可能程序正处于某些怪异行为中。

看样子这段路走到头了，不过还是那句话，线程是靠cpu养着的，那就硬着头皮看看各个线程都在做什么吧，为了让后果更清晰一点，换一个命令 ~*e !clrstack。

从图中能够看出以后有 25 个线程正卡在 FindEntry(System.__Canon) 处，而且从调用堆栈上看，貌似是 aliyun 封装的dll，为什么有这么多的线程卡在这里呢？这就给人一个很大的问号？接下来我就把阿里云的这段代码给导出来看看到底产生了什么。

3. 查看问题代码

要想导出问题代码，还是用经典的 !ip2md + !savemodule 组合命令。

0:000> !ip2md 000007fe9a1a0641MethodDesc:   000007fe9a5678e0Method Name:  Aliyun.Acs.Core.Utils.CacheTimeHelper.AddLastClearTimePerProduct(System.String, System.String, System.DateTime)Class:        000007fe9a595a08MethodTable:  000007fe9a567900mdToken:      00000000060000a6Module:       000007fe9a561f58IsJitted:     yesCodeAddr:     000007fe9a1a0610Transparency: Critical0:000> !savemodule 000007fe9a561f58 E:\dumps\AddLastClearTimePerProduct.dll3 sections in filesection 0 - VA=2000, VASize=14148, FileAddr=200, FileSize=14200section 1 - VA=18000, VASize=3fc, FileAddr=14400, FileSize=400section 2 - VA=1a000, VASize=c, FileAddr=14800, FileSize=200

而后用 ILSpy 反编译一下这个dll，因为是阿里云的代码，我就能够放心大胆的放进去啦。

// Aliyun.Acs.Core.Utils.CacheTimeHelperusing System;using System.Collections.Generic;public class CacheTimeHelper{    private static Dictionary<string, DateTime> lastClearTimePerProduct = new Dictionary<string, DateTime>();    private const int ENDPOINT_CACHE_TIME = 3600;    public static bool CheckCacheIsExpire(string product, string regionId)    {        string key = product + "_" + regionId;        DateTime dateTime;        if (lastClearTimePerProduct.ContainsKey(key))        {            dateTime = lastClearTimePerProduct[key];        }        else        {            dateTime = DateTime.Now;            lastClearTimePerProduct.Add(key, dateTime);        }        if (3600.0 < (DateTime.Now - dateTime).TotalSeconds)        {            return true;        }        return false;    }    public static void AddLastClearTimePerProduct(string product, string regionId, DateTime lastClearTime)    {        string key = product + "_" + regionId;        if (lastClearTimePerProduct.ContainsKey(key))        {            lastClearTimePerProduct.Remove(key);        }        lastClearTimePerProduct.Add(key, lastClearTime);    }}

能够看出，下面这段代码在 if (lastClearTimePerProduct.ContainsKey(key)) 处走不上来了，如果往下追，可参考 Dictionary 的源码。

public class Dictionary<TKey, TValue> {    // System.Collections.Generic.Dictionary<TKey,TValue>    public bool ContainsKey(TKey key)    {        return FindEntry(key) >= 0;    }}

到这里，有没有看出这个 CacheTimeHelper 有什么问题吗？对，居然在多线程环境下用的是非线程平安的 Dictionary<string, DateTime>，这就很有问题了。

4. 用 Dictionary 到底会有什么问题

在多线程环境下用 Dictionary 必定会导致数据错乱，这个毫无疑问，而且还会遇到一些 迭代时异样，但如果说这个误用会导致 CPU 爆高，在我的视线范畴内还没看到过。。。为了确保起见，到 bing 上搜搜这样的 咫尺沦落人。

嘿嘿，还真的有这样的案例： High CPU in .NET app using a static Generic.Dictionary ，再截个图。

从文章形容看，几乎是一摸一样，这也就判定在多线程环境下操作 Dictionary ，可能会导致 FindEntry(key) 时呈现死循环，而后 25 个死循环一起把cpu抬起来了，补充一下以后爆满的CPU利用率。。。

0:000> !tpCPU utilization: 100%Worker Thread: Total: 27 Running: 27 Idle: 0 MaxLimit: 32767 MinLimit: 4Work Request in Queue: 0--------------------------------------Number of Timers: 1--------------------------------------Completion Port Thread:Total: 4 Free: 3 MaxFree: 8 CurrentLimit: 3 MaxLimit: 1000 MinLimit: 4

三：总结

既然是阿里云的sdk出的bug，这问题就麻烦了。。。改也改不得，而后通知敌人去提工单解决。

本认为事件就这样完结了，但我想一想，几年前用的阿里云其余 sdk 也遇到了相似CPU爆高的问题，起初通过降级sdk就搞定了，这次也赌赌看，先看一下程序集信息。

[assembly: CompilationRelaxations(8)][assembly: RuntimeCompatibility(WrapNonExceptionThrows = true)][assembly: Debuggable(DebuggableAttribute.DebuggingModes.IgnoreSymbolStoreSequencePoints)][assembly: TargetFramework(".NETStandard,Version=v2.0", FrameworkDisplayName = "")][assembly: AssemblyCompany("Alibaba Cloud")][assembly: AssemblyConfiguration("Release")][assembly: AssemblyCopyright("©2009-2018 Alibaba Cloud")][assembly: AssemblyDescription("Alibaba Cloud SDK for C#")][assembly: AssemblyFileVersion("1.1.12.0")][assembly: AssemblyInformationalVersion("1.1.12")][assembly: AssemblyProduct("aliyun-net-sdk-core")][assembly: AssemblyTitle("aliyun-net-sdk-core")][assembly: AssemblyVersion("1.1.12.0")]

能够看到敌人以后用的是 1.1.12.0 版本，那就把 aliyun-net-sdk-core 降级到最新再看看这个 CacheTimeHelper 有没有被修复？

果然不出所料，在新版本中给修复好了，所以教训通知我，用阿里云的sdk，要记得常常降级，不然各种大坑等着你。。。

更多高质量干货：参见我的 GitHub: dotnetfly