使用PerfView监测.NET程序性能（转发）
原文：
使用PerfView监测.NET程序性能（一）：Event Trace for Windows
前言：
在日常项目开发中，我们时不时会遇到程序【占用了很高CPU的】情况，可能是程序里某些未经优化的代码或者Bug，或者是程序运行压力太大。无论是什么原因，我们总希望能看到到底是【哪个方法占用了如此高的CPU】。
微软为我们提供了很多【性能诊断工具】来达到此目的。例如在Visual Studio 2017中的性能查探器，Windows SDK中的Windows Performance Recorder (WPR) 和Windows Performance Analyzer (WPA)，XPerf，当然，还有这篇博客介绍的PerfView。
但在介绍PerfView的使用前，有一个在Windows系统及应用程序性能这个主题上扮演重要角色的技术必须被提及，这就是Event Trace for Windows (ETW)。事实上，上边提及到的性能分析工具都是基于ETW来实现的。
什么是ETW
在微软上的解释中，ETW是自Windows 2000 推出的"内核级"的事件日志实现。通过记录系统及应用程序中各类事件日志，可以监测和分析系统及程序的运行细节，例如CPU使用率，.NET程序的GC状况等。ETW的日志里，包含着非常多的有用信息，例如进程/线程信息,上下文切换，各种I/O信息，程序执行时的时间节点，甚至是函数调用等信息。通过对日志数据进行实时采集,或者分析事件日志记录文件(.etl文件)，就能轻易地检测和分析系统和程序的运行状况和性能瓶颈，而更为难得的是，ETW的性能还非常的高，据说可以达到 每秒写入20W条记录，而仅占用5%的CPU。
Windows除了在系统内核及系统组件自带了大量事件日志，ETW还为开发者提供编程接口（在 System.Diagnostics.Eventing 命名空间下），允许开发人员在项目中实现自己的事件跟踪，或者像使用log4net一样，将系统自定义的日志记录到ETW里面。这点不在这里展开了，有兴趣的可以参考Artech的文章：如何利用ETW（Event Tracing for Windows）记录日志
但话说回来，我曾经也尝试过在项目了使用ETW，但感觉在一般项目开发中，还是使用Log4net和nlog这些日志框架较为合适，毕竟一般来说业务系统的日志是给人看的，而ETW的日志数据是二进制形式保存的，更偏向于给日志消费者用的，肉眼在看起来并不那么方便，而且log4net/nlog更合适系统的业务场景的日志使用。ETW还是作为系统性能分析手段比较适合。关于这个可以参考这里
ETW VS 性能监视器
或者有人会问，Windows里已经提供了强大的性能监视器(Perfmon.exe)，和资源监视器(顺便说下，资源监视器也是基于ETW实现的。参考这里)，为什么还需要ETW和其他基于它的工具？例如使用性能监视器，添加各种性能计数器，也可以将系统在运行时的方方面面的性能数据呈现出来，那ETW及PerfView还有什么存在意义？
一个非常明显的理由就是，ETW的日志存储着非常详细的程序运行数据。利用PerfView等工具，你可以看到具体一个进程加载信息，线程的执行信息，函数的调用树，和执行时间，执行堆栈，CPU执行时间等等信息，而性能监视器只能提供各个性能指标的数据，但并不能具体地展示哪个程序引起了具体的性能问题。通常我们可以配合性能监视器和ETW相关工具的使用，可以全方位的了解系统的性能状况，并且可以直观地看到具体是那些函数导致了性能问题，达到知其然同时知其所以然的效果。
第二个理由便是，ETW日志的速度比性能监视器要快，可以在生产环境中自由地获取运行数据而不影响服务器运行。但性能监视器也是即开即用，所以我觉得这点对我来说意义不太大。
.ETL文件
.etl文件是ETW的日志文件扩。当使用PerfView等工具捕获系统日志后，便会生成此类文件。使用PerfView等ETW的分析工具，可以对文件内的日志进行各种统计与分析操作。而如果只想单纯地看日志内容，可以使用Microsoft Message Analyzer打开文件。
参考资料：
ETW (Event Tracing For Windows) – what it is and useful tools
Inside Event Tracing for Windows
Logging ETW events in C#: System.Diagnostics.Tracing.EventSource
Application Analysis with Event Tracing for Windows (ETW)
如何利用ETW（Event Tracing for Windows）记录日志
原文：
使用PerfView监测.NET程序性能（二）：Perfview的使用
在上一篇博客中，我们了解了对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程序性能（三）：分组
在上一篇博客中，我们通过Perfview帮助文件中自带的代码来简单使用了Perfview，了解了基本操作。现在来看看Perfview中的分组操作（Grouping）。分组功能都旨将记录到的各种函数调用堆栈以指定的规则进行分组，帮助你组织和找到更关心的数据。
在实际使用中，PerfView通常会收集到非常多的函数调用栈数据，包括我们关心的程序的函数调用信息，及一大堆我们不关心的其他函数调用信息，例如windows系统的底层函数。这么多有用没用的条目都列出在列表视图上，令人眼花缭乱。如何将我们不需要的数据分组归纳呢？Perfview提供分组功能。
分组功能使用类似于正则的匹配功能，将函数全名（一个函数的全名包含了程序集，命名空间，类名和函数名，例如"mscorlib.n!System.DateTime.get_Now()"）进行匹配，并替换成自定义的分组名称。例如，可以对所有在Debug目录下的程序集的函数单独显示，而其他函数则分组成“OTHER”，这样，我们就可以只看见我们程序里的函数调用。其实这就是默认的[Just My App]分组规则的作用：
通配符
那么，分组功能如何使用呢？
在使用分组之前，先看看PerfView定义的几个"通配符":
* :匹配任意数量的字符
%：匹配任意数量的数字和英文字母和点号(".")，等于.NET正则中的 [\w\d.]*
^ ：匹配开头
|：“或”操作
{}：代表一个分组，等于.NET正则里的小括号
分组规则
PerfView中有两种分组操作，分别是 PAT->GROUP 和 PAT=>GROUP。在这里“PAT”代表需要匹配的模式(Pattern)，“GROUP”代表你自定义的组名。 而这两种分组方式区别就在于中间的“->”和"=>"，前者表示忽略入口函数，后者则会将入口函数显示在分组中。有时我们希望知道一个分组里的函数最初是由哪个函数开始调用的，这时候就可以使用后者了。除此之外，两种分组方式没有其他不同。
我们看看具体的分组规则的使用：
1. PAT->GROUP形式
如上述，PAT->GROUP形式是简单地将一个函数的全名称中包含"PAT"字眼的条目都分到“GROUP”组中，例如，在不分组的情况下，我们收集到的函数调用数据列表是这样的：
里面有我们Tutorial.exe的函数，例如，tutorial!Program.SpinForASecond()和tutorial!Program.RecSpin()，同时也有很多.NET的内部函数，例如 mscorlib.n!System.get_Now()和mscorlib.n!System.TimeSpan.get_TotalSeconds()，等等。假设我们只关心tutorial.exe自身的函数，而不希望被.NET内部函数所干扰，我们则可以设置一个分组规则“mscorlib->.NET”，这样，所有包含“mscorlib”字眼的方法全名称的条目都会被分组进“.NET”组，效果如下：
是不是清爽了很多？这样的分组能使我们快速地过滤掉mscorlib有关的函数，只剩下tutorial自己的函数（和一些其他函数，当然如果你愿意，也可以将其他的函数"分组"掉）
2. {*}=>$1
该形式的规则意思是： 花括号里匹配到的条目会被分组，而组名正是是花括号里的匹配到的内容，“$1”是一个占位符，对应的是花括号“{}”里的内容。假设有两个函数：tutorial!Program.SpinForASecond()和tutorial!Program.RecSpin()， 而应用的规则是“{tutorial!}->My APP $1”，则分组后，这两个函数被分进一组，并且组名为“My App tutorial!”
Perfview还支持同时设置多个规则，例如设置规则为“{tutorial!}->My APP $1;{mscorlib.ni!}->Internal $1”，这里有两个规则，一个是蓝色部分，另一个是红色部分，中间用分号(;)隔开。如果函数全名中有"tutorial!"的就分进名为“My APP tutorial!”组，而有“mscorlib.ni!”字眼的就分进“Internal mscorlib.ni!”组。
3.PAT=>GROUP
最后来看看入口点规则分组(Entry Point Grouping)。前边提到过，“PAT=>GROUP”与“PAT->GROUP”的不同在于，后者会忽略掉该组的入口函数，意味着你很难知道某个分组里的函数是从哪个函数执行进去的，而前者则会包含入口点函数信息。我们通过图例来看看实际效果。
下图中，使用“mscorlib->System Functions”规则来对mscorlib的函数进行分组，组名为“System Functions”,但除非你展开这个分组的明细，查找每个函数调用树，否则你不知道是什么函数调用了这组函数。
而现在使用“mscorlib=>System Functions”，看看有什么不同：
System Functions组明确指示了该组的函数的入口点是“mscorlib.ni!System.DateTime.get_Now()”函数，即DateTime.Now导致了这些函数的执行。
以上便是PerfView的分组功能。但其实这只是分组功能中的一部分。通过规则的搭配可以有更强大的效果。而最全面的说明其实是在PerfView自带的F1帮助文件。这里只作一个抛砖引玉的简要说明。因此如果需要了解更全面的分组技巧，可以去帮助文件里搜索相关主题。
使用PerfView监测.NET程序性能（四）：折叠，过滤和时间范围选择
使用PerfView监测.NET程序性能（四）：折叠，过滤和时间范围选择
在上一篇文章中，我们使用了Perfview的分组功能。分组功能旨在对某些函数按照某个格式进行分组，以减少视图中的各种无关函数的数量。但仅有分组还不够，有时我们想将一些函数调用信息按某些条件过滤掉，例如将采用小于1%的函数调用信息去掉，或者将函数名中包含某个字眼的函数信息去掉，甚至只显示某个时间段调用的函数。这就需要用到PerfView提供的过滤（Filtering）功能了。PerfVIew提供了3种过滤功能：折叠（Folding），匹配过滤，和时间范围选择（Set Time Range）
折叠（Folding）
PerfView在界面上提供了两种Folding功能：“Fold%” 和 “FoldPats”.
“Fold%”意思是，将采样少于该百分比的函数调用信息条目“折叠”掉，并将其采样时间累加到这些函数的调用者。这里“折叠”的意思其实应该说是隐藏掉。
“FoldPats”：与“Fold%”类似，会将符合条件的函数调用记录“折叠”（或“隐藏”）掉，而它的采样时间将会算在它的直接调用者头上。而与“Fold%”不同的是它的条件不是“Inc%”的值，而是函数名称中符合给定的匹配模式。同时，这个功能也支持指定多个模式，不同模式之间用";"(分号)隔开。
过滤（Filtering）
折叠功能能实现过滤的效果，只是被过滤的项的采样时间会被累加到调用者身上。有时我们其实只想简单地去掉一些我们不关心的函数，同时也不需要保留它们的采样时间。这时，我们可以采用“简单粗暴”的过滤方式。
"IncPats":可以设置一个或多个模式(多个时用分号";"隔开)，只有当函数名称匹配一个或者多个给定的模式时，这个函数会被显示在列表上，不匹配的会被从列表上删除。
"ExcPats":可以设置一个或多个模式(多个时用分号";"隔开)，只有当函数名称匹配一个或者多个给定的模式时，这个函数会从列表上删除。
因此，"IncPats"和"ExcPats"是一对反义词，前者是“匹配则保留”，后者是“匹配则删除”
这里说的模式，和上一篇文章中说的“通配符”是一样的，或者可以参考帮助文件，或者在界面上对于的ToolTip提示中也有说明。
例如，以下图例的设置中，在”IncPats“框中设置”Process% ConsoleApp7 (4108)“，起到只显示我的程序”ConsoleApp7“的函数调用堆栈
时间范围选择
有时我们希望能只显示某一段时间内的函数调用情况，Perfview也提供时间范围选择的功能，在界面上提供了"Start"和"End"两个输入框。但要注意的是，这里的时间范围不是以绝对的时间值(比如：2018/12/27 23:15:02),而是从开始收集时经历的毫秒数。假设你某个时间开始收集，5秒后停止，你想只看第3秒到第4秒的数据，就可以在Start中设置"3000"，在End中设置"4000"，Perfview只显示大于或等于3000毫秒小于或等于4000毫秒的函数调用数据。
不仅只提供文本框输入值的功能，Perfview还提供一个更便利的时间范围选择功能，如下图：
在”When“一列中，显示了一串文本值，一共32个，由数字字母和一些符号组成。这串由符号组成的”字符串“代表了该函数在收集过程中被采样数（可以理解成出现的频繁度），具体来说，Pferview将每一个函数的”Inclusive“时间分成32"段"，每一段的不同符号代表了该函数的”Inclusive“时间的比例值：（以下内容是从帮助文档中COPY的，稍作翻译）
”_“ 代表在该段"时间段"内没有采样（means no samples occurred in that bucket. ）
”.“代表在该段"时间段"内有0%到0.1%的Inclusive时间 （means that interval consumed between 0% and .1%. ）
”o” 代表在该段"时间段"内有1% 到 1%的Inclusive时间（means that interval consumed between .1% and 1%. ）
”0” 代表在该段"时间段"内有1% 到10%的Inclusive时间（means that interval consumed between 1% and 10%. ）
”1” 代表在该段"时间段"内有10% 到 20%的Inclusive时间（means that interval consumed between 10% and 20% ）
...
”9 代表在该段"时间段"内有90% 到100%的Inclusive时间（means that interval consumed between 90% and 100% ）
”A” 代表在该段"时间段"内有100% 到110%的Inclusive时间（means that interval consumed between 100% and 110% ）
...
”Z” 代表在该段"时间段"内有350% 到360%的Inclusive时间（means that interval consumed between 350% and 360% ）
”*” 代表在该段"时间段"内有超过360%的Inclusive时间（means that interval consumed over 360%）
”a” 代表在该段"时间段"内有0% 到-10%的Inclusive时间（means that interval consumed between 0% and -10% ）
”b” 代表在该段"时间段"内有-10% 到-20%的Inclusive时间（means that interval consumed between -10% and -20% ）
...
”z” 代表在该段"时间段"内有-250% 到-260%的Inclusive时间（means that interval consumed between -250% and -260% ）
”*” 代表在该段"时间段"内有超过 -260 %的Inclusive时间（means that interval consumed over -260 %） 这个我不是很清楚，不是代表360%吗？？
另外，为什么会有些值是超过100%呢？ 按文档的解释，应该是有多个可消耗的资源单元，例如200%代表某个函数在2个CPU上都有100%的INCLUSIVE时间，但我不确定是否理解正确。
那怎么在“When”栏中进行时间范围选择呢？
可以双击“When”栏的文本值，然后用鼠标光标选择一段或整段文本（就像平时选择一段文字进行ctrl+c ctrl+v一样），然后右击并在右键菜单中选择“Set Time Range”，如图：
这样，该时间范围的值就会被设置到"Start"和“End”中，并进行过滤。
以上便是Perfiveiw中的几种数据过滤功能，还是那句话，这里涉及只介绍了基本的功能，更多更具体的功能说明，可以查看帮助文档。
