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

  • 一次.net code中的placeholder导致的高cpu诊断已关闭评论
  • 172 次浏览
  • A+
所属分类:.NET技术
摘要

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


背景

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

分析

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

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

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

 

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

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

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

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

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

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

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

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

反编译看一下:

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

天啦撸,这好像是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:

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

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

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

 

 看起来这个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只在特定条件下被触发,更难根据代码的版本历史排除出故障,而适合用底层诊断技术分析。