linux - 如何测量与文件相关的系统调用在 perf 中花费了多长时间？

Question

我有一个运行异常缓慢的应用程序。我有理由怀疑这可能是因为某些特定文件的读取和统计速度较慢。

我知道我可以使用 strace 获取计时信息，但我更愿意使用 perf，因为开销要低得多。

Brendan Gregg 有一些使用 perf 的有用示例:

http://www.brendangregg.com/perf.html

但他的第一个系统调用示例仅显示所有调用的总计时，我需要每个文件的计时。他的第二个系统调用示例不包括时间，只显示 fd 数字，而不是真实路径。

我如何将它们拼凑起来？我正在寻找类似于我从“strace -Tttt -e trace=file”中得到的东西。

如果我可以同时测量周期，那将是额外的好处。

Answer 1

strace -Tttt -e trace=file 的输出是 trace(跟踪工具)，perf 通常用作分析工具(按名称汇总在函数中花费的时间 - 在 perf 记录中 默认按时间或硬件事件 + perf report、perf top 模式)或作为统计工具(在 perf stat 模式下) - 在程序的整个运行时间内对一些事件进行计数)。

您应该尝试一些跟踪工具(trace-cmd、sysdig、lttng、...)或者您可以尝试在跟踪模式下使用perf(perf record 使用跟踪点和 perf 脚本 随时间输出非聚合日志)

有系统调用的跟踪点(syscalls 614): http://www.brendangregg.com/perf.html#Tracepoints http://www.brendangregg.com/perf.html#StaticKernelTracing

perf record -e 'syscalls:sys_*' ./program
perf script

格式输出示例:process_name, pid, [cpu_core], time_since_boot_seconds.microseconds:, tracepoint_name, tracepoint_arguments

          ls 19178 [001]  16529.466566:                   syscalls:sys_enter_open: filename: 0x7f6ae4c38f82, flags: 0x00080000, mode: 0x
          ls 19178 [001]  16529.466570:                    syscalls:sys_exit_open: 0x4
          ls 19178 [001]  16529.466570:               syscalls:sys_enter_newfstat: fd: 0x00000004, statbuf: 0x7ffe22df92f0
          ls 19178 [001]  16529.466572:                syscalls:sys_exit_newfstat: 0x0
          ls 19178 [001]  16529.466573:                   syscalls:sys_enter_mmap: addr: 0x00000000, len: 0x00042e6f, prot: 0x00000001,
          ls 19178 [001]  16529.466767:                    syscalls:sys_exit_mmap: 0x7f6ae4df8000
          ls 19178 [001]  16529.466768:                  syscalls:sys_enter_close: fd: 0x00000004
          ls 19178 [001]  16529.466769:                   syscalls:sys_exit_close: 0x0

您也可以尝试使用 perf record -g -e 'syscalls:sys_*' 来记录函数回溯(以获取应用程序的哪个函数进行了系统调用以及谁调用了该函数的信息；与调试信息配合使用效果更好)。

perf 作为跟踪工具可能无法解码系统调用(跟踪点)参数； trace-cmd 或 lttng 等跟踪工具可能会更好地解码它们(至少在打开的系统调用中解码文件名)。