記一次 .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,先不管了,死馬當活馬醫,調出執行緒的所有託管和非託管棧,看看有沒有 WaitUntilGCCompletetry_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

圖片名稱

相關文章