一:背景

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 选项,截图如下:

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

完整的 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,截图如下:

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

从卦象上看,当前的 ConsoleApp2 耗费了 3.2s 的CPU时间,总跟踪时间 17.19s

既然说了方法慢那必然是知道方法名的,只不过不知道慢在方法哪里,对应代码就是 mytest1() 方法,在 perfview 面板的 Find 输入框上搜索一下 mytest1 方法就可以找到,截图如下:

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

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

  • First:表示 mytest1 第一次被调用的时间戳
  • Last: 表示 myttest1 最后一次被释放的时间戳
  • when: 这里面是 32 个时间间隔的桶,每个桶的值是资源消化的比重。
  • TimeBucket: 一个桶的时间刻度,比如上图中的 633.8 ms

有了这些基础接下来就可以放大时间轴了,依次点击: First列 -> 右键菜单 -> Set Time Range ,放大后的截图如下:

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

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

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

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

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

从卦中的 Inc 列来看,当前的 mytest1 方法耗费了 5.01s,其内部的 Thread.Sleep() 耗费了 5.005s ,这和测试代码中的 mytest1(5000); 不约而同。

哈哈,这不就找到了问题所在,在你的真实场景下,你可以继续观察底层的调用栈,找到问题所在。

三:总结

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

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