Понимание вывода отчета о производительности Linux

Хотя я могу интуитивно получить большую часть результатов, мне трудно понять, что выводит команду perf report, особенно для графа вызовов, поэтому я написал глупый тест для решения этой проблемы один раз для всех.

Глупый тест

Я скомпилировал следующее:

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

Нет агрессивных оптимизаций, чтобы избежать inlining и т.д.

#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          [.] [email protected]
   1,24%  perf-test  perf-test          [.] foo
   0,85%  perf-test  perf-test          [.] baz
   0,83%  perf-test  perf-test          [.] bar

Что звучит разумно, так как тяжелая работа на самом деле выполняется __sin_sse2 и [email protected], вероятно, всего лишь оболочка, в то время как накладные расходы моих функций учитывают только цикл, в целом: 3*N итерации для foo, 2*N для двух других.

Иерархическое профилирование

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

Теперь верхние столбцы, которые я получаю, равны двум: Children (результат сортируется по умолчанию) и Self (те же самые служебные данные плоского профиля).

Вот где я начинаю чувствовать, что я что-то пропустил: независимо от того, что я использую -G или нет, я не могу объяснить иерархию в терминах "x calls 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
    • Почему __sin_sse2 вызывается main (косвенно?), foo и bar, но не baz?
    • Почему функции иногда содержат процент и иерархию (например, последний экземпляр 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% [email protected]
-   23,41%     1,35%  perf-test  perf-test          [.] foo
   - foo
      + 64,40% __sin_sse2
      + 29,18% bar
      + 3,98% [email protected]
        2,44% baz
     __libc_start_main
     main
     foo
    1. Как интерпретировать первые три записи в __sin_sse2?
    2. main вызывает foo и это нормально, но почему, если он вызывает __sin_sse2 и [email protected] (косвенно?), он также не вызывает bar и baz?
    3. Почему __libc_start_main и main отображаются под foo? И почему foo появляется дважды?

Подозреваю, что существует два уровня этой иерархии, в которых вторая фактически представляет "x-вызовы y" / "y, которые вызывается семантикой x", но я устал догадываться, поэтому я прошу здесь. И документация, похоже, не помогает.

Извините за длинный пост, но я надеюсь, что весь этот контекст может помочь или действовать как ссылка для кого-то еще.

Ответы

Ответ 1

Хорошо, допустим, временно игнорировать разницу между call-графами звонящего и вызываемого, главным образом потому, что, когда я сравниваю результаты между этими двумя параметрами на своей машине, я вижу только эффекты внутри DSO kernel.kallsyms по причинам, я понимаю - относительно новое для меня.

Я обнаружил, что для вашего примера немного легче прочитать все дерево. Итак, используя --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% от бара.

Документация для -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

Это изменяется на использование абсолютных процентов, где каждый процент времени сообщается для этой цепочки вызовов: So foo->bar составляет 26% от общего количества тиков (что в свою очередь вызывает baz) и foo->baz (direct) составляет 12% от общего количества клещей.

Я до сих пор не знаю, почему я не вижу различий между диаграммами вызываемого и вызывающего, хотя с точки зрения __sin_sse2.

Update

Одна вещь, которую я действительно изменил из вашей командной строки, - это то, как собирались callgrraphs. Linux perf по умолчанию использует метод указателя кадра для восстановления стоп-копов. Это может быть проблемой, когда компилятор использует -fomit-frame-pointer как default. Поэтому я использовал

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