使用Xperf和Vtune小小的分析一下C#中抛出异常的开销
C#非我所长,但是这不妨我通过一些底层工具来分析C#的异常处理的性能。
在这里我无意讨论异常好或者坏,也无意讨论什么时候该用异常或者不该用。也不深入讨论C#和Windows的异常处理机制。我只是给出试验数据,告诉你异常到底是慢还是快。
两个实验都是用同样一次编译出来的exe文件。两个实验都是分别使用命令行参数来控制是否抛出异常,然后收集数据来比较。至于不使用try catch和使用try catch但是不抛出异常的情况,我懒得写了。当然我的实验并无意证明处理异常的开销和自己写的FuncToKillTime的开销有什么样的关系,我只是要说,处理异常很慢。
实验代码如下,就是一个简单的console程序,编译环境是WinXP SP3+ VS2008 SP1,默认的release配置。
代码
{
class Program
{
static Int64 BigNumber;
static void FuncToKillTime()
{
for (int i = 0; i < 1000; ++i)
{
BigNumber += i * i;
}
}
static void Main(string[] args)
{
BigNumber = 0;
for (int i = 0; i < 100000; ++i)
{
try
{
FuncToKillTime();
if (args[0] == "throw")
{
throw new Exception("An Exception");
}
}
catch (Exception err){ }
}
System.Console.Write(BigNumber);
}
}
}
实验1是在我的心爱的Win7的上网本上做的,它的Atom CPU有超线程,所以从操作系统角度来看,这是一个双核的CPU.
实验使用Xperf工具观察抛出异常与否的区别。Xperf是Vista以后微软推出的性能调试工具,运行时对系统的影响相当的小.
图一非常直白的显示了当抛出异常的时候,程序的执行时间大大的增加了。
这张图分为上下两个部分,上部分是CPU的使用率,两条曲线是因为双核,下部分是程序的生存周期,上下两部分的X轴都是时间。可以看出,在抛出异常(用蓝色的Throw标示的)时,执行时间大约在12秒,而没有抛出异常时(蓝色的No Throw标示的)执行时间大约只有2秒。
图二是使用Xperf来具体观察哪些模块(Module)在消耗CPU资源。比如说左边Throw的情况(程序从5秒执行到17秒),我随便的选择了8.6~14.5秒这段时间的来观察CPU使用率.
那么我们可以看到,VtuneExampleCSharp.exe分别占用了49.97%(Throw的情况)和44.13%(No Throw的情况)的CPU资源,其他的都大部分被Idle进程占用了,这是因为双核的原因,单线程程序,不可以达到100%
进一步在Xperf中展开VtuneExampleCSharp.exe,于是就可以观察具体每个模块所占用的CPU资源,他们的加起来就是整个程序所占用的CPU资源了。
这里就是我要展示的结果,各个模块在是否抛出异常时所占用整个程序资源的比例是大大的不同。
1。比如说左边No Throw的情况,一个叫Unknown的module占用了绝大部分的CPU资源。这个叫Unknown的module基本上就等同于main函数的那些代码,包括FuncToKillTime和Throw的操作,但是不包括Throw以后,系统处理这个异常的操作。至于叫Unknown的原因是因为Xperf暂时还无法解析managed code的symbols文件,如果实验是用C++做的话,是可以看到具体的模块名,甚至里面的函数的情况。
2。值得关注的两个module是ntkrnlpa.exe和mscorwks.dll, 在No throw的情况下,他们俩的开销基本上为0。而在Throw的情况下,他们两个开销之和占了整个VtuneExampleCSharp.exe开销的绝大部分。而这两个模块其实就是throw以后性能大大下降的根源所在。
(注1:我无意解释ntkrnlpa.exe和mscorwks.dll是什么,以及为什么一个exe可以作为另外一个exe的模块出现,这非我所长)
(注2:我选取得时间段并不相等,所以程序开销的绝对总量不一样,所以你无法说8.97%的unknown比43.73%的unknown模块执行快)
实验1的结论就是,如果没有Throw的话,几乎所有的CPU都在跑main函数,而出现了Throw的话,绝大部分CPU资源都被其他系统模块占用去处理异常了。
实验2回到了我老掉牙的WinXP SP3的开发机上,这台机器上装有性能调试的神器Vtune.
实验2使用可执行文件和实验1是一样的,也是测试了抛出与不抛出异常的情况。
首先贴上来的是原始数据并简单的解释一下每一列的意义。
Module: 在这个process进程空间下有哪些不同的模块被执行过。VtuneExampleCSharp.exe.jit就是我在开篇写的代码编译后属于的模块
Process:属于哪一个Process,在这里我只关注了一个进程,所以都是一样的。
Instructions Retired samples,Instructions Retired%和Instructions Retired events这三列的意思就是这个模块一共执行了多少条CPU指令。虽然执行指令的条数并不能等同于运行的时间,但是依然可以用来反映程序的开销。
首先是没有throw的情况,可以看到最大的开销依然是VtuneExampleCSharp.exe.jit, 和实验1的结论一样。
(mfeapfk.sys是我的McAfee在作怪,可以忽略掉)
在有throw的情况下.
1.VtuneExampleCSharp.exe.jit总共执行的指令数并没有太大的变化,参考Instructions Retried samples和Instructions Retried Events这两列,这两列的值是绝的值,直接反映了这个模块所执行过的指令数。可以发现这些值还略小于没有throw的情况,当然这并不是说有throw的情况这些代码还执行得少,这只是Vtune采样的误差罢了。
2.虽然VtuneExampleCSharp.exe.jit的总执行指令数没有太大的变化,可是占整个进程所执行的指令数的比例却大大的下降了,原因还是因为有其他模块在处理异常。
再附上根据数据得到的更加直观的图,下图表示的是各个模块所执行指令占整个程序运行所执行指令的百分比。
再次提醒,Throw和No Throw的情况下所执行的指令数的绝对值是不一样的,在实验1里,可以看到运行时间是不同的,这里就可以看到具体多少执行被执行是不同的。
下图是Throw和No Throw情况下,主要模块所执行的指令数绝对值的比较。可以看到ntoskrnl.exe和mscorwks.dll有巨大的增加,而我自己写的实验代码的模块基本上没有变化。至于ntoskrnl.exe和mscorwks.dll是什么,为什么增加这么多,我这里无意去详细解释,这也不是我所长。
OK,分析就到这里了,其实我打得字都有点画蛇添足了,这几张图很直观了。
-------------------------------------------------------------------我是无聊的分割线------------------------------------------------------------------------
后记与废话:做实验和得出结论没花我多久时间,但是处理数据,图片和写blog倒是花了很长的的时间。