PerfView专题 (第十五篇)：如何洞察 C# 中的慢速方法-Toy模板网

这篇具有很好参考价值的文章主要介绍了PerfView专题 (第十五篇)：如何洞察 C# 中的慢速方法。希望对大家有所帮助。如果存在错误或未考虑完全的地方，请大家不吝赐教，您也可以点击"举报违法"按钮提交疑问。

一：背景

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# 中的慢速方法

完整的 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# 中的慢速方法

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

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

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

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

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

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

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

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

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