阅读:3940次
评论:0条
更新时间:2011-06-01
Erlang tools lib中包含三个用于性能分析的工具:cprof,eporf和fprof。
cprof 提供函数调用计数,其对系统的性能影响最小
eprof 提供函数运行时间的百分比
fprof 通过将trace存储到文件,提供函数调用计数及运行时间统计信息
这里我们主要介绍fprof,首先其提供的信息最为详细,其次因为将trace存储到文件中,我们可以进行较长运行时间的性能分析
fprof使用
1,fprof:start().
2,
OR
apply在函数开始的时候进行fprof:trace(start, ..),在函数结束的时候执行fprof:trace(stop).上面三个函数都有很多可选参数,默认情况下,使用下面文件保存各阶段信息:fprof.trace, fprof.profile,fprof.analysis
fprof Analysis format
产生了分析报告,最重要的就是如何阅读了。
让我们写一个简单的例子:
进行profiling
analysis结果已经保存到bar.analysis中,此文件可以通过erl_scan and erl_parse, file:consult/1 or io:read/2进行读取分析。
下面我们看看analysis内容:
%% Analysis results:
{ analysis_options,
[{callers, true},
{sort, acc},
{totals, false},
{details, true}]}.
% CNT ACC OWN
[{ totals, 5019, 18.886, 18.884}]. %%%
CNT表示总的函数调用次数,ACC表示Trace起始经历的时间,OWN是Trace中所有函数执行的时间和(不包含调用函数的执行时间),我们这个例子中OWN和ACC比较接近,因为我们这里在启动trace后就立即开始了函数调用,没有进行其他特殊的工作。这里时间的单位为ms。
% CNT ACC OWN
[{ "<0.82.0>", 5019,undefined, 18.884}]. %%
这里表示一个process的开始,在我们这个例子中我们调用fprof:apply/3开始进行trace,因此这个Pid其实就是我们调用apply所在的Process,我们没有Spawn新的Process,所以这里的CNT,OWN和totals相同。ACC的值为undefined,这是因为这个数值对于我们没有什么意义,我们可以通过totals计算出这个数值。
请注意此行结尾处的 “%%”表明一个process的开始
{[{undefined, 0, 18.886, 0.002}],
{ {fprof,apply_start_stop,4}, 0, 18.886, 0.002}, %
[{{bar,test,1}, 1, 18.884, 0.004},
{suspend, 1, 0.000, 0.000}]}.
{[{{fprof,apply_start_stop,4}, 1, 18.884, 0.004}],
{ {bar,test,1}, 1, 18.884, 0.004}, %
[{{lists,map,2}, 1, 14.859, 12.352},
{{lists,splitwith,2}, 1, 3.012, 0.001},
{{lists,seq,2}, 1, 1.009, 0.001}]}.
analysis内容通过空行,间隔成不同的段落。
每个段落中尾部以"%"标记的行为这个段落的标记行。比如上面的内容中{bar,test,1}所在行为一个关键行,此行上面的List为所有调用bar:test/1的函数列表(called list),此行下面的List为bar:test/1调用的函数列表(calling list)。
所有的段落按照ACC递减的顺序排列,同时段落内部的called list和calling list也是按照这个规则排列。
CNT为对应函数累计调用次数,ACC为此函数消耗时间包含其调用的函数,OWN为此函数自身消耗时间不包含called函数。即:
ACC(marked) = OWN(marked) + ACC(calling fun 1) + ACC(calling fun 2) ... ACC(calling fun N)
让我们看看上面的内容中,{bar,test,1}其ACC为:
18.884 = 0.004 + 14.859 + 3.012 + 1.009
同时{bar,test,1}作为我们module的入口其ACC为18.884等于所在process对应的OWN时间。
其实看到这里,我们已经明白,我们这个module中{lists,map,2}最耗时,其占用79% (14.859/18.880)时间,{lists,splitwith,2}占用16% (3.012/18.880) 的时间,而{lists,seq,2} (1.009%18.880) 只占用5%左右。
{[{{bar,test,1}, 1, 14.859, 12.352},
{{lists,map,2}, 1000, 0.000, 1.502}],
{ {lists,map,2}, 1001, 14.859, 13.854}, %
[{{bar,'-test/1-fun-0-',1}, 1000, 1.002, 1.001},
{garbage_collect, 2, 0.002, 0.002},
{suspend, 1, 0.001, 0.000},
{{lists,map,2}, 1000, 0.000, 1.502}]}.
接下来就是依次分析所有的被调用函数,这里说明{lists,map,2}被两个函数调用:
{bar,test,1}和{lists,map,2},也许你有疑问了,在bar:test/1中的确调用了lists:map/2依次,可是我的代码中没有用lists:map/2调用lists:map/2啊,看看stdlib/src/lists.erl代码,你就会明白,lists:map/2是递归方式调用,所以bar module中调用了1次,而我们的List长度是1000,所以lists:map/2函数就被调用了 1 + 1000 = 1001次哦。然后marked行下面就是lists:map/2调用的函数列表。
bar.analysis接下的部分,是对每个函数的分析,如果某个函数为BIF,没有调用任何其他函数,那么其对应的输出内容为:
{[{{lists,reverse,1}, 1, 0.001, 0.001}],
{ {lists,reverse,2}, 1, 0.001, 0.001}, %
[ ]}.
恩,我们lists:reverse/2是BIF,毫无疑问。
在结果中出现了suspend,这是一个pseudo函数,用来说明我们的process此刻处于中止状态,为什么会处于中止状态?我们没有调用erlang:yield/0,也没有调用receive相关的函数,怎么中止了呢?这里是Erlang虚拟机调度的结果,suspend函数对应的ACC时间总是为0,要不要把真正的suspend时间显示出来,这是一个值得争论的问题。
同样的还有garbage_collect函数,其OWN和ACC相同,这里我们把garbage_collect计入了运行时间。
cprof 提供函数调用计数,其对系统的性能影响最小
eprof 提供函数运行时间的百分比
fprof 通过将trace存储到文件,提供函数调用计数及运行时间统计信息
这里我们主要介绍fprof,首先其提供的信息最为详细,其次因为将trace存储到文件中,我们可以进行较长运行时间的性能分析
fprof使用
1,fprof:start().
2,
fprof:apply fprof:profile fprof:analyse
OR
fprof:trace(start) fprof:trace(stop) fprof:profile fprof:analyse
apply在函数开始的时候进行fprof:trace(start, ..),在函数结束的时候执行fprof:trace(stop).上面三个函数都有很多可选参数,默认情况下,使用下面文件保存各阶段信息:fprof.trace, fprof.profile,fprof.analysis
fprof Analysis format
产生了分析报告,最重要的就是如何阅读了。
让我们写一个简单的例子:
-module(bar). -export([test/1]). test(N) when is_integer(N) -> L = lists:seq(1, N), L2 = lists:map(fun(E) -> E * 2 end, L), _L3 = lists:splitwith(fun(E) -> E rem 2 =:= 0 end, L2), ok.
进行profiling
> c(bar). > fprof:apply(bar, test, [1000]). > fprof:profile(). > fprof:analyse({dest, "bar.analysis"}). Processing data... Creating output... Done! ok
analysis结果已经保存到bar.analysis中,此文件可以通过erl_scan and erl_parse, file:consult/1 or io:read/2进行读取分析。
下面我们看看analysis内容:
引用
%% Analysis results:
{ analysis_options,
[{callers, true},
{sort, acc},
{totals, false},
{details, true}]}.
% CNT ACC OWN
[{ totals, 5019, 18.886, 18.884}]. %%%
CNT表示总的函数调用次数,ACC表示Trace起始经历的时间,OWN是Trace中所有函数执行的时间和(不包含调用函数的执行时间),我们这个例子中OWN和ACC比较接近,因为我们这里在启动trace后就立即开始了函数调用,没有进行其他特殊的工作。这里时间的单位为ms。
引用
% CNT ACC OWN
[{ "<0.82.0>", 5019,undefined, 18.884}]. %%
这里表示一个process的开始,在我们这个例子中我们调用fprof:apply/3开始进行trace,因此这个Pid其实就是我们调用apply所在的Process,我们没有Spawn新的Process,所以这里的CNT,OWN和totals相同。ACC的值为undefined,这是因为这个数值对于我们没有什么意义,我们可以通过totals计算出这个数值。
请注意此行结尾处的 “%%”表明一个process的开始
引用
{[{undefined, 0, 18.886, 0.002}],
{ {fprof,apply_start_stop,4}, 0, 18.886, 0.002}, %
[{{bar,test,1}, 1, 18.884, 0.004},
{suspend, 1, 0.000, 0.000}]}.
{[{{fprof,apply_start_stop,4}, 1, 18.884, 0.004}],
{ {bar,test,1}, 1, 18.884, 0.004}, %
[{{lists,map,2}, 1, 14.859, 12.352},
{{lists,splitwith,2}, 1, 3.012, 0.001},
{{lists,seq,2}, 1, 1.009, 0.001}]}.
analysis内容通过空行,间隔成不同的段落。
每个段落中尾部以"%"标记的行为这个段落的标记行。比如上面的内容中{bar,test,1}所在行为一个关键行,此行上面的List为所有调用bar:test/1的函数列表(called list),此行下面的List为bar:test/1调用的函数列表(calling list)。
所有的段落按照ACC递减的顺序排列,同时段落内部的called list和calling list也是按照这个规则排列。
CNT为对应函数累计调用次数,ACC为此函数消耗时间包含其调用的函数,OWN为此函数自身消耗时间不包含called函数。即:
ACC(marked) = OWN(marked) + ACC(calling fun 1) + ACC(calling fun 2) ... ACC(calling fun N)
让我们看看上面的内容中,{bar,test,1}其ACC为:
18.884 = 0.004 + 14.859 + 3.012 + 1.009
同时{bar,test,1}作为我们module的入口其ACC为18.884等于所在process对应的OWN时间。
其实看到这里,我们已经明白,我们这个module中{lists,map,2}最耗时,其占用79% (14.859/18.880)时间,{lists,splitwith,2}占用16% (3.012/18.880) 的时间,而{lists,seq,2} (1.009%18.880) 只占用5%左右。
引用
{[{{bar,test,1}, 1, 14.859, 12.352},
{{lists,map,2}, 1000, 0.000, 1.502}],
{ {lists,map,2}, 1001, 14.859, 13.854}, %
[{{bar,'-test/1-fun-0-',1}, 1000, 1.002, 1.001},
{garbage_collect, 2, 0.002, 0.002},
{suspend, 1, 0.001, 0.000},
{{lists,map,2}, 1000, 0.000, 1.502}]}.
接下来就是依次分析所有的被调用函数,这里说明{lists,map,2}被两个函数调用:
{bar,test,1}和{lists,map,2},也许你有疑问了,在bar:test/1中的确调用了lists:map/2依次,可是我的代码中没有用lists:map/2调用lists:map/2啊,看看stdlib/src/lists.erl代码,你就会明白,lists:map/2是递归方式调用,所以bar module中调用了1次,而我们的List长度是1000,所以lists:map/2函数就被调用了 1 + 1000 = 1001次哦。然后marked行下面就是lists:map/2调用的函数列表。
bar.analysis接下的部分,是对每个函数的分析,如果某个函数为BIF,没有调用任何其他函数,那么其对应的输出内容为:
引用
{[{{lists,reverse,1}, 1, 0.001, 0.001}],
{ {lists,reverse,2}, 1, 0.001, 0.001}, %
[ ]}.
恩,我们lists:reverse/2是BIF,毫无疑问。
在结果中出现了suspend,这是一个pseudo函数,用来说明我们的process此刻处于中止状态,为什么会处于中止状态?我们没有调用erlang:yield/0,也没有调用receive相关的函数,怎么中止了呢?这里是Erlang虚拟机调度的结果,suspend函数对应的ACC时间总是为0,要不要把真正的suspend时间显示出来,这是一个值得争论的问题。
同样的还有garbage_collect函数,其OWN和ACC相同,这里我们把garbage_collect计入了运行时间。
评论 共 0 条 请登录后发表评论