翼度科技»论坛 编程开发 .net 查看内容

PerfView专题 (第十五篇): 如何洞察 C# 中的慢速方法

3

主题

3

帖子

9

积分

新手上路

Rank: 1

积分
9
一:背景

1. 讲故事

在 dump 分析旅程中,经常会遇到很多朋友反馈一类问题,比如:

  • 方法平时都执行的特别快,但有时候会特别慢,怎么排查?
  • 我的方法第一次执行特别慢,能看到慢在哪里吗?
相信有朋友肯定说,加些日志不就好了,大方向肯定是没问题的,但加日志的颗粒度会比较粗而且侵入性也比较大,比如说这个方法不是你的,或者说这个方法是操作系统的,一般情况下对他们无法干涉,那如何洞察在你作用域之外的方法性能呢?作为 CLR团队首推的 PerfView 性能分析工具,必须要 KO 这些问题,接下来我们就简单聊一聊。
二:PerfView 洞察慢速方法

1. 测试代码

为了方便讲述,我们模拟这样的一种情况,一个方法第一次执行会特别慢(5s),后面执行都很快(3s),测试代码如下:
  1.     internal class Program
  2.     {
  3.         static void Main(string[] args)
  4.         {
  5.             mytest1(5000);
  6.             for (int i = 0; i < int.MaxValue; i++) { };
  7.             
  8.             mytest1(3000);
  9.             Console.ReadLine();
  10.         }
  11.         static void mytest1(int senconds)
  12.         {
  13.             Console.WriteLine("mytest1 start...");
  14.             Thread.Sleep(senconds);
  15.             Console.WriteLine("mytest1 end...");
  16.         }
  17.     }
复制代码
那如何用 perfview 来洞察呢?玩过 perfview 的朋友都知道它是带时间轴的,我们可以对上面的慢速方法 mytest1 适当的放大,一直找到那一次的慢速调用,为了能够记录到 Thread 使用 CPU 的情况,需要开启 ThreadTime 选项,截图如下:

完整的 Command 命令如下:
  1. PerfView.exe  "/DataFile:PerfViewData.etl" /BufferSizeMB:256 /StackCompression /CircularMB:500 /KernelEvents:ThreadTime /ClrEvents:GC,Binder,Security,AppDomainResourceManagement,Contention,Exception,Threading,JITSymbols,Type,GCHeapSurvivalAndMovement,GCHeapAndTypeNames,Stack,ThreadTransfer,Codesymbols,Compilation /NoGui /NoNGenRundown /Merge:True /Zip:True collect
复制代码
有了这些基础之后,先用 perfview 开启收集,然后执行应用程序,程序执行完成之后停止 perfview 收集,稍等片刻之后就有一个生成好的 zip 文件。
2. perfview 洞察

这里选择 Thread Time Stacks 视图,在弹框中选择我们的应用程序 ConsoleApp2,截图如下:

从卦象上看,当前的 ConsoleApp2 耗费了 3.2s 的CPU时间,总跟踪时间 17.19s。
既然说了方法慢那必然是知道方法名的,只不过不知道慢在方法哪里,对应代码就是 mytest1() 方法,在 perfview 面板的 Find 输入框上搜索一下 mytest1 方法就可以找到,截图如下:

那这一行怎么解读呢? 我稍微说一下吧。

  • First:表示 mytest1  第一次被调用的时间戳
  • Last:  表示 myttest1 最后一次被释放的时间戳
  • when: 这里面是 32 个时间间隔的桶,每个桶的值是资源消化的比重。
  • TimeBucket: 一个桶的时间刻度,比如上图中的 633.8 ms
有了这些基础接下来就可以放大时间轴了,依次点击: First列 -> 右键菜单 -> Set Time Range ,放大后的截图如下:

从 When 列的 999999999999992________599999999 可以看到,当前这 11s 的挂钟时间内大概有两次 mytest1 调用,其实的 9 表示这个桶内消耗的单个资源的90%,我们要调查的就是其中 999999999999992 段,双击 When 列的 999999999999992 ,右键选择 Set Time Range 即可,截图如下:

放大到这里就差不多了,我们已经进入了第一次 mytest1 方法调用的作用域内,接下来依次点击 右键 -> Goto -> Goto Item in Callee 来观察下这个方法的下层到底都是写什么。

从卦中的 Inc 列来看,当前的 mytest1 方法耗费了 5.01s,其内部的 Thread.Sleep() 耗费了 5.005s ,这和测试代码中的 mytest1(5000); 不约而同。
哈哈,这不就找到了问题所在,在你的真实场景下,你可以继续观察底层的调用栈,找到问题所在。
三:总结

相信这篇能够给一些在慢速方法查找上有困惑的朋友找到一些灵感,还是那句话,CLR团队首推的 PerfView 在运行期监控方面是王者般的存在,与 WinDbg 优势互补。

来源:https://www.cnblogs.com/huangxincheng/archive/2023/07/21/17571032.html
免责声明:由于采集信息均来自互联网,如果侵犯了您的权益,请联系我们【E-Mail:cb@itdo.tech】 我们会及时删除侵权内容,谢谢合作!

本帖子中包含更多资源

您需要 登录 才可以下载或查看,没有账号?立即注册

x

举报 回复 使用道具