公司某资料子系统定期cpu过高的诊断 - dotnet程序故障诊断
source link: https://www.cnblogs.com/dotnet-diagnostic/p/17181455.html
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
公司某资料子系统定期cpu过高的诊断
公司里的某负责保存用户文档的子系统有时会忽然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
在告知同事这个原因前，我还有意无意地查了一下那个保存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
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);
这么错误的使用，就相当于把user name作为separator，而后面的集合参数其实就传了一个性别，所以生成的key就总是同一个，本想做成user cache的Dictionary的数据最终退化为两个很大的lists? 然后多个线程一起在这两个大大的list上以O(n)的时间复杂度查找东西，cpu就高起来了……
Recommend
About Joyk
Aggregate valuable and interesting links.
Joyk means Joy of geeK