使用Flamegraph分析.NET启动时间

438次阅读
没有评论

共计 2400 个字符,预计需要花费 6 分钟才能阅读完成。

.NET运行时在启动过程中在哪里花费时间?

代码样例

在本练习中,我们仅关注程序启动期间的.NET运行时,我们确保正在运行最少数量的用户代码,因此使用以下 “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是一个非常强大的程序,但不是最用户友好的工具,因此我整理了逐步指南:

  • 下载并运行最新版本的 PerfView.exe
  • 单击 Run a commandAlt-R,然后单击 collect data while the command is running
  • 确保输入以下值:
    • Command
    • Current Dir
  • 如果尚未选中,勾选 Cpu Samples
  • Max Collect Sec 设置为15秒(因为我们的 HelloWorld 应用程序永远不会退出,因此我们需要确保PerfView在某个时刻停止收集数据)
  • 确保已选择 .NET Symbol Collection
  • 点击 Run Command
使用Flamegraph分析.NET启动时间
PerfView – Collection Options – annotated

如果随后查看该日志,则可以看到该日志正在收集数据,获取符号并最终将所有内容写到.zip文件中。完成该过程后,您应该在主UI的左侧窗格中看到新创建的文件,在这种情况下,该文件称为PerfViewData.etl.zip

数据处理

拥有 .etl.zip 文件后,双击该文件,您将看到带有所有可用数据的树状视图。现在,选择 CPU Stacks ,将显示如下视图:

使用Flamegraph分析.NET启动时间
PerfView – Unresolved Symbols

注意列表中有很多“?”的字符,这意味着PerfView无法解决方法名称,因为它尚未解析运行时dll的必要符号。让我们修复:

  • 打开 CPU Stacks
  • 在列表中,选择 HelloWorld 进程(PerfView在整个计算机范围内收集数据)
  • GroupPats 下拉列表中,选择 [no grouping]
  • 可选,将 Symbol Path 从默认值更改为其他值
  • By name 标签中,按 Ctrl + A 以选择所有行
  • 右键单击并选择 Lookup Symbols(或仅单击“ Alt + S”)

现在,CPU Stacks 视图应如下所示:

使用Flamegraph分析.NET启动时间
PerfView – Resolved Symbols

最后,我们可以获得所需的数据:

  • 选择 Flame Graph 标签
  • GroupPats 更改为以下值之一以获得更好的火焰图:
  • Fold%更改为更高的数字,可能是3%,以消除一些悠长的线条(更高的条形,但将丢失一些细节信息)
使用Flamegraph分析.NET启动时间
PerfView – Flamegraph

现在,在这一点上,我建议用PerfView数据导出为可装入一个格式 https://speedscope.app 这个网站上可以生成更直观的火焰图。为此,单击 File->Save View As,然后在 Save as type 框中选择 Speed Scope Format 。之后即可上传到 speedscope.app 进行分析。

.NET运行时启动的分析

最后,我们可以回答我们原来的问题:

.NET运行时在启动过程中在哪里花费时间?

这是来自 Flamegraph 的数据,摘要为文本,并链接了.NET Core Runtime 源代码中的相应功能:

  • 整个应用-100% -233.28ms
  • 一切,除了 helloworld!wmain – 21%
  • helloworld!wmain – 79% – 184.57ms
    • hostpolicy!create_hostpolicy_context -30% -70.92ms >
    • hostpolicy!create_coreclr-22% -50.51ms >
      • coreclr!CorHost2::Start-9% -20.98ms >
      • coreclr!CorHost2::CreateAppDomain-10% -23.52ms >
    • hostpolicy!runapp -20% -46.20ms >
      • 最终调用到 Assembly::ExecuteMainMethod >
        • coreclr!RunMain-9.9% -23.12ms >
        • coreclr!RunStartupHooks-8.1% -19.00ms >
    • hostfxr!resolve_frameworks_for_app-3.4% -7.89ms >

因此,运行时花费时间的主要位置是:

  • 花了总时间的30%来启动运行时,这是通过 host policy 控制的,这主要发生在 hostpolicy!create_hostpolicy_context 总时间的30%中
  • 22%的时间花费在运行时本身及其创建的初始(唯一)AppDomain的初始化上,这可以在 CorHost2::Start(native)CorHost2::CreateAppDomain(managed) 中看到。
  • 从上面开始,在我们的 Hello World 代码示例中使用了20%的 JITting 并执行了该 Main 方法 Assembly::ExecuteMainMethod

为了确认最后一点,我们可以返回PerfView并查看它产生的“ JIT统计摘要”。从主菜单的 Advanced Group -> JIT Stats 下,我们看到 JITing 花费了23.1 ms 9.1%的CPU总时间:

使用Flamegraph分析.NET启动时间
PerfView – JIT Stats for HelloWorld

翻译自 https://mattwarren.org/2020/03/03/Analysing-.NET-Runtime-Startup-with-Flamegraphs/

正文完
 1
太阳
版权声明:本站原创文章,由 太阳 2021-01-06发表,共计2400字。
转载说明:除特殊说明外本站文章皆由CC-4.0协议发布,转载请注明出处。
评论(没有评论)