CODEWITHSUNDEEP
linuxprofilingperfstrace
Joseph Garvin
Joseph Garvin

Reputation: 21936

How to measure how long file related system calls are taking in perf?

I have an application which is running unusually slow. I have reason to suspect that this may be because some specific files are slower to read from and stat.

I know I can use strace to get timing information, but I'd prefer to use perf because the overhead is so much lower.

Brendan Gregg has some helpful examples of using perf:

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

But his first system call example only shows aggregate timings across all calls and I need per-file timings. His second system call example doesn't include timings, and only shows fd numbers, not real paths.

How do I piece this together? I'm looking to get something similar to what I would get from “strace -Tttt -e trace=file”.

Added bonus would be if I can measure cycles at the same time.

Upvotes: 4

Views: 2820

Answers (1)

osgx
osgx

Reputation: 94225

Output from strace -Tttt -e trace=file is trace (tracing tool), and perf is usually used as profiling tool (aggregating time spent in function by name - in perf record by default on time or on hardware events + perf report, perf top modes) or as statistics tool (in perf stat mode - with counting of some events over all running time of the program).

You should try some tracing tool (trace-cmd, sysdig, lttng, ...) or you can try to use perf in tracing modes (perf record with tracepoints and perf script to output non-aggregated log over time)

There are tracepoints for syscalls (syscalls 614): http://www.brendangregg.com/perf.html#Tracepoints http://www.brendangregg.com/perf.html#StaticKernelTracing

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

Example of output with format: 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

You may also try perf record -g -e 'syscalls:sys_*' to record function backtrace (to get information which function of the application did the syscall, and who did call this function; works better with debug information).

perf as tracing tool may not decode syscall (tracepoint) arguments; and tracing tools like trace-cmd or lttng may decode them better (at least decoding file name in open syscall).

Upvotes: 5

Related Questions