在上一篇博客中,我们了解了对Windows及应用程序进行性能分析的基础:Event Trace for Windows (ETW)。现在来看看基于ETW的性能分析工具——Perfview.exe
Perfview简介
Perfview是一个开源的CPU和内存性能分析工具,也包括一些针对.NET的分析功能,例如GC分析,JIT分析,甚至ASP.NET中的请求统计等等。Perfview是一个Windows应用程序,但也能对在Linux系统上采集的数据进行分析(参考)。Perfview免安装,而且只是一个14M的.exe文件,非常容易部署到需要进行性能分析的机器上,例如生产环境的服务器。而且在性能数据收集的过程中不需要重启应用程序或者服务器,而且收集的性能数据日志(.etl文件)可以被拷贝到其他Windows机器上,再进行分析工作,对业务的影响非常少。
Perfview已迁移到GitHub上,可以在上面下载Perfview.exe,clone库或者查看相关资料。
Perfview GitHub:https://github.com/Microsoft/perfview
Perfview视频教程:https://channel9.msdn.com/Series/PerfView-Tutorial
Vance Morrison关于Perfview的博客:https://blogs.msdn.microsoft.com/vancem/tag/perfview/
Perfview使用
在简单介绍Perfview后,我们来使用Perfview进行一个小小的性能分析,来熟悉一下Perfivew的基本操作。
这个实验使用的代码,就是Vance Morrison在视频教程中用到的Console程序。代码可以在Perfivew自带的帮助文件中找到。
using System; // using System.Collections.Generic; class Program { public static int aStatic = 0; // Spin is a simple compute bound program that lasts for 5 seconds // It is a useful test program for CPU profilers. static int Main(string[] args) { int numSec = 5; if (args.Length == 1) numSec = int.Parse(args[0]); Console.WriteLine("Spinning for {0} seconds", numSec); RecSpin(numSec); return 0; } // Spin for 'timeSec' seconds. We do only 1 second in this // method, doing the rest in the helper. static void RecSpin(int timeSec) { if (timeSec <= 0) return; --timeSec; SpinForASecond(); RecSpinHelper(timeSec); } // RecSpinHelper is a clone of RecSpin. It is repeated // to simulate mutual recursion (more interesting example) static void RecSpinHelper(int timeSec) { if (timeSec <= 0) return; --timeSec; SpinForASecond(); RecSpin(timeSec); } // SpingForASecond repeatedly calls DateTime.Now until for // 1 second. It also does some work of its own in this // methods so we get some exclusive time to look at. static void SpinForASecond() { DateTime start = DateTime.Now; for (; ; ) { if ((DateTime.Now - start).TotalSeconds > 1) break; // Do some work in this routine as well. for (int i = 0; i < 10; i++) aStatic += i; } } }
以上代码很简单,SpinForASecond()在一秒内不断调用DateTIme.Now,而RecSpin()和RecSpinHelper()则不断地相互调用对方。这里使用循环的目的是,循环执行是一种典型的CPU密集型操作,而RecSpin()和RecSpinHelper()则是为了丰富程序的函数调用栈。
步骤一:收集程序运行数据,生成由ETW数据组成的.etl文件。
Perfview提供两种收集数据的方式,Run和Collect。“Run”是直接指定需要启动的应用程序的名称,以便启动该程序。“Collect”则是直接启动Perfview并开始收集。但不要以为"Run"方式只收集指定程序的数据。事实上无论哪种方式,Perfview都会收集系统范围内全部数据,并且收集完成后,需要选择某一个进程以进行分析。
我们以“Run”方式来收集以上代码生成的Tutorial.exe程序。
在弹出的对话框中,填入需要启动Tutorial.exe的全文件名,以及填入生成etl文件的文件名(这里是PerfViewData.etl),并点击“Run Command”:
Perfview收集和处理数据的时间比较长。在处理过程中,Perfview的右下角会闪动,并且可以查看运行日志,了解到当前Perfview在执行什么工作。
步骤二:选择需要分析的进程
在收集完毕后,在左边选择“PerfViewData.etl.zip”,并在展开的选择项中双击选择“CPU Stacks”,此时,会弹出进程选择对话框,选择需要进行CPU分析的进程。这里选择我们运行的Tutorial.exe进程。
步骤三:查看执行栈视图
在双击选择了“Tutorial.exe”的进程后,进入到程序详细的执行栈的视图中。这里记录着Tutorial.exe的函数调用树,以及函数的执行时间。
在该视图中,你可以看到Tutorial.exe的函数调用情况,包括函数调用树(Call-Tree),某个函数的调用者(Calls)和被该函数调用的函数(Callees),另外,在视图右侧,是函数的执行时间,其中,“Exc”是指 Exclusive,是指函数自己(不包含该函数里执行的子函数)的执行时间,而“Inc”是指Inclusive,指该函数及该函数中执行的子函数的总的执行时间。
另外,这个执行时间是怎么认定的呢? 答案是CPU采样。Perfview对CPU进行采样,默认每个CPU采样是1毫秒(在Prefview的高级设置中可以设置到0.125毫秒~1毫秒),每次采样中可以得到当前CPU正则执行什么代码。例如DateTime_getNow()有3250采样,则可以说明在整个程序运行中,DateTime_getNow()占用了3250毫秒的CPU时间,占整个运行时间的66.2%。通过比较各个函数的执行时间,我们就可以知道程序中哪个函数占用比较多的CPU时间。
以上便是Prefview的基本的使用步骤。Prefview提供了非常多并强大的功能,例如分组(Grouping),折叠(Folding),时间范围选择,这些在后续教程里再聊。而更强大的是,F1帮助手册里,有着非常详细的使用说明和术语解析,而且界面上几乎每个功能都有说明的ToolTip和说明的超链接如果对某个功能用法不是很清楚,可以方便地找到说明,真是业界良心。
参考资料
How many samples are enough when using a sample based profiler in a performance Investigation
The TraceEvent Library Programmers Guide
系列目录
使用PerfView监测.NET程序性能(一):Event Trace for Windows