526互联

使用火焰图分析.NET的 start-up 期间花费的时间

发布时间 2023-07-01 10:26:25作者: wxlevel
本文将告诉你从“dotnet run”到“hello world”，如何使用 PerfView 来分析 .NET 运行时在启动期间所花费的时间。

代码示例

在这个示例中，我故意只关注.NET运行时在程序启动(start-up)过程中的操作，以确保运行的用户代码最少，因此只有以下的“Hello World”：
using System;
namespace HelloWorld {
    class Program {
        static void Main(string[]args) {
            Console.WriteLine("Hello World!");
            Console.WriteLine("Press <ENTER> to exit");
            Console.ReadLine();
        }
    }
}
添加Console.ReadLine()是为了确保在 PerfView 仍在收集数据时进程不会退出。

数据收集

PerfView 是一个非常强大的程序，但不是最易于使用的工具，因此我写了一个逐步指南：
  1. 下载并运行最新版本的'PerfView.exe'
  2. 点击“Run a command(运行命令)”或（Alt-R）并选择“collect data while the command is running(在命令运行时收集数据)”
  3. 确保已输入以下值：
    1. “Command”（命令）
    2. “Current Dir”（当前目录）
  4. 如果尚未选中“Cpu Samples（CPU采样）”，那请选中它，确保这选项是打勾的
  5. 将“Max Collect Sec（最长收集时间）”设置为15秒（因为我们的“HelloWorld”应用程序永远不会退出，我们需要确保PerfView在某个时刻停止收集数据）
  6. 确保选择了“.NET Symbol Collection（.NET符号收集）”
  7. 点击“Run Command（运行命令）”
然后，如果您检查日志，您会看到它正在收集数据，获取符号，然后最终将所有内容写入一个.zip文件。完成后，您应该在主界面的左侧窗格中看到新创建的文件，本例中称为“PerfViewData.etl.zip”。

数据处理

一旦你有了“.etl.zip”文件，双击它，您将看到一个树视图，显示所有可用的数据。现在，选择“CPU Stacks”，您将看到以下视图：
注意列表中有很多“?”字符，这意味着PerfView无法解析运行时dll所需的方法名称。让我们修复这个问题：
  1. 打开“CPU Stacks”
  2. 在列表中，选择“HelloWorld”进程（PerfView在整个机器上收集数据）
  3. 在“GroupPats”下拉菜单中，选择“[no grouping]”
  4. 可选项，将“Symbol Path”从默认值更改为其他值
  5. 在“By name”选项卡中，按下“Ctrl+A”选择所有行
  6. 右键单击并选择“Lookup Symbols”（或按下“Alt+S”）
 
现在，“CPU Stacks”视图应该类似于以下内容：
最后，我们可以获得我们想要的数据：
  1. 选择“Flame Graph”选项卡
  2. 将“GroupPats”更改为以下选项之一，以获得更好的火焰图：
    1. [group module entries] {%}!=>module $1
    2. [group class entries] {%!*}.%(=>class $1;{%!*}::=>class $1
  3. 将“Fold%”更改为更高的数字，例如3%，以去除那些细小的条（过高的数字会导致丢失信息）
 
现在，我实际上建议将PerfView数据导出为可以加载到 https://speedscope.app/ 中的格式，因为它可以提供更好的体验。要做到这一点，请单击“文件”->“另存为视图”，然后在“另存为类型”框中选择“Speed Scope Format”。完成后，你可以在speedscope.app上“浏览”该文件。
 
注意：如果你以前从了解到过“火焰图”，我强烈建议阅读 Julia Evans 关于 perf & flamegraphs 的精彩解释：
分析性能数据的 3 种方法

分析.NET Runtime的Startup

最后，我们可以回答最初的问题：
.NET Runtime在启动期间花费时间较多的地方是哪里？
以下是火焰图中汇总为文本的数据，其中包含“.NET Core Runtime”源代码中相应函数的链接：
  1. 整个应用程序 - 100％ - 233.28毫秒
  2. 除了helloworld!wmain之外的所有内容 - 21％
  3. helloworld!wmain - 79％ - 184.57毫秒
    1. hostpolicy!create_hostpolicy_context - 30％ - 70.92毫秒（create_hostpolicy_context函数）
    2. hostpolicy!create_coreclr - 22％ - 50.51毫秒（create_coreclr 函数
      1. coreclr!CorHost2::Start - 9％ - 20.98毫秒（CorHost2::Start 函数）
      2. coreclr!CorHost2::CreateAppDomain - 10％ - 23.52毫秒（CorHost2::CreateAppDomain 函数）
    3. hostpolicy!runapp - 20％ - 46.20毫秒（runapp 函数），最终调用Assembly::ExecuteMainMethod（Assembly::ExecuteMainMethod 函数）
      1. coreclr!RunMain - 9.9％ - 23.12毫秒（RunMain 函数）
      2. coreclr!RunStartupHooks - 8.1％ - 19.00毫秒（RunStartupHooks 函数）
    4. hostfxr!resolve_frameworks_for_app - 3.4％ - 7.89毫秒（fx_resolver_t::resolve_frameworks_for_app 函数）
 
因此，运行时花费时间最多的地方是：
  1. 30％的总时间用于启动runtime，由“host policy”控制，其中大部分发生在hostpolicy!create_hostpolicy_context中（总时间的30％）
  2. 22％的时间用于初始化runtime本身以及它创建的初始（也是唯一的）AppDomain，这可以在CorHost2::Start（native 本地）和CorHost2::CreateAppDomain（managed 托管）中看到。有关这方面的更多信息，请参阅CLR在执行一行代码之前所做的68件事情
  3. 20％用于 JIT编译和执行 “Hello World”代码示例中的Main方法，这是从上面的Assembly::ExecuteMainMethod中开始的。
为了确认最后一点，我们可以返回到 PerfView 并查看它生成的“JIT Stats Summary（JIT统计摘要）”。从主菜单的“Advanced Group”->“JIT Stats”下，我们可以看到23.1毫秒或总CPU时间的9.1％花在了JIT编译上。