使用perf测量到达main函数的时间？
•浏览 1
Measure the time to reach the main function using perf?
我想通过测量到达主函数的时间来测量我的程序初始化时间，这样我就得到了"运行时初始化"的时间(例如，bss 部分设置为 0 并调用了全局构造函数) .
我如何使用 perf 来做到这一点？
将一些可以立即终止进程而很少或根本没有清理的东西，例如 exit_group，作为 main 中的第一件事，然后使用 perf stat(查看任务时钟)或简单地使用 time 来测量进程运行时间。
如果您不需要专门使用 perf，则一种非破坏性方法是使用 clock() 调用，它测量自进程启动以来的 CPU 时间以及对于大多数进程(不启动线程)或在 main 之前阻塞)如果您在 main 开始时发出它，则?等于在 main 之前花费的实际时间。
我经常使用 clock() 和 perf\\ 的 --delay 选项来将启动成本排除在测量之外。这实际上导致了第三种方法 - 在运行时使用和不使用排除启动的 --delay 参数时的统计数据差异。如果您想获取启动部分的时间以外的性能统计信息，这很有用。
首先，您必须考虑到 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 sleepsudo perf record -e probe_gctor:main -e syscalls:sys_exit_execve ./gctor
^ this is what perf probe told you earlier# 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)gdb ./gctor -ex 'b main' -ex 'python import time' -ex 'python ts=time.time()' -ex 'run' -ex 'python print(time.time()-ts)'[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.\
", 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.您现在可以在所有性能工具中使用它，例如：
$ sudo perf probe -x ./gctor main Added new event: probe_gctor:main (on main in ./gctor)perf record -e probe_gctor:main -aR sleepsudo perf record -e probe_gctor:main -e syscalls:sys_exit_execve ./gctor
^ this is what perf probe told you earlier# 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)gdb ./gctor -ex 'b main' -ex 'python import time' -ex 'python ts=time.time()' -ex 'run' -ex 'python print(time.time()-ts)'[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.\
", 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.这确实需要相当高的权限，我将在示例中使用 root。
2) 二进制文件的"开始"是一个明智的点。
我建议使用跟踪点 syscalls:sys_exit_execve。这基本上是在 perf record 开始执行您的二进制文件之后。这适用于我的版本(5.3.7) - 如果它不适合您，您可能需要修补。您当然可以只使用 -e cycles，但随后您会收到不想要的事件的垃圾邮件。
把它放在一起：
$ sudo perf probe -x ./gctor main Added new event: probe_gctor:main (on main in ./gctor)perf record -e probe_gctor:main -aR sleepsudo perf record -e probe_gctor:main -e syscalls:sys_exit_execve ./gctor
^ this is what perf probe told you earlier# 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)gdb ./gctor -ex 'b main' -ex 'python import time' -ex 'python ts=time.time()' -ex 'run' -ex 'python print(time.time()-ts)'[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.\
", 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.然后用perf script --header
查看
$ sudo perf probe -x ./gctor main Added new event: probe_gctor:main (on main in ./gctor)perf record -e probe_gctor:main -aR sleepsudo perf record -e probe_gctor:main -e syscalls:sys_exit_execve ./gctor
^ this is what perf probe told you earlier# 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)gdb ./gctor -ex 'b main' -ex 'python import time' -ex 'python ts=time.time()' -ex 'run' -ex 'python print(time.time()-ts)'[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.\
", 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.您可以从这两个样本中计算它，或者如果您的跟踪中确实只有两个样本，则使用 sample duration。
为了完整性：这是一种使用 gdb:
的方法
$ sudo perf probe -x ./gctor main Added new event: probe_gctor:main (on main in ./gctor)perf record -e probe_gctor:main -aR sleepsudo perf record -e probe_gctor:main -e syscalls:sys_exit_execve ./gctor
^ this is what perf probe told you earlier# 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)gdb ./gctor -ex 'b main' -ex 'python import time' -ex 'python ts=time.time()' -ex 'run' -ex 'python print(time.time()-ts)'[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.\
", 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.这不太准确，在我的系统上大约有 100 毫秒的开销，但它不需要更高的权限。您当然可以通过在 C 中使用 fork/ptrace/exec 构建自己的跑步者来改进这一点。
另一种选择是提供您自己的可执行入口点，该入口点记录时间戳计数器，然后将控制权转移到标准入口点 _start。输入 main 后，您可以从现在减去它以获得 C 或 C 运行时启动的确切循环计数。
工作示例：
$ sudo perf probe -x ./gctor main Added new event: probe_gctor:main (on main in ./gctor)perf record -e probe_gctor:main -aR sleepsudo perf record -e probe_gctor:main -e syscalls:sys_exit_execve ./gctor
^ this is what perf probe told you earlier# 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)gdb ./gctor -ex 'b main' -ex 'python import time' -ex 'python ts=time.time()' -ex 'run' -ex 'python print(time.time()-ts)'[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.\
", 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.