fprof
fprof
模块
fprof
模块摘要
一种时间分析工具，它使用跟踪文件来减少对运行时性能的影响。
描述
此模块用于分析程序，以了解如何使用执行时间。跟踪到文件用于最小化运行时性能的影响。
大fprof模块使用跟踪来收集分析数据，因此不需要对要分析的任何模块进行特殊编译。当它开始追踪时，fprof将删除节点中所有以前的跟踪，并在分析目标进程上设置必要的跟踪标志，以及对所有加载模块和要加载的所有模块中的所有函数设置本地调用跟踪。fprof当节点停止跟踪时，删除节点中的所有跟踪。
fprof两种自己的时间即一个函数用于自己执行的时间，以及累积时间也就是包括所谓的函数。所有呈现的时间都使用跟踪时间戳收集。fprof如果主机操作系统支持CPU时间戳，则尝试收集它。因此，时间可能是时钟时间和操作系统调度将随机打击所有被调用的功能，想必公平的方式。
但是，如果分析时间很短，而且主机操作系统不支持高分辨率CPU时间测量，那么一些OS调度可能会显示为功能执行时间太长，而这些功能几乎什么也不做。一个函数在大约100倍的正常执行时间内组成一个元组的例子已经被看到，当跟踪被重复时，执行时间就变得正常了。
分析主要分三个步骤进行：
1跟踪；如上一段所述，归档。跟踪包含函数调用、函数返回、进程调度、其他与%28派生相关的进程等%29事件和垃圾收集的条目。所有跟踪条目都有时间戳。2分析；读取跟踪文件，模拟执行调用堆栈，并从模拟调用堆栈和跟踪时间戳中计算原始配置文件数据。配置文件数据存储在fprof服务器状态。在此步骤中，跟踪数据可以以文本格式转储到文件或控制台。3分析；原始配置文件数据被排序、过滤并以文本格式转储到文件或控制台。文本格式既可供人阅读，也可使用标准Erlang解析工具进行解析。
由于fprof使用跟踪文件，运行时性能下降被最小化，但仍然远远忽视，特别是对于自己使用文件系统的程序而言。放置跟踪文件的位置也很重要，例如在Solaris /tmp上通常是一个不错的选择，因为它本质上是一个RAM磁盘，而任何NFS（网络）挂载的磁盘都不是好主意。
fprof还可以跳过文件步骤，并跟踪在运行时执行分析的跟踪程序进程。
出口
start() -> {ok, Pid} | {error, {already_started, Pid}}
类型
启动fprof服务器。
注意，它很少需要显式启动，因为它是由需要运行服务器的函数自动启动的。
stop() -> ok
同stop(normal)...
stop(Reason) -> ok
类型
停止fprof服务器。
提供的Reason成为服务器进程的退出原因。默认任何Reason除kill向服务器发送请求并等待其清理、回复和退出。如果Reason是kill服务器被直接杀死了。
如果fprof服务器没有运行，此函数将立即以相同的返回值返回。
注
当fprof服务器停止，收集的原始配置文件数据丢失。
apply(Func, Args) -> term()
类型
同apply(Func, Args, [])...
apply(Module, Function, Args) -> term()
类型
同apply{Module, Function}, Args, [])...
apply(Func, Args, OptionList) -> term()
类型
打电话erlang:apply(Func, Args)被trace([start, ...])和trace(stop)...
进行了一些努力，以使跟踪从不必要的跟踪消息中保持干净；跟踪将从生成的进程中启动并停止，而erlang:apply/2调用在当前进程中进行，仅由receive和send语句指向跟踪启动进程。当不再需要时，跟踪启动进程就会退出。
这TraceStartOption是允许的任何选项trace/1。这些选项[start, {procs, [self() | PidList]} | OptList]被赋予trace/1，其中OptList是OptionList有continue，start而{procs, _}选项中删除。
大continue选项抑制对trace(stop)让来电者在适当的时间停止追踪。
apply(Module, Function, Args, OptionList) -> term()
类型
同apply{Module, Function}, Args, OptionList)。
OptionList是否允许使用选项列表？apply/3。
trace(start, Filename) -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
同trace([start, {file, Filename}])。
trace(verbose, Filename) -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
同trace([start, verbose, {file, Filename}])...
trace(OptionName, OptionValue) -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
同trace([{OptionName, OptionValue}])。
trace(verbose) -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
同trace([start, verbose])。
trace(OptionName) -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
同trace([OptionName])。
trace{OptionName, OptionValue}) -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
同trace([{OptionName, OptionValue}])。
trace([Option]) -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
开始或停止跟踪。
PidSpec和Tracer在调用erlang:trace(PidSpec, true, [{tracer, Tracer} | Flags])，和Filename用于调用dbg:trace_port(file, Filename)请参阅有关文件。
选项说明：
stop停止正在运行的fprof跟踪并清除节点中的所有跟踪。无论是选项stop还是start必须指定，但不能同时指定。start清除节点中的所有跟踪并开始新的fprof跟踪。无论是选项start还是stop必须指定，但不能同时指定。verbose** | ** {verbose, bool()}这些选项verbose或{verbose, true}添加一些fprof不需要的跟踪标志，但对于一般调试目的而言可能很有趣。该选项仅适用于该start选项。cpu_time** | ** {cpu_time, bool()}选项cpu_time或{cpu_time, true>使跟踪中的时间戳为CPU时间而不是挂钟时间，这是默认值。该选项仅适用于该start选项。{procs, PidSpec}**| ** {procs, [PidSpec]}指定应追踪哪些进程。如果没有给出这个选项，则调用过程被追踪。跟踪过程产生的所有过程也被追踪。该选项仅适用于该start选项。file** | ** {file, Filename}指定跟踪的文件名。如果file给出选项，或者没有给出这些选项，"fprof.trace"则使用该文件。此选项仅适用于该start选项，但不适用于该{tracer, Tracer}选项。{tracer, Tracer}指定应完成对进程或端口的跟踪，而不是跟踪到文件。此选项仅适用于该start选项，但不适用于该{file, Filename}选项。
profile() -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
同profile([])。
profile(OptionName, OptionValue) -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
同profile([{OptionName, OptionValue}])。
profile(OptionName) -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
同profile([OptionName])...
profile{OptionName, OptionValue}) -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
同profile([{OptionName, OptionValue}])...
profile([Option]) -> ok | {ok, Tracer} | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
将跟踪编译到由fprof服务器。
Dumpfile用于调用file:open/2，和Filename用于调用dbg:trace_port(file, Filename)请参阅有关文件。
选项说明：
file** | ** {file, Filename}读取文件Filename并创建由fprof服务器存储在RAM中的原始配置文件数据。如果file给出选项，或者没有给出这些选项，"fprof.trace"则读取文件。ok如果成功读取了整个跟踪的返回值，则调用将返回。start或stop选项不允许使用此选项。dump** | ** {dump, Dump}指定跟踪文本转储的目标。如果未提供此选项，则不生成转储，如果它是dump目标将是调用者的组长，否则目标Dump是I / O设备的pid或文件名。最后，如果文件名是[]-"fprof.dump"被用来代替。该选项不允许使用该stop选项。append导致跟踪文本转储追加到目标文件。该选项仅适用于该{dump, Dumpfile}选项。start开始在运行时分析跟踪数据的跟踪过程。{ok, Tracer}如果成功，该调用将立即返回返回值。此选项与被许可stop，file或{file, Filename}选项。stop停止运行时配置跟踪数据的跟踪器进程。ok如果成功，返回值将是值。此选项与被许可start，file或{file, Filename}选项。
analyse() -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
同analyse([])。
analyse(OptionName, OptionValue) -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
同analyse([{OptionName, OptionValue}])...
analyse(OptionName) -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
同analyse([OptionName])...
analyse{OptionName, OptionValue}) -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
同analyse([{OptionName, OptionValue}])...
analyse([Option]) -> ok | {error, Reason} | {'EXIT', ServerPid, Reason}
类型
中的原始配置文件数据进行分析。fprof服务器。如果在没有原始配置文件数据的情况下调用，{error, no_profile}会被归还。
Destfile用于调用file:open/2请参阅有关文件。
选项说明：
dest** | ** {dest, Dest}指定分析的目的地。如果没有给出这个选项或者它是dest，则目标将是调用者的组长，否则目标Dest是pid()I / O设备或文件名。最后，如果文件名是[]- "fprof.analysis"用来代替。append使分析附加到目标文件。该选项仅适用于该{dest, Destfile}选项。{cols, Cols}指定分析文本中的列数。如果未指定此选项，则列数设置为80. callers** | ** {callers, true}在分析中打印呼叫者和被叫信息。这是默认设置。{callers, false}** | **no_callers禁止在分析中打印呼叫者和被叫信息。{sort, SortSpec}指定是否应根据ACC列（默认值）或OWN列对分析进行排序。见Analysis Format下文。totals** | **在分析中{totals, true}包含一个包含所有呼叫的呼叫统计数据的部分，而不管流程如何。{totals, false}压缩分析中的总计部分，这是默认值。details** | ** {details, true}打印分析中每个过程的呼叫统计。这是默认设置。{details, false}** | ** no_details从分析中抑制每个过程的呼叫统计。
分析格式
本节介绍分析命令的输出格式。看analyse/0。
该格式可解析与标准Erlang的分析工具erl_scan和erl_parse，file:consult/1或io:read/2。解析格式在这里没有解释 - 感兴趣的人应该很容易尝试一下。请注意，一些标志analyse/1将影响格式。
下面的示例是在Solaris 8上的OTP/R8上运行的，这个示例中的所有OTP内部都非常依赖于版本。
作为例子，我们将使用以下函数，您可以从手册页文件（3）中识别出稍微修改过的基准函数：
-module(foo).
-export([create_file_slow/2]).
create_file_slow(Name, N) when integer(N), N >= 0 ->
{ok, FD} =
file:open(Name, [raw, write, delayed_write, binary]),
if N > 256 ->
ok = file:write(FD,
lists:map(fun (X) -> <<X:32/unsigned>> end,
lists:seq(0, 255))),
ok = create_file_slow(FD, 256, N
true ->
ok = create_file_slow(FD, 0, N)
end,
ok = file:close(FD).
create_file_slow(FD, M, M) ->
ok;
create_file_slow(FD, M, N) ->
ok = file:write(FD, <<M:32/unsigned>>),
create_file_slow(FD, M+1, N).
让我们看看运行后的打印输出：
1> fprof:apply(foo, create_file_slow, [junk, 1024]).
2> fprof:profile().
3> fprof:analyse().
打印输出以：
%% Analysis results:
{ analysis_options,
[{callers, true},
{sort, acc},
{totals, false},
{details, true}]}.
% CNT ACC OWN
[{ totals, 9627, 1691.119, 1659.074}]. %%%
CNT列显示跟踪中找到的函数调用的总数。在ACC列中，是跟踪从第一个时间戳到最后的总时间。在自己的列中是跟踪中找到的函数中的执行时间之和，不包括被调用的函数。在这种情况下，它非常接近ACC时间，因为仿真器实际上除了执行我们的测试程序之外没有什么可做的。
打印输出中的所有时间值都以毫秒为单位。
打印稿继续写道：
% CNT ACC OWN
[{ "<0.28.0>", 9627,undefined, 1659.074}]. %%
这是一个进程的打印头。打印输出只包含这一个进程，因为我们已经完成了。fprof:apply/3它只跟踪当前进程。因此，CNT和自己的列完全匹配以上总数。ACC列没有定义，因为将过程中所有调用的ACC时间相加是没有意义的--您可以从上面的总计中得到类似ACC值，乘以调用堆栈的平均深度，或者其他什么。
直到下一个进程头的所有段落都只涉及该进程中的函数调用。
现在我们来看一些更有趣的事情：
{[{undefined, 0, 1691.076, 0.030}],
{ {fprof,apply_start_stop,4}, 0, 1691.076, 0.030}, %
[{{foo,create_file_slow,2}, 1, 1691.046, 0.103},
{suspend, 1, 0.000, 0.000}]}.
{[{{fprof,apply_start_stop,4}, 1, 1691.046, 0.103}],
{ {foo,create_file_slow,2}, 1, 1691.046, 0.103}, %
[{{file,close,1}, 1, 1398.873, 0.019},
{{foo,create_file_slow,3}, 1, 249.678, 0.029},
{{file,open,2}, 1, 20.778, 0.055},
{{lists,map,2}, 1, 16.590, 0.043},
{{lists,seq,2}, 1, 4.708, 0.017},
{{file,write,2}, 1, 0.316, 0.021}]}.
打印输出包含每个被调用函数的一个段落。标有'％' 的功能是该段涉及的功能foo:create_file_slow/2。标记函数的上方是调用函数 - 那些调用了标记的函数，下面是被标记的函数调用的函数。
段落按默认情况按ACC列中标记函数的递减顺序排序。一个段落中的调用列表和被叫列表也是按ACC列的递减顺序排列的默认情况。
列是：cnt--函数被调用的次数，ACC--在函数中花费的时间(包括被调用的函数)和属于的时间--在函数中花费的时间(不包括被调用的函数)。
调用函数的行包含标记函数的统计信息，约束条件是只有当从行函数调用到标记函数时出现这种情况。
的行。标记函数只包含所有的和。呼叫一排排。
被调用函数的行包含行的函数的统计信息，约束条件是只有在从标记到行函数的调用时才被考虑。
所以，我们看到foo:create_file_slow/2很少用时间来执行它。它花了大部分时间在file:close/1.功能foo:create_file_slow/3写3/4的文件内容是第二大时间盗贼。
我们也看到，调用file:write/2它写入了1/4的文件内容本身花费的时间很少。需要花时间的是建立数据（lists:seq/2和lists:map/2）。
已调用的函数“未定义” fprof:apply_start_stop/4是未知函数，因为该调用未记录在跟踪中。只记录了执行返回fprof:apply_start_stop/4到调用堆栈中上面的某个其他函数，或者该进程从那里退出。
让我们继续打印出来，以便找到：
{[{{foo,create_file_slow,2}, 1, 249.678, 0.029},
{{foo,create_file_slow,3}, 768, 0.000, 23.294}],
{ {foo,create_file_slow,3}, 769, 249.678, 23.323}, %
[{{file,write,2}, 768, 220.314, 14.539},
{suspend, 57, 6.041, 0.000},
{{foo,create_file_slow,3}, 768, 0.000, 23.294}]}.
如果与代码进行比较，您会看到那里foo:create_file_slow/3只有来自foo:create_file_slow/2自己的代码，并且仅被调用file:write/2，请记录调用的次数file:write/2。但在这里我们看到这suspend被称为几次。这是一个伪函数，其指示在执行，所述过程被暂停foo:create_file_slow/3，并且由于不存在receive或erlang:yield/0在代码，它必须是二郎调度悬浮液，或跟踪文件驱动器补偿大文件写入操作（这些被视为安排后面的时间表进入相同的过程）。
让我们找到suspend条目：
{[{{file,write,2}, 53, 6.281, 0.000},
{{foo,create_file_slow,3}, 57, 6.041, 0.000},
{{prim_file,drv_command,4}, 50, 4.582, 0.000},
{{prim_file,drv_get_response,1}, 34, 2.986, 0.000},
{{lists,map,2}, 10, 2.104, 0.000},
{{prim_file,write,2}, 17, 1.852, 0.000},
{{erlang,port_command,2}, 15, 1.713, 0.000},
{{prim_file,drv_command,2}, 22, 1.482, 0.000},
{{prim_file,translate_response,2}, 11, 1.441, 0.000},
{{prim_file,'-drv_command/2-fun-0-',1}, 15, 1.340, 0.000},
{{lists,seq,4}, 3, 0.880, 0.000},
{{foo,'-create_file_slow/2-fun-0-',1}, 5, 0.523, 0.000},
{{erlang,bump_reductions,1}, 4, 0.503, 0.000},
{{prim_file,open_int_setopts,3}, 1, 0.165, 0.000},
{{prim_file,i32,4}, 1, 0.109, 0.000},
{{fprof,apply_start_stop,4}, 1, 0.000, 0.000}],
{ suspend, 299, 32.002, 0.000}, %
[ ]}.
我们没有发现特别长的暂停时间，因此似乎没有函数在接收语句中等待。实际上，prim_file:drv_command/4包含一个接收语句，但是在这个测试程序中，当输入Receign语句时，消息位于流程接收缓冲区中。我们还看到，测试运行的总暂停时间很小。
大suspend伪函数有一个自己的时间为零。这是为了防止过程本身的总时间包括暂停时间。暂停时间是否真的是ACC，还是属于自己的时间是一个哲学问题。
现在我们来看另一个有趣的伪函数，garbage_collect*
{[{{prim_file,drv_command,4}, 25, 0.873, 0.873},
{{prim_file,write,2}, 16, 0.692, 0.692},
{{lists,map,2}, 2, 0.195, 0.195}],
{ garbage_collect, 43, 1.760, 1.760}, %
[ ]}.
在这里，我们看到没有任何函数能很好地区分自己，这是非常正常的。
大garbage_collect伪函数没有自己的零点时间suspend，相反，它等于ACC时间。
垃圾收集经常发生在进程挂起时，但是fprof通过假装挂起的函数首先是未挂起的，然后是垃圾收集来隐藏这一事实。否则打印出来会显示garbage_collect从suspend但不是哪个函数可能导致垃圾收集。
现在让我们回到测试代码：
{[{{foo,create_file_slow,3}, 768, 220.314, 14.539},
{{foo,create_file_slow,2}, 1, 0.316, 0.021}],
{ {file,write,2}, 769, 220.630, 14.560}, %
[{{prim_file,write,2}, 769, 199.789, 22.573},
{suspend, 53, 6.281, 0.000}]}.
不出所料，我们看到file:write/2从foo:create_file_slow/3和foo:create_file_slow/2每一次通话的次数和所用的时间也证实了先前的结果。
我们看到了file:write/2只打电话prim_file:write/2，但是让我们不要深入到内核应用程序的内部。
但是，如果我们做深入挖掘，我们可以找到对链接中驱动程序的调用，该驱动程序对主机操作系统执行文件操作：
{[{{prim_file,drv_command,4}, 772, 1458.356, 1456.643}],
{ {erlang,port_command,2}, 772, 1458.356, 1456.643}, %
[{suspend, 15, 1.713, 0.000}]}.
这是总运行时间的86％，正如我们之前看到的那样，这是关闭操作的绝对最大贡献者。我们发现调用堆栈中的比较比率略高一点：
{[{{prim_file,close,1}, 1, 1398.748, 0.024},
{{prim_file,write,2}, 769, 174.672, 12.810},
{{prim_file,open_int,4}, 1, 19.755, 0.017},
{{prim_file,open_int_setopts,3}, 1, 0.147, 0.016}],
{ {prim_file,drv_command,2}, 772, 1593.322, 12.867}, %
[{{prim_file,drv_command,4}, 772, 1578.973, 27.265},
{suspend, 22, 1.482, 0.000}]}.
在驱动程序中链接的文件操作的时间分配为：打开1%，写入11%，关闭87%。所有数据可能都会在操作系统中缓冲，直到关闭为止。
不睡觉的读者可能会注意到ACC时代prim_file:drv_command/2和prim_file:drv_command/4在上述段落之间并不相等，尽管人们很容易相信prim_file:drv_command/2只是一个传递函数。
失踪时间可在以下段落中找到：prim_file:drv_command/4很明显不仅仅是prim_file:drv_command/2被称为，但也是一种乐趣：
{[{{prim_file,drv_command,2}, 772, 1578.973, 27.265}],
{ {prim_file,drv_command,4}, 772, 1578.973, 27.265}, %
[{{erlang,port_command,2}, 772, 1458.356, 1456.643},
{{prim_file,'-drv_command/2-fun-0-',1}, 772, 87.897, 12.736},
{suspend, 50, 4.582, 0.000},
{garbage_collect, 25, 0.873, 0.873}]}.
还有更多的缺失时间可以解释为prim_file:open_int/4两次通话prim_file:drv_command/2直接和通过prim_file:open_int_setopts/3，这使情况变得复杂。
{[{{prim_file,open,2}, 1, 20.309, 0.029},
{{prim_file,open_int,4}, 1, 0.000, 0.057}],
{ {prim_file,open_int,4}, 2, 20.309, 0.086}, %
[{{prim_file,drv_command,2}, 1, 19.755, 0.017},
{{prim_file,open_int_setopts,3}, 1, 0.360, 0.032},
{{prim_file,drv_open,2}, 1, 0.071, 0.030},
{{erlang,list_to_binary,1}, 1, 0.020, 0.020},
{{prim_file,i32,1}, 1, 0.017, 0.017},
{{prim_file,open_int,4}, 1, 0.000, 0.057}]}.
.
.
.
{[{{prim_file,open_int,4}, 1, 0.360, 0.032},
{{prim_file,open_int_setopts,3}, 1, 0.000, 0.016}],
{ {prim_file,open_int_setopts,3}, 2, 0.360, 0.048}, %
[{suspend, 1, 0.165, 0.000},
{{prim_file,drv_command,2}, 1, 0.147, 0.016},
{{prim_file,open_int_setopts,3}, 1, 0.000, 0.016}]}.
注记
对执行时间的实际监督本身就是CPU密集型活动。在跟踪文件上为由配置代码执行的每个函数调用编写一条消息。
ACC时间计算有时很难正确，因为它很难定义。这种情况尤其发生在调用堆栈中的几个实例中，例如，通过其他函数甚至是非尾函数递归地调用自己。
为了产生明智的结果，fprof尽量不要在ACC时间内多次收取任何功能。选择调用堆栈中最高（持续时间最长）的实例。
有时一个函数可能会意外地浪费很多时间（大约10 ms或更长，这取决于主机操作系统）OWN（和ACC）时间，甚至是几乎完全没有任何作用的函数。问题可能在于操作系统选择安排Erlang运行时系统进程一段时间，如果操作系统不支持高分辨率cpu时间测量，fprof将使用wallclock时间进行计算，并且它会显示为随机刻录虚拟机器时间。
另见
dbg(3), eprof(3), erlang(3), io(3), Tools User's Guide
