eTpf

快速高效简单易用的erlang tracer and profiler 程序

Build

$ rebar3 compile

Useage

oooo

相关软件

qcachegrind graphviz FlameGraph seqdiag

介绍

eTpf是Erlang/OTP的跟踪器和分析器。 旨在提供一种非常有效的工具, 可在开发和生产环境中使用, 并且即使在繁忙的系统上也能够长时间运行 需要使用cachegrind工具从中读取输出lg_callgrind。 建议使用具 kcachegrind 。请注意，最好安装同样graphviz具有丰富信息的调用图。

Tracing

eTpf既是跟踪工具, 也是分析工具。下面介绍该工具的跟踪功能, 并学习如何创建分析所需的跟踪文件。

第一步

让我们从追踪所有内容开始。

打开一个Erlang shell并运行以下命令：

1> lg:trace('_').
{link,<0.4.0>,1488297881224444,#Port<0.692>}
{getting_unlinked,<0.4.0>,1488297881224533,#Port<0.692>}
{link,<0.4.0>,1488297881224640,#Port<0.693>}
{getting_unlinked,<0.4.0>,1488297881224720,#Port<0.693>}
{link,<0.4.0>,1488297881224817,#Port<0.694>}
{getting_unlinked,<0.4.0>,1488297881224881,#Port<0.694>}
{link,<0.4.0>,1488297881224979,#Port<0.695>}
{getting_unlinked,<0.4.0>,1488297881225060,#Port<0.695>}

如您所见，我们得到了很多输出。这是因为该eTpf:trace/1功能默认情况下会将原始跟踪事件输出到控制台。我们还使用了原子 '_'来跟踪所有模块，并且没有限制应跟踪哪个过程。 请注意: 不要在生产中执行此操作。 跟踪事件始终带有 事件名称, 事件发生过程的进程的pid,时间戳（以微秒为单位）以及一个或两个额外的元素, 以提供有关事件的额外上下文。

例如，以下事件是一个函数调用，该过程<0.64.0>在时间戳1488297891226328 为的过程中发生supervisor:handle_info/2

{call,<0.64.0>,1488297891226328,{supervisor,handle_info,2}}

停止追踪: 要停止跟踪，只需调用：

2 >  eTpf:stop().

跟踪特定模块

为了获得更有趣的输出，我们需要过滤将要跟踪的内容。例如，我们可能只希望来自模块的事件shell：

1 >  eTpf:trace(shell).

{通话，< 0.58。0 >，1488298545020494，{ shell，result_will_be_saved，0 }}
{通话，< 0.58。0 >，1488298545020497，{ shell，get_history_and_results，0 }}
{通话，< 0.58。0 >，1488298545020498，{ shell，get_env，2 }}
{ return_to，< 0.58。0 >，1488298545020501，{ shell，get_history_and_results，0 }}
{通话，< 0.58。0 >，1488298545020502，{ shell，get_env，2 }}
{ return_to，< 0.58。0 >，1488298545020503，{ shell，get_history_and_results，0 }}
{ return_to，< 0.58。0 >，1488298545020504，{ shell，result_will_be_saved，0 }}

我们还可以请求跟踪模块列表：

1> eTpf:trace([shell, user_drv]).
{call,<0.58.0>,1488299067458321,{shell,record_print_fun,1}}
{return_to,<0.58.0>,1488299067458322,{shell,pp,4}}
{call,<0.58.0>,1488299067458323,{shell,enc,0}}
{call,<0.49.0>,1488299067459603,{user_drv,handle_req,4}}
{call,<0.49.0>,1488299067459605,{user_drv,get_unicode_state,1}}

追踪app

除了提供模块之外，您还可以提供OTP应用程序。当您这样做时，将跟踪属于该应用程序的所有模块。我们当然可以跟踪eTpf本身：

1> eTpf:trace({app, looking_glass}).
{link,<0.4.0>,1488299179652509,#Port<0.688>}
{getting_unlinked,<0.4.0>,1488299179652621,#Port<0.688>}
{call,<0.58.0>,1488299179653161,{lg,'-trace_patterns/1-fun-0-',1}}
{call,<0.58.0>,1488299179653164,{lg,trace_pattern,1}}

请注意, eTpf将禁用跟踪程序进程本身的跟踪(以避免无限递归)

您可以跟踪模块和app的任何组合:

1> eTpf:trace([shell, {app, looking_glass}]).

跟踪特定过程 在默认情况下，eTpf会跟踪所有进程。 大型系统往往具有许多过程，并且会产生大量噪声，尤其是在您尝试优化特定组件的情况下。 您可以使用输入选项指定应跟踪的进程 scope：

1> eTpf:trace([{scope, [self()]}, io]).
{call,<0.58.0>,1489494935163831,{io,columns,0}}
{call,<0.58.0>,1489494935163841,{io,default_output,0}}
{return_to,<0.58.0>,1489494935163844,{io,columns,0}}
{call,<0.58.0>,1489494935163846,{io,columns,1}}

在scope元组中找到的列表可以采用与的第一个参数相同的值erlang:trace/3。当元组丢失时，默认值为processes。

可以在输入中多次找到范围元组。当组合跟踪定义回调时，这特别有用。 eTpf将跟踪所有指定的过程以及它们创建的过程。这意味着，当您提供主管pid时，只要在跟踪会话开始之后就启动了所有子进程，也将跟踪其所有子进程。

跟踪回调

为了易于使用，eTpf允许您在代码中定义返回有趣模式的函数。这使您可以定义经常分析的代码区域，或在必要时动态生成列表。 要使用回调，只需提供一个回调元组：

1> eTpf:trace({callback, lg_callgrind, patterns}).

您当然可以将其与其他输入结合使用：

1> eTpf:trace([shell, {callback, lg_callgrind, patterns}]).

您还可以根据需要组合任意数量的回调。 回调采用以下形式：

patterns() -> lg:input(). 函数名称可以是任何东西。一个模块可能具有多个eTpf回调。

返回值是将要跟踪的模式和范围的列表。因此，它可以包含模块，应用程序或其他回调。

一个示例回调可能是：

-module(ranch_lg).
-export([connections/0]).

%% Trace all events but only from the TCP connection processes.
connections() ->
ConnsPid = ranch_server:get_connections_sup(tcp_echo),
['_', {scope, [ConnsPid]}].

Tracers

eTpf附带了许多示踪剂。缺省值被调用 tpRawConsoleTracer，仅将事件输出到控制台，而不应用任何格式。

默认eTpf:trace/1调用等效于以下内容：

1> eTpf:trace(shell, lg_raw_console_tracer, undefined, #{}).

自变量依次是跟踪模式（需要跟踪的模块或应用程序），跟踪器模块，跟踪器选项和 eTpf选项。

Tracing to file

eTpf带有跟踪器，可将所有事件直接保存到压缩文件中。跟踪文件可用于重播事件（例如，如果您在调试时正在寻找特定的东西）或进行概要分析。

该跟踪器的选项仅是文件名：

1> eTpf:trace('_', lg_file_tracer, "traces.lz4").

如果您在运行此命令后稍稍玩一下外壳，然后再运行，eTpf:stop().您会看到已创建以下文件：

$ ls -l traces.lz4.* -rw-r--r-- 1 essen essen 333676 Feb 28 18:24 traces.lz4.1 -rw-r--r-- 1 essen essen 384471 Feb 28 18:24 traces.lz4.2 -rw-r--r-- 1 essen essen 333776 Feb 28 18:24 traces.lz4.3 -rw-r--r-- 1 essen essen 11689 Feb 28 18:24 traces.lz4.4 在默认情况下，eTpf将为每个调度程序创建一个跟踪文件(通常等于您计算机上的内核数)。这些文件被分割文件，以便将一个进程的所有事件始终存储在同一文件中。

我们可以使用eTpf附带的文件阅读器模块来检查文件的内容：

2> tpFileReader:foreach(fun(E) -> erlang:display(E) end, "traces.lz4.1").
{call,<0.51.0>,1488302656982110,{group,io_request,5}}
{call,<0.51.0>,1488302656982114,{group,io_request,4}}
{call,<0.51.0>,1488302656982117,{group,get_tty_geometry,1}}
{call,<0.75.0>,1488302656982129,{file_io_server,io_request,2}}

不过请注意，也不要在生产环境中运行它！跟踪文件可能非常大。

您还可以编写一个稍大的乐趣来过滤您想要查看的内容，例如来自单个进程的所有事件：

3> Pid = pid(0,51,0).
<0.51.0>
4> F = fun(E) when element(2, E) =:= Pid ->
    erlang:display(E);
    (_) ->
    ok
end.
#Fun<erl_eval.6.52032458>
5> lg_file_reader:foreach(F, "traces.lz4.1").
{call,<0.51.0>,1488302656982110,{group,io_request,5}}
{call,<0.51.0>,1488302656982114,{group,io_request,4}}
{call,<0.51.0>,1488302656982117,{group,get_tty_geometry,1}}
{return_to,<0.51.0>,1488302656982306,{group,io_request,4}}

Tracer mode

当出于分析目的而跟踪文件时，您很可能不关心某些事件，例如链接的进程。要禁用任何不必要的事件分析，请传递mode选项：

1> lg:trace('_', lg_file_tracer, "traces.lz4", #{mode => profile}).

tracing_running 您还可以通过启用选项来获得仅对配置文件有用的额外事件。 该running选项将启用事件，这些事件指示何时安排进出流程。 启用它通常会很有用，因为它可以启用其他统计信息，但会占用大量资源，因此默认情况下未启用：

1> lg:trace('_', lg_file_tracer, "traces.lz4", #{mode => profile, running => true}).

tracing_send 您可能还希望跟踪进程发送的消息。为此，您需要启用该send选项。然后，您 可以获得有关发送消息的过程的详细信息。要启用消息跟踪：

1> lg:trace('_', lg_file_tracer, "traces.lz4", #{send => true}).

本节中的所有选项都可以随意组合。在对函数和消息进行概要分析时，可以使用来自同一跟踪会话的数据。

跟踪文件旋转

对于长时间运行的会话，eTpf可以旋转跟踪文件。这是一项有助于避免磁盘空间用完的功能，并且不用于保留较小的文件（eTpf可以处理非常大的文件就可以了）。

eTpf:trace/3,4可以提供一个映射，而不是将文件名前缀作为第三个参数传递 给。当前有三个选项，包括filename_prefix。其他选项是最大文件大小（以字节为单位）fMaxSize，以及将在文件中每LZ4帧存储的事件数 fMaxLog。这两个选项使您可以控制文件写入或旋转的频率。

以下示例将文件大小限制为100MB：

1> eTpf:trace('_', lg_file_tracer, #{fBaseName => "traces.lz4", fMaxSize => 100000000}, #{mode => profile, running =>true}). 

在测试此功能期间，目前实施的轮换似乎很昂贵，因此您应注意不要设置太低的值。

Callgrind分析

eTpf的主要目的是对Erlang应用程序进行性能分析。这是通过首先将事件跟踪到文件或套接字，然后对其进行处理以提取有用的输出来完成的。

分析工具通常具有几种不同类型的输出。本章是关于callgrind输出的，可以使用qcachegrind/kcachegrind 工具读取。

快速开始 假设您使用概要文件模式和运行标志生成了跟踪文件（如Tracer一章中所述），则可以使用以下命令生成callgrind.out文件：

1> tpCallgrind:pfm("traces.lz4.*", "callgrind.out", #{running => true}).

这将为您生成的所有跟踪文件创建一个callgrind.out文件。例如，如果您具有“ traces.lz4.1”和“ traces.lz4.2”，则现在还应该具有“ callgrind.out.1”和“ callgrind.out.2”。 现在，您可以通过用户界面或命令行在cachegrind工具中打开这两个文件：

$ qcachegrind callgrind.out

它将自动检测并打开所有与该callgrind.out.*模式匹配的文件。

Profiling one file 您可以通过调用函数来分析一个文件 tpCallgrind:pfs/2,3。它包含跟踪文件名，输出文件名和一个可选的选项映射：

1> tpCallgrind:pfs("traces.lz4.1", "callgrind.out.1").

它还接受以下选项：

1> tpCallgrind:pfs("traces.lz4.1", "callgrind.out.1", #{running => true}).

Profiling many files 便利功能可用于一次分析许多文件：tpCallgrind:profile_many/2,3, 它以通配符模式作为第一个参数，并以文件名前缀作为第二个参数：

1> tpCallgrind:pfm("traces.lz4.*", "callgrind.out").

如果有两个跟踪文件，这将导致两个'callgrind.out'文件：'callgrind.out.1'和'callgrind.out.2'。

它还接受以下选项：

1> tpCallgrind:pfm("traces.lz4.*", "callgrind.out", #{running => true}).

Running information 当跟踪文件包含运行信息时，这意味着它们是在running启用了标记的情况下创建的，您还需要将running标记传递给事件探查器，以使该信息在'callgrind.out'文件中可用：

1> tpCallgrind:pfm("traces.lz4.*", "callgrind.out", #{running => true}).

Scope 默认情况下，跟踪事件的范围是全局的。这意味着cachegrind工具会将所有事件组合在一起，无论它们发生在何处。这对于查看哪些功能总体上占用最多资源很有用。

其他时间，您可能想查看哪些进程占用最多的资源。为此，您需要指示eTpf在生成“ callgrind.out”文件时保留过程信息。使用以下scope选项完成此操作：

1> lg_callgrind:pfm("traces.lz4.*", "callgrind.out", #{scope => per_process}).

使用cachegrind工具 当将cachegrind工具与Looking Glass生成的输出一起使用时，需要注意一些陷阱。

cachegrind工具在构建时就考虑了命令性代码。递归处理得不太好。这意味着调用函数的次数可能并不总是正确的，尤其是对于调用自身的函数而言。例如，在查看调用图时，您可以看到此问题的示例。

当使用该scope => per_process选项时，Looking Glass使用ELF对象字段来存储过程的pid 。这使您可以通过使用'grouping'功能并选择'ELF Object'来单独调查过程。 然后，您可以查看哪些进程占用最多的资源，并查看这些进程中的函数调用。

使用运行标志时，将生成以下事件类型：

• Total time in microseconds
• Active time in microseconds
• Wait time in microseconds (scheduled out)
• Number of times the process was scheduled out

以下公式是正确的：Total = Active + Wait.

等待时间是指计划该流程（即它未运行）所花费的时间。这发生在许多不同的地方，like receive clauses or when the reduction count reached zero.

目前，process was scheduled out 次数统计可能不准确。另一个可能不准确的部分是花费在执行端口操作上的时间，该时间可能在进程主要等待时显示为活动时间。两者都将在未来得到改进。

虽然eTpf提供了有关各种调用的行号信息，但它无法识别此调用过程中涉及的函数子句。 这意味着当在cachegrind工具中查看源代码时，具有很多子句的函数的调用信息将聚集在同一行号上。 这对大多数标准行为（包括handle_event 来自）具有重要影响gen_statem。但是，您可以对代码进行结构化，以使子句繁重的函数仅分派给其他函数，从而在cachegrind工具中获得更好的视图。

eTpf目前无法找到列表理解和匿名函数的行号。他们将始终指向第1行。

Flame graph 分析

作为Callgrind输出的替代方法，eTpf提供了火焰图。火焰图是堆栈轨迹的图形视图，可让您清楚地了解花费最多的时间。它补充了所提供的其他图形视图qcachegrind。 eTpf只负责提供输出，然后可以使用常规工具（不附带）将其转换为火焰图。本章将说明这两种操作。

必需的trace选项 为了生成火焰图，我们目前在跟踪时需要使用一个附加选项。此选项将导致将堆栈跟踪信息添加到调用事件。选项为process_dump, 并且必须将其设置为true。

举个例子 使用第二个替换第一个

1> lg:trace('_', lg_file_tracer, "traces.lz4").
1> lg:trace('_', lg_file_tracer, "traces.lz4", #{process_dump => true}).

分析一个文件 该tpFlame模块提供与其他eTpf分析器类似的界面。您可以基于一个或多个文件产生中间输出。

要分析一个文件：

1> lg_flame:utils("traces.lz4.1", "output").

这将创建一个名为'output'的中间文件。

分析许多文件 要分析许多文件：

1> lg_flame:profile_many("traces.lz4.*", "output").

请注意，由于结果合并在一起，因此输出始终是单个文件。

建立火焰图 flamegraph.pl 可用于生成实际的SVG火焰图。 首先，我们需要克隆它 FlameGraph 。任何地方都可以做： $ git clone https://github.com/brendangregg/FlameGraph.git 然后，可以在输出文件中使用它来创建SVG： $ ./FlameGraph/flamegraph.pl output > output.svg 然后，您可以在所选的Web浏览器中打开输出SVG。产生的SVG是交互式的，您可以单击不同的功能来放大，也可以搜索特定的功能调用。

Messages profiling

eTpf也可以根据它们发送的消息来分析Erlang进程。它可以帮助您检测哪些进程最忙，并且可以生成图形和顺序图来帮助您调试复杂的问题。

启用消息跟踪 默认情况下，eTpf将消息不包括在跟踪文件中。需要通过send选项启用它 。

然后，一个跟踪会话的输出可用于callgrind和消息概要分析。

分析一个文件 您可以通过调用函数来分析一个文件 lg_messages:utils/1。它使用跟踪文件名并打印出分析结果。

1> lg_messages:utils("traces.lz4.1").

它还将创建一个GraphViz文件，当前将其硬编码为“ digraph.gv”，并打印使用说明。

分析许多文件

便利功能可用于一次分析许多文件：lg_callgrind:profile_many/2,3。它以通配符模式作为第一个参数，并以文件名前缀作为第二个参数：

您可以通过调用函数来分析许多文件 lg_messages:profile_many/1。它采用通配符模式，并输出分析结果。结果是不同跟踪文件中事件的合并。

1> lg_messages:profile_many("traces.lz4.*").

=== Profile output

配置文件步骤将导致打印四个表。 第一张表显示了发送最多消息的进程。 第二张表显示了将最多消息发送到已死或根本不存在的进程的进程。 第三张表显示了最频繁地将消息发送到一个特定的其他进程（从Alice到Bob）的进程。 第四张表显示了交换最多消息的过程（从Alice到Bob，从Bob到Alice）。

输出示例 1> lg_messages:profile_many("traces.lz4.*").

They sent the most messages

Process ID Count Most recent message

---

<7782.367.0> 147327 {notify,{event,channel_closed,...}} <7782.356.0> 73035 {notify,{event,connection_closed,...}} <7782.382.0> 30514 pause <7782.391.0> 30052 {'$gen_cast',{deliver,{...},...}} <7782.365.0> 1486 {channel_exit,1,{writer,...}} [...]

They sent the most messages to dead processes

Process ID Count Most recent message

---

<7782.367.0> 29 {notify,{event,channel_closed,...}}

They sent the most messages to one other process

From pid To pid Count Most recent message

---

<7782.367.0> <7782.365.0> 74318 {notify,{event,channel_closed,...}} <7782.356.0> <7782.367.0> 73001 {notify,{event,connection_closed,...}} <7782.367.0> <7782.375.0> 73000 {notify,{event,channel_closed,...}} <7782.382.0> <7782.391.0> 30202 pause <7782.391.0> <7782.375.0> 29894 {'$gen_cast',{deliver,{...},...}} <7782.365.0> <7782.375.0> 1485 {channel_exit,1,{writer,...}} [...]

They sent the most messages to each other

Count Pid 1 Most recent message Pid 2 from the corresponding process

---

74318 <7782.365.0> {channel_exit,1,{writer,...}} <7782.367.0> {notify,{event,channel_closed,...}} 73001 <7782.356.0> {notify,{event,connection_closed,...}} <7782.367.0> {notify,{event,channel_closed,...}} 73000 <7782.367.0> {notify,{event,channel_closed,...}} <7782.375.0> '' 30351 <7782.382.0> pause <7782.391.0> {'$gen_cast',{deliver,{...},...}} 29894 <7782.375.0> '' <7782.391.0> {'$gen_cast',{deliver,{...},...}} [...]

文件digraph.gv已创建。使用GraphViz制作PNG。 digraph $ dot -Tpng -O digraph.gv

您也可以编辑文件以删除不感兴趣的进程。 文件中的一行等于两个进程之间的连接。 在输出的末尾，给出了从GraphViz文件生成图像的指令。此图显示了进程之间的关系，并指示它们相互发送了多少消息。

Looking Glass生成的文件是文本文件，可以根据需要进行进一步编辑。看起来像这样：

digraph {
concentrate=true;
splines=ortho;
edge [arrowhead=none, labelfontsize=12.0, minlen=3];

    "error_logger" -> "<7782.354.0>" [taillabel=0, headlabel=2];
    "<7782.32.0>" -> "<7782.380.0>" [taillabel=0, headlabel=1];
    "<7782.388.0>" -> "<7782.391.0>" [taillabel=0, headlabel=1];
    "error_logger" -> "<7782.355.0>" [taillabel=0, headlabel=4];
[...]
}

当然可以编辑该文件。您可能想要修改样式属性，甚至完全从输出中删除进程。

生成序列图 eTpf还可以用于提取两个或多个进程之间交换的消息序列。这是使用lg_messages_seqdiag模块完成的，就像该 模块lg_messages 接受包含您要调查的pid列表的第二个参数一样。

要查看一个文件：

1> lg_messages_seqdiag:utils("traces.lz4.1",
["<7788.381.0>", "<7788.382.0>", "<7774.383.0>",
"<7774.384.0>", "<7774.386.0>"]).

还有很多文件：

1> lg_messages_seqdiag:profile_many("traces.lz4.*",
["<7788.381.0>", "<7788.382.0>", "<7774.383.0>",
"<7774.384.0>", "<7774.386.0>"]).

pid列表必须以字符串列表形式给出。这是因为所表示的进程在运行的系统上不存在。eTpf也将忽略pid中的节点信息，因此您不必担心它。 这解释了为什么前两个片段中请求的pid看起来好像来自不同的节点。因此，pid"<7888.381.0>" 和 "<7774.381.0>"等效。

运行这些命令之一后，您将得到一个文件“ seq.diag”，该文件可用于创建映像。如果需要，以后也可以编辑此文件。看起来像这样：

seqdiag {
edge_length = 300;
activation = none;

    "<7774.382.0>" -> "<7774.381.0>" [label="gen:call #1 {start_child,{collector,{rabbit_queue_collector,start_link,[...]},intrinsic,30000,worker,...}}"];
    "<7774.383.0>" -> "<7774.381.0>" [label="{ack,<7774.383.0>,{ok,<7774.383.0>}}"];
    "<7774.381.0>" -> "<7774.382.0>" [label="#1 {ok,<7774.383.0>}"];
[...]
}

您必须先安装，然后才能从其创建映像 seqdiag。安装说明将取决于您的系统。 该项目页面位于 seqdiag

序列 图1.示例输出

执行 seqdiag 命令 $ seqdiag simple.diag $ ls simple.png simple.png 如果您想要 SVG 图像，请使用 -T 选项

$ seqdiag -Tsvg simple.diag $ ls simple.svg simple.svg

识别过程 Looking Glass将显示每个过程的pid和一个示例消息，但识别哪个过程并不总是理想的。

为了解决这个问题，Looking Glass提供了一个简单的解决方案：lg在运行跟踪程序时将消息发送到指定的进程。 Looking Glass将不可避免地将此消息记录在跟踪文件中，识别出目标为目标lg并将该消息用作元数据。然后，此元数据可用于从跟踪文件读取的任何模块。

当然，该过程仅在Looking Glass运行时可用，这意味着我们不能直接发送消息。以下作品：

is_pid(whereis('$eTpfHole')) andalso ('$eTpfHole' ! Info). 当然，这可以做成一个宏：

％％启用消息跟踪时，将元数据存储在跟踪文件中。 -define(LG_INFO(Info), is_pid(whereis('$eTpfHole')) andalso ('$eTpfHole' ! Info)). 然后可以这样使用：

?LG_INFO(#{process_type => reader}). 该消息必须始终是地图。否则，将无法读取跟踪文件。process_type在对消息交换进行概要分析时，Looking Glass仅识别该字段， 并将其用作标签来标识进程。您可以自由定义地图中需要的任何其他值。

还可以通过发送另一条消息或第二次调用宏来更新元数据。默认情况下，在地图上完成的操作将是合并。