一次.net code中的placeholder导致的高cpu诊断
背景
最近一位朋友找到我,让我帮看他们的一个aspnet core service无端cpu高的问题。从描述上看,这个service之前没有出现过cpu高的情况,最近也没有改过实际的什么code。很奇怪了,会有什么变化导致cpu上去了呢?
分析
由于比较容易复现 (据说一启动service,cpu就上去了),我便让那位朋友在cpu高的时候直接手动把.net进程dump了一下。于是就开始用windbg分析了
先看一下案发时进程中的线程情况,毕竟它们是让进程动起来的源泉哈。大部分线程都运行到如下类似位置(下面的callstack是虚拟化的,因为为了朋友的隐私,code已经虚拟化):
这里可以看出有约38/2=19个线程运行到Services.CronJob+d__1.MoveNext这个位置。我又问了那位朋友,当时的运行环境是大约20个cpu core。真巧哈,几乎所有cpu core都很有可能跑到了这个地方了。
注:上面如何知道有38/2个线程,而不是38个线程呢?这是因为一般来说,当某个函数正在被调用时,callstack中会显示出两次,如图哈:
看到没,在"current frame"下面显示的上一层调用关系中会也显示这个方法,此时它是callee哈。
那么这个Services.CronJob+d__1.MoveNext是何方神圣呢,名字叫cpu killer更贴切吧???
跑题了,去看看这个方法的代码。注意到这个是compiler generated code,所以就先看看generated code长啥样吧:
先利用上图中透露出来的method的md地址,用!dumpmd看一下这个方法的信息:
反编译看一下:
天啦撸,这好像是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:
正好19个CronJob, 这和刚分析的有19个线程正高速运行吻合。因为心情不错,所以再去看看CronJob的样子吧:
看起来这个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 }
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之前可是让这位朋友背了不少时间的锅哈