一:背景
1. 讲故事
在 dump 分析旅程中,经常会遇到很多朋友反馈一类问题,比如:
- 方法平时都执行的特别快,但有时候会特别慢,怎么排查?
- 我的方法第一次执行特别慢,能看到慢在哪里吗?
相信有朋友肯定说,加些日志不就好了,大方向肯定是没问题的,但加日志的颗粒度会比较粗而且侵入性也比较大,比如说这个方法不是你的,或者说这个方法是操作系统的,一般情况下对他们无法干涉,那如何洞察在你作用域之外的方法性能呢?作为 CLR团队首推的 PerfView 性能分析工具,必须要 KO 这些问题,接下来我们就简单聊一聊。
二:PerfView 洞察慢速方法
1. 测试代码
为了方便讲述,我们模拟这样的一种情况,一个方法第一次执行会特别慢(5s),后面执行都很快(3s),测试代码如下:
internal class Program
{
static void Main(string[] args)
{
mytest1(5000);
for (int i = 0; i < int.MaxValue; i++) { };
mytest1(3000);
Console.ReadLine();
}
static void mytest1(int senconds)
{
Console.WriteLine("mytest1 start...");
Thread.Sleep(senconds);
Console.WriteLine("mytest1 end...");
}
}
那如何用 perfview 来洞察呢?玩过 perfview 的朋友都知道它是带时间轴的,我们可以对上面的慢速方法 mytest1
适当的放大,一直找到那一次的慢速调用,为了能够记录到 Thread 使用 CPU 的情况,需要开启 ThreadTime
选项,截图如下:
完整的 Command 命令如下:
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 优势互补。