4

一次.net code中的placeholder导致的高cpu诊断 - dotnet程序故障诊断

 1 year ago
source link: https://www.cnblogs.com/dotnet-diagnostic/p/17227866.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.

一次.net code中的placeholder导致的高cpu诊断

最近一位朋友找到我,让我帮看他们的一个aspnet core service无端cpu高的问题。从描述上看,这个service之前没有出现过cpu高的情况,最近也没有改过实际的什么code。很奇怪了,会有什么变化导致cpu上去了呢?

由于比较容易复现 (据说一启动service,cpu就上去了),我便让那位朋友在cpu高的时候直接手动把.net进程dump了一下。于是就开始用windbg分析了Expression_34@2x.png

先看一下案发时进程中的线程情况,毕竟它们是让进程动起来的源泉哈。大部分线程都运行到如下类似位置(下面的callstack是虚拟化的,因为为了朋友的隐私,code已经虚拟化):

3115652-20230317184021347-1783549164.png

这里可以看出有约38/2=19个线程运行到Services.CronJob+d__1.MoveNext这个位置。我又问了那位朋友,当时的运行环境是大约20个cpu core。真巧哈,几乎所有cpu core都很有可能跑到了这个地方了。

注:上面如何知道有38/2个线程,而不是38个线程呢?这是因为一般来说,当某个函数正在被调用时,callstack中会显示出两次,如图哈:

3115652-20230317184209244-1835755038.png

看到没,在"current frame"下面显示的上一层调用关系中会也显示这个方法,此时它是callee哈。

那么这个Services.CronJob+d__1.MoveNext是何方神圣呢,名字叫cpu killer更贴切吧?😂

跑题了,去看看这个方法的代码。注意到这个是compiler generated code,所以就先看看generated code长啥样吧:

先利用上图中透露出来的method的md地址,用!dumpmd看一下这个方法的信息:

3115652-20230317184308044-1737822992.png

反编译看一下:

3115652-20230317184320420-117745692.png

天啦撸,这好像是async state machine code,没事凑合看吧😓仔细观察那些标红的位置后,我发现这里面有些蹊跷啊。如果schedules不是null的话,有两种情况,这两种情况最终都会到label_10的地方,在那里,cpu可以得到休息;但如果schedules是null的话,会不会一直以同步的方式高速循环在while里?我在所有threads的stack上找寻,找不到有类型为List<string>的instance被stack引用着,所以很有可能是这个原因了。

另外,从Services.CronJob+d__1.MoveNext这个名字看,这个closure应该是在user code class CronJob中生成的,我们去看看。用!dumpheap:

3115652-20230317184407254-1894769643.png

正好19个CronJob, 这和刚分析的有19个线程正高速运行吻合。因为心情不错,所以再去看看CronJob的样子吧:

3115652-20230318102557586-400861544.png

 看起来这个CronJob是个long running的IHostedService,在循环中有的flow没有让thread休息导致cpu上来了。

把这个结果告诉那位朋友后,朋友很快找到了对应的代码,简化后的代码如下:
 1     protected override async Task ExecuteAsync(CancellationToken stoppingToken)
 2     {
 3         await InitializeJobAsync();
 4 ​
 5         while (!stoppingToken.IsCancellationRequested)
 6         {
 7             List<string>? schedules = PreferenceService.GetSchedules(Region);
 8             if (schedules == null)
 9             {
10 ​
11             }
12             else
13             {
14                 await ProcessJobAsync(schedules);
15                 await Task.Delay(TimeSpan.FromSeconds(10), stoppingToken);
16             }
17         }
18     }
很奇怪为什么要在第8行写个空的if block在那里。那位朋友用git history发现,一个月前他的一个同事在这位朋友的代码里加了empty if block,而加之前的简化代码大约是这样的:
 1    protected override async Task ExecuteAsync(CancellationToken stoppingToken)
 2     {
 3         await InitializeJobAsync();
 4 ​
 5         while (!stoppingToken.IsCancellationRequested)
 6         {
 7             List<string>? schedules = PreferenceService.GetSchedules(Region);
 8 ​
 9             await ProcessJobAsync(schedules);
10             await Task.Delay(TimeSpan.FromSeconds(10), stoppingToken);
11         }
12     }

于是原因便是,当时加了这个empty if block后,由于PreferenceService.GetSchedules总不是null,所以没有进入问题flow;后来配置变了,返回了null,进入问题flow,问题flow又错过了await Task.Delay(),所以悲剧发生。。

据这位朋友说,他的同事后来说:"这个empty if block当时是个placeholder。现在不用了,可以删了" ……。。唉,删是好删,不过在发现root cause之前可是让这位朋友背了不少时间的锅哈

无论在自己的代码还是别人的代码里加placeholder,一定要谨慎添加这种empty block。加对了顶多稍影响性能和可读性,加不对就是给别人或自己或项目组添堵了。并且这种bug只在特定条件下被触发,更难根据代码的版本历史排除出故障,而适合用底层诊断技术分析。

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK