【问题标题】:Understanding Linux perf report output了解 Linux 性能报告输出
【发布时间】:2015-01-02 12:45:19
【问题描述】:

虽然我可以直观地得到大部分结果,但我很难完全理解 perf report 命令的输出,特别是关于调用图的内容,所以我写了一个愚蠢的测试来解决我的这个问题一次所有人。

愚蠢的测试

我编译了以下内容:

gcc -Wall -pedantic -lm perf-test.c -o perf-test

没有积极的优化来避免内联等。

#include <math.h>

#define N 10000000UL

#define USELESSNESS(n)                          \
    do {                                        \
        unsigned long i;                        \
        double x = 42;                          \
        for (i = 0; i < (n); i++) x = sin(x);   \
    } while (0)

void baz()
{
    USELESSNESS(N);
}

void bar()
{
    USELESSNESS(2 * N);
    baz();
}

void foo()
{
    USELESSNESS(3 * N);
    bar();
    baz();
}

int main()
{
    foo();
    return 0;
}

平面分析

perf record ./perf-test
perf report

有了这些,我得到:

  94,44%  perf-test  libm-2.19.so       [.] __sin_sse2
   2,09%  perf-test  perf-test          [.] sin@plt
   1,24%  perf-test  perf-test          [.] foo
   0,85%  perf-test  perf-test          [.] baz
   0,83%  perf-test  perf-test          [.] bar

这听起来很合理,因为繁重的工作实际上是由 __sin_sse2 执行的,sin@plt 可能只是一个包装器,而我的函数的开销只考虑了循环,总体而言:3*N 迭代 foo , 2*N 其他两个。

分层分析

perf record -g ./perf-test
perf report -G
perf report

现在我得到的开销列是两个:Children(输出默认按这一列排序)和Self(与平面配置文件的开销相同)。

这是我开始觉得我错过了什么的地方:无论我是否使用-G,我都无法用“x 调用 y”或“y 被 x 调用”来解释层次结构,例如:

  • 没有-G(“y被x调用”):

    -   94,34%    94,06%  perf-test  libm-2.19.so       [.] __sin_sse2
       - __sin_sse2
          + 43,67% foo
          + 41,45% main
          + 14,88% bar
    -   37,73%     0,00%  perf-test  perf-test          [.] main
         main
         __libc_start_main
    -   23,41%     1,35%  perf-test  perf-test          [.] foo
         foo
         main
         __libc_start_main
    -    6,43%     0,83%  perf-test  perf-test          [.] bar
         bar
         foo
         main
         __libc_start_main
    -    0,98%     0,98%  perf-test  perf-test          [.] baz
       - baz
          + 54,71% foo
          + 45,29% bar
    
    1. 为什么__sin_sse2 被main(间接?)、foo 和bar 调用,而不是baz?
    2. 为什么函数有时附有百分比和层次结构(例如,baz 的最后一个实例),而有时没有(例如,bar 的最后一个实例)?
  • 与-G(“x 调用y”):

    -   94,34%    94,06%  perf-test  libm-2.19.so       [.] __sin_sse2
       + __sin_sse2
       + __libc_start_main
       + main
    -   37,73%     0,00%  perf-test  perf-test          [.] main
       - main
          + 62,05% foo
          + 35,73% __sin_sse2
            2,23% sin@plt
    -   23,41%     1,35%  perf-test  perf-test          [.] foo
       - foo
          + 64,40% __sin_sse2
          + 29,18% bar
          + 3,98% sin@plt
            2,44% baz
         __libc_start_main
         main
         foo
    
    1. 我应该如何解释__sin_sse2下的前三个条目?
    2. main 调用 foo 没关系,但为什么如果它调用 __sin_sse2 和 sin@plt(间接?)它不会调用 bar 和 baz?
    3. 为什么__libc_start_main 和main 出现在foo 下?为什么foo 会出现两次?

怀疑这个层次结构有两个级别,其中第二个实际上表示“x 调用 y”/“y 由 x 调用”语义,但我猜累了所以我在这里问。而且文档似乎没有帮助。


很抱歉,这篇文章很长,但我希望所有这些上下文都可以对其他人有所帮助或作为参考。

【问题讨论】:

  • 我不是perf 的专家,但我知道默认情况下它每秒查看堆栈约 1000 次以收集其数据。因此,您尝试的细粒度分析可能会失败。所以例如当sin_sse2 被baz 调用时,可能没有任何样本发生。考虑使用gprof,它在存根中编译以捕获每个调用并返回(尽管它有其他问题)。
  • 是的,我知道,但它很快,它让我可以记录各种疯狂的事件,例如缓存未命中和每个符号的分支预测错误,而 AFAIK gprof 无法做到。我使用N 相当大,正是为了避免你提到的;无论如何,我尝试进一步增加它没有运气,我不知道,但我认为即使在 100M 迭代循环中也不太可能没有收集到样本。

