erlang进程性能分析方法

有时erlang进程cpu异常高，可以通过下面的工具函数(fprof)来分析一下各函数占用cpu时间的情况
Now = fun() ->
    {A, B, _} = erlang:now(),
    A * 1000000 + B
end.

Fprof_start = fun(Procs) ->
    fprof:trace([start, {file, "/tmp/fprof.trace"}, {procs, Procs}])
end.

Fprof_stop = fun() ->
    ok = fprof:trace(stop),
    ok = fprof:profile({file, "/tmp/fprof.trace"}),
    Analyse = lists:concat(["/tmp/fprof-", Now(), ".analysis"]),
    % {sort, own}
    ok = fprof:analyse([{dest, Analyse}, {details, true}, {totals, true}, {sort, own}]),
    io:format(("fprof result:~s\n"), [Analyse]),
    ok
end.

%% Fprof_start  Fprof_stop 是用来开启和关闭对erlang系统的监控，并生成分板结果文件/tmp/fprof-xxxx.analysis

调用方式：
PID = pid(x,x,x). %% 需要监控的erlang进程号，可以通过etop来查出哪个进程cpu异常高，使用方法常见注1
Fprof_start(PID).
%% 停一段时间，具体看情况，可能是20秒吧
Fprof_stop().
%% 然后就可以看分析结果文件了，如何分析见注2

如果不需要分析得这么细可以用 eprof
eprof:start().
eprof:profile([pid(x,x,x)]).
eprof:stop_profiling().
eprof:analyze().
%% 停一小段时间
eprof:stop().


另外推荐一本erlang之父写的经典名书《Erlang程序设计》，前阵子看到淘宝上有卖，还送erlang资料，随手买了一本收藏：
http://item.taobao.com/item.htm?id=26286504297
注1：
spawn(fun() -> etop:start([{output, text}, {interval, 5}, {lines, 20}, {sort, memory}]) end).


sortIdentifies what information to sort by.
Value: runtime | reductions | memory | msg_q
Default: runtime (reductions if tracing=off)

注2：转自涛老大的博客http://erlangdisplay.iteye.com/blog/318975
Erlang tools lib中包含三个用于性能分析的工具：cprof，eporf和fprof。
cprof 提供函数调用计数，其对系统的性能影响最小
eprof 提供函数运行时间的百分比
fprof 通过将trace存储到文件，提供函数调用计数及运行时间统计信息

这里我们主要介绍fprof，首先其提供的信息最为详细，其次因为将trace存储到文件中，我们可以进行较长运行时间的性能分析

fprof使用

1,fprof:start().
2,
Erlang代码  
1. fprof:apply 
2. fprof:profile 
3. fprof:analyse 
     
OR  
Erlang代码  
1. fprof:trace(start) 
2. fprof:trace(stop) 
3. fprof:profile 
4. fprof:analyse 

apply在函数开始的时候进行fprof:trace(start, ..),在函数结束的时候执行fprof:trace(stop).上面三个函数都有很多可选参数，默认情况下，使用下面文件保存各阶段信息:fprof.trace， fprof.profile，fprof.analysis
  
fprof Analysis format
产生了分析报告，最重要的就是如何阅读了。

让我们写一个简单的例子：
Erlang代码  
1. -module(bar). 
2. -export([test/1]). 
3.  
4. test(N) when is_integer(N) ->     
5.     L = lists:seq(1, N), 
6.     L2 = lists:map(fun(E) -> E * 2 end, L), 
7.     _L3 = lists:splitwith(fun(E) -> E rem 2 =:= 0 end, L2), 
8.     ok. 


进行profiling

Erlang代码  
1. > c(bar). 
2. > fprof:apply(bar, test, [1000]). 
3. > fprof:profile(). 
4. > fprof:analyse({dest, "bar.analysis"}). 
5. Processing data... 
6. Creating output... 
7. Done! 
8. 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计入了运行时间。