一:背景
1. 讲故事
前几天有位敌人 wx 求助,它的程序 CPU 常常飙满,没找到起因,心愿帮忙看一下。
这些天间断接到几个 cpu 爆高的 dump,都看烦了😂😂😂,心愿前面再来几个其余方面的 dump,从沟通上看,这位敌人体现的好惨,可能理论更惨,那既然找到我了,我就尽最大能力帮他找到幕后真凶,话不多说,上 windbg。
二:windbg 剖析
1. 查看托管线程
因为线程都是靠 cpu 养着,所以从线程上动手也是一个很好的思路,要想查看程序的所有托管线程,能够应用 !t
命令。
0:000> !t
ThreadCount: 38
UnstartedThread: 0
BackgroundThread: 34
PendingThread: 0
DeadThread: 3
Hosted 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 000007fe9a1a0641
MethodDesc: 000007fe9a5678e0
Method Name: Aliyun.Acs.Core.Utils.CacheTimeHelper.AddLastClearTimePerProduct(System.String, System.String, System.DateTime)
Class: 000007fe9a595a08
MethodTable: 000007fe9a567900
mdToken: 00000000060000a6
Module: 000007fe9a561f58
IsJitted: yes
CodeAddr: 000007fe9a1a0610
Transparency: Critical
0:000> !savemodule 000007fe9a561f58 E:\dumps\AddLastClearTimePerProduct.dll
3 sections in file
section 0 - VA=2000, VASize=14148, FileAddr=200, FileSize=14200
section 1 - VA=18000, VASize=3fc, FileAddr=14400, FileSize=400
section 2 - VA=1a000, VASize=c, FileAddr=14800, FileSize=200
而后用 ILSpy 反编译一下这个 dll,因为是阿里云的代码,我就能够放心大胆的放进去啦。
// Aliyun.Acs.Core.Utils.CacheTimeHelper
using 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> !tp
CPU utilization: 100%
Worker Thread: Total: 27 Running: 27 Idle: 0 MaxLimit: 32767 MinLimit: 4
Work 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