标签: c linux perf


【解决方案1】:

好吧,好吧,让我们暂时忽略调用者和被调用者调用图之间的区别,主要是因为当我在我的机器上比较这两个选项的结果时,我只看到 kernel.kallsyms DSO 内部的效果,原因我没有不明白——我自己对此比较陌生。

我发现对于您的示例,阅读整棵树要容易一些。所以,使用--stdio,让我们看看__sin_sse2的整棵树:

# Overhead    Command      Shared Object                  Symbol
# ........  .........  .................  ......................
#
    94.72%  perf-test  libm-2.19.so       [.] __sin_sse2
            |
            --- __sin_sse2
               |
               |--44.20%-- foo
               |          |
               |           --100.00%-- main
               |                     __libc_start_main
               |                     _start
               |                     0x0
               |
               |--27.95%-- baz
               |          |
               |          |--51.78%-- bar
               |          |          foo
               |          |          main
               |          |          __libc_start_main
               |          |          _start
               |          |          0x0
               |          |
               |           --48.22%-- foo
               |                     main
               |                     __libc_start_main
               |                     _start
               |                     0x0
               |
                --27.84%-- bar
                          |
                           --100.00%-- foo
                                     main
                                     __libc_start_main
                                     _start
                                     0x0

所以,我的阅读方式是:44% 的时间,sin 是从 foo 调用的; 27% 的时间从 baz 调用,27% 从 bar 调用。

-g 的文档很有指导意义:

 -g [type,min[,limit],order[,key]], --call-graph
       Display call chains using type, min percent threshold, optional print limit and order. type can be either:

       ·   flat: single column, linear exposure of call chains.

       ·   graph: use a graph tree, displaying absolute overhead rates.

       ·   fractal: like graph, but displays relative rates. Each branch of the tree is considered as a new profiled object.

               order can be either:
               - callee: callee based call graph.
               - caller: inverted caller based call graph.

               key can be:
               - function: compare on functions
               - address: compare on individual code addresses

               Default: fractal,0.5,callee,function.

这里重要的是默认是分形的,在分形模式下,每个分支都是一个新对象。

因此,您可以看到 50% 的时间调用 baz,它是从 bar 调用的,另外 50% 是从 foo 调用的。

这并不总是最有用的衡量标准,因此使用-g graph 查看结果很有启发性:

94.72%  perf-test  libm-2.19.so       [.] __sin_sse2
        |
        --- __sin_sse2
           |
           |--41.87%-- foo
           |          |
           |           --41.48%-- main
           |                     __libc_start_main
           |                     _start
           |                     0x0
           |
           |--26.48%-- baz
           |          |
           |          |--13.50%-- bar
           |          |          foo
           |          |          main
           |          |          __libc_start_main
           |          |          _start
           |          |          0x0
           |          |
           |           --12.57%-- foo
           |                     main
           |                     __libc_start_main
           |                     _start
           |                     0x0
           |
            --26.38%-- bar
                      |
                       --26.17%-- foo
                                 main
                                 __libc_start_main
                                 _start
                                 0x0

这将更改为使用绝对百分比,其中为该调用链报告每个时间百分比:所以foo-&gt;bar 是总滴答数的 26%(依次调用 baz)和foo-&gt;baz(直接)占总刻度的 12%。

从__sin_sse2 的角度来看,我仍然不知道为什么我看不到被调用者和调用者图之间的任何差异。

更新

我从命令行更改的一件事是调用图的收集方式。 Linux perf 默认使用重构调用栈的帧指针方法。当编译器使用-fomit-frame-pointer 作为default 时,这可能是一个问题。所以我用了

perf record --call-graph dwarf ./perf-test

【讨论】:

  • 相对与绝对百分比的事情绝对有意义。要点是我无法想出与您的输出相似的输出(这似乎是合法的,因为__sin_sse2 似乎被所有三个函数直接调用,而我的功能仅限foo、main 和 bar)。您能否发布您使用的确切标志?
  • @cYrus 看看我的更新... 午餐后将发布 perf report 的确切命令行。
  • @MatthewG。好吧,看来这完全是关于使用dwarf...我会检查这是否解决了我列出的所有问题。
  • @cYrus 我复制并粘贴了您的命令行以进行编译(不过,必须将链接器标志移到末尾)。内核是 3.13.0-37-generic(这可能很重要)。报告的命令行系列是perf report -g {graph,fractal},0.05,calle{e,r} --stdio &gt; {graph,fracal}Calle{e,r}
  • 您确定百分比反映的是调用次数而不是周期数吗?
猜你喜欢
  • 1970-01-01
  • 1970-01-01
  • 1970-01-01
  • 2014-04-27
  • 2012-10-01
  • 2015-10-18
  • 1970-01-01
  • 1970-01-01
  • 1970-01-01
相关资源
最近更新 更多