記一次 .NET 車聯網雲端服務 CPU爆高分析

一線碼農發表於2021-05-19

一：背景

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

圖片名稱

相關文章