公司某資料子系統定期cpu過高的診斷

dotnet程式故障診斷發表於2023-03-06

背景

公司裡的某負責儲存使用者文件的子系統有時會忽然cpu很高，過了大約5分鐘後又恢復正常水平。領導協調讓我幫看一下 (我心裡是: 不熟悉這個子系統裡面的程式碼，我盡力哈?)

其實確實是這樣的，如果熟悉出問題的系統的程式碼，會對診斷問題起到很大的幫助，否則就需要更多的利用對底層的理解了。

分析

打聽後知道了這個子系統用.net core寫的，可以執行在windows和linux docker上，且這次的cpu高的問題，他們在windows執行也可復現。於是，我讓他們在windows上執行，發現cpu高的時候dump一下。(然後windbg就可以準備下地幹活了?)

在用windbg看了大部分threadpool worker執行緒的情況後，我發現大部分執行緒都執行到這樣類似的call stack上:

先大概看一下這個PeopleManagementService.Program+c__DisplayClass2_0.b__0(PeopleManagementService.User)在做什麼，用IL反編譯工具可以看到:

再結合call stack，感覺上下文正在從某集合裡查詢東西呢？（一個題外話，上面那個c__DisplayClass2_0.b__0名字挺奇怪，其實這是C# compiler在build我們的C#程式碼到IL時幫著生成的一些code。對於目前這個，就對應我們C#程式設計師寫出的lambda )

找東西會把cpu明顯提高麼？去看看PrintUserLastEnteredTimeDetail()在幹什麼吧。(其實子系統team的同事人很好，所以這次我直接找他要對應的程式碼得了?) 簡化程式碼：

 看起來是在一個叫users的List中按條件查詢東西。看看這個list的size, 用!do試一下：

 1 0:027> !DumpObj /d 0000019a8000d938
 2 Name:        System.Collections.Generic.List`1[[PeopleManagementService.User, PeopleManagementService]]
 3 MethodTable: 00007ff96c313e88
 4 EEClass:     00007ff96c2df530
 5 Tracked Type: false
 6 Size:        32(0x20) bytes
 7 File:        C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.14\System.Private.CoreLib.dll
 8 Fields:
 9               MT    Field   Offset                 Type VT     Attr            Value Name
10 00007ff96c2fd618  4002099        8     System.__Canon[]  0 instance 0000019a90bc12a0 _items
11 00007ff96c2a94b0  400209a       10         System.Int32  1 instance           524288 _size
12 00007ff96c2a94b0  400209b       14         System.Int32  1 instance           524288 _version
13 00007ff96c2fd618  400209c        8     System.__Canon[]  0   static dynamic statics NYI                 s_emptyArray
size大約524288，500K的items在list裡面，然後多個執行緒在一起進行這樣的查詢，所以cpu提高了。

後記

在告知同事這個原因前，我還有意無意地查了一下那個儲存big list的Dictionary，用!gcroot:

 然後!do看一下：

1 !do 0000019A8000D818
2 Name:        System.Collections.Generic.Dictionary`2+Entry[[System.String, System.Private.CoreLib],[System.Collections.Generic.List`1[[PeopleManagementService.User, PeopleManagementService]], System.Private.CoreLib]][]
3 MethodTable: 00007ff96c322808
4 EEClass:     00007ff96c322770
5 Tracked Type: false
6 Size:        96(0x60) bytes
7 Array:       Rank 1, Number of elements 3, Type VALUETYPE
一個儲存著那麼大list的Dictionary, 其實只有<=3的key value pairs。再看看它的keys是啥。我們用windbg的memory view直接看記憶體中的"瓤"吧：

64位的程式執行環境，clr array的第一個item在0000019A8000D818 + 8(mt ptr size) + 4(length field) + 4 (padding)，所以看標紅的那兩個地址。

1 0:027> !DumpObj /d 0000019a8000cce8
2 Name:        System.String
3 MethodTable: 00007ff96c2bd708
4 EEClass:     00007ff96c299d60
5 Tracked Type: false
6 Size:        30(0x1e) bytes
7 File:        C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.14\System.Private.CoreLib.dll
8 String:      Male
1 0:027> !DumpObj /d 0000019a8000cd08
2 Name:        System.String
3 MethodTable: 00007ff96c2bd708
4 EEClass:     00007ff96c299d60
5 Tracked Type: false
6 Size:        34(0x22) bytes
7 File:        C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.14\System.Private.CoreLib.dll
8 String:      Female

原來Dictionary按性別分類儲存了所有的使用者資訊。

我把這些資訊告訴同事，他第一反應是沒有想到這個執行的結果。按照他的程式碼，他預期是按性別和使用者名稱一起來當key，然後放到Dictionary，這樣查詢起來至少時間複雜度不應這麼高。於是我和那個同事開啟相關的生成key的程式碼：

1 private static string GetUserKey(Gender gender, string userName) => string.Join(userName, gender);
大家發現沒？想當然的用String.Join來連線2個object，卻沒注意其實String.Join的定義是這樣，注意第一個引數可是separator啊:

這麼錯誤的使用，就相當於把user name作為separator，而後面的集合引數其實就傳了一個性別，所以生成的key就總是同一個，本想做成user cache的Dictionary的資料最終退化為兩個很大的lists? 然後多個執行緒一起在這兩個大大的list上以O(n)的時間複雜度查詢東西，cpu就高起來了……

總結

看來大家不能這麼隨隨便便的寫C#程式碼啊，雖然.net sdk會為C#程式設計師提供便利和安全性，但自己也不該想當然的無腦coding哈。最後同事的臉比較紅哈?

相關文章