Измерить время достижения основной функции, используя перф? - PullRequest
Новая
       25

Измерить время достижения основной функции, используя перф?

2 голосов
/ 06 ноября 2019

Я хотел бы измерить время инициализации моей программы, измерив время достижения основной функции, чтобы я получил время "инициализации во время выполнения" (например, для разделов bss установлено значение 0 и вызваны глобальные конструкторы).

Как я могу использовать perf для этого?

Ответы [ 3 ]

2 голосов
/ 07 ноября 2019

Поместите что-нибудь, что немедленно завершает процесс, практически без очистки, например, exit_group , в качестве первого шага в main, а затем используйте perf stat (глядя на часы-задачи) или просто time, чтобыизмерить время выполнения процесса.

Если вам не нужно специально использовать perf, неразрушающим способом является использование вызова clock(), который измеряет время ЦП с момента запуска процесса и для большинства процессов (которые не запускаются)потоков или блока перед main) равно реальному времени, потраченному перед main, если вы запускаете его в начале main.

Я часто использую clock() вместе с опцией perf --delay для exclude начальные затраты от измерения. Это на самом деле приводит к третьему подходу - учитывает разницу в статистике между запуском с и без аргумента --delay, который исключает запуск. Это полезно, если вы хотите получить статистику производительности, отличную от времени для начальной загрузки.

2 голосов
/ 06 ноября 2019

Во-первых, вы должны учитывать, что perf на самом деле не измеряет время - он записывает события. Теперь вы можете выполнить некоторое профилирование, просмотреть стеки вызовов и получить некоторую информацию об инициализации, но для измерения определенного времени нам нужно записать начальную и конечную временную метку.

В случае время достижения функции main , мы можем использовать

1) Динамическую точку трассировки на main: 

$ sudo perf probe -x ./gctor main Added new event:   probe_gctor:main  (on main in ./gctor)

Теперь вы можете использовать ее во всех инструментах перфорации,например: 

perf record -e probe_gctor:main -aR sleep

Для этого требуются довольно высокие привилегии, в этом примере я просто использую root.

2) Разумная точка для "запуска" вашего двоичного файла.

Я предлагаю точку трассировки syscalls:sys_exit_execve. Это в основном сразу после того, как perf record начал выполнять ваш двоичный файл. Это работает в моей версии (5.3.7) - если это не для вас, вам, возможно, придется повозиться. Конечно, вы могли бы просто использовать -e cycles, но потом вы получите спам с событиями, которые вам не нужны.

Соберите все вместе: 

sudo perf record -e probe_gctor:main -e syscalls:sys_exit_execve ./gctor
                  ^ this is what perf probe told you earlier

И затем посмотрите на это с помощьюperf script --header

# time of first sample : 77582.919313
# time of last sample : 77585.150377
# sample duration :   2231.064 ms
[....]
# ========
#
           gctor 238828 [007] 77582.919313: syscalls:sys_exit_execve: 0x0
           gctor 238828 [001] 77585.150377:         probe_gctor:main: (5600ea33414d)

Вы можете либо вычислить его по этим двум выборкам, либо использовать sample duration, если в вашей трассе действительно только два образца.

Для полноты: Вотспособ сделать это с помощью gdb: 

gdb ./gctor -ex 'b main' -ex 'python import time' -ex 'python ts=time.time()' -ex 'run' -ex 'python print(time.time()-ts)'

Это гораздо менее точно, с нагрузкой в ​​моей системе около 100 мс, но не требует более высоких привилегий. Конечно, вы могли бы улучшить это, просто создав собственного бегуна с fork/ptrace/exec в C.

1 голос
/ 07 ноября 2019

Другой вариант - предоставить собственную исполняемую точку входа, которая записывает счетчик меток времени, а затем передает управление на стандартную точку входа _start. Когда введено main, вы можете вычесть это, чтобы получить точное число циклов запуска C или C ++ при запуске.

Рабочий пример: 

[max@supernova:~/src/test] $ cat test.cc
#include <stdint.h>
#include <stdio.h>

extern uint64_t start_tsc;

int main() {
    uint64_t main_tsc = __builtin_ia32_rdtsc();
    printf("C/C++ run-time start took %lu cycles.\n", main_tsc - start_tsc);
}

[max@supernova:~/src/test] $ cat mystart.asm
        global mystart
        global start_tsc
        extern _start

        section .text
mystart:
        push rdx
        rdtsc
        shl rdx, 32
        or rax, rdx
        mov [rel start_tsc], rax
        pop rdx
        jmp _start

        section .data
start_tsc:
        dq 0

[max@supernova:~/src/test] $ make
g++ -o test.o -c -W{all,extra,error} -g -Og test.cc
nasm -felf64 -o mystart.o mystart.asm
g++ -o test -g -Wl,-emystart test.o mystart.o 

[max@supernova:~/src/test] $ ./test
C/C++ run-time start took 5314 cycles.
...