2

I can use perf trace as a low-overhead replacement for strace, e.g. to trace all Apache instances:

perf trace -p $(pidof apache2 | tr ' ' ',')

To run the trace only for up to 10 seconds:

perf trace -p $(pidof apache2 | tr ' ' ',') -- sleep 10

Some example output:

server ~ # perf trace -p $(pidof apache2 | tr ' ' ',') -- sleep 10 2>&1 | head
         ? (         ): apache2/8661  ... [continued]: poll()) = 0 Timeout
     0.022 ( 0.005 ms): apache2/8661 close(fd: 28                                                          ) = 0
     0.066 ( 0.007 ms): apache2/8661 read(fd: 13<pipe:[3452760950]>, buf: 0x7ffe815038ff, count: 1         ) = -1 EAGAIN Resource temporarily unavailable
         ? (         ): apache2/26492  ... [continued]: semop()) = 0
     0.088 (         ): apache2/8661 semop(semid: 557481986, tsops: 0x7f846e0cfd6c, nsops: 1               ) ...
         ? (         ): apache2/7580  ... [continued]: epoll_wait()) = 1
    46.136 (         ): apache2/26492 epoll_wait(epfd: 27<anon_inode:[eventpoll]>, events: 0x7f846dd0c698, maxevents: 5, timeout: 10000) ...
    46.081 ( 0.013 ms): apache2/7580 accept4(fd: 12<socket:[3452759675]>, upeer_sockaddr: 0x7ffe81503830, upeer_addrlen: 0x7ffe81503810, flags: 524288) = 28
    46.100 ( 0.010 ms): apache2/7580 semop(semid: 557481986, tsops: 0x7f846e0cfd60, nsops: 1               ) = 0
    46.116 ( 0.002 ms): apache2/7580 getsockname(fd: 28<socket:[3465711918]>, usockaddr: 0x7f846dd0a130, usockaddr_len: 0x7f846dd0a110) = 0

This works as expected. Now I want to record these events in a file so that I can later analyze them in detail. I had expected that perf trace record does this, but I'm not even sure if this is recording properly:

server ~ # perf trace record -p $(pidof apache2 | tr ' ' ',') -- sleep 10
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0,312 MB perf.data (67 samples) ]

perf trace ... | wc -l amounts to ~12000 lines, so why does record only record 67 samples?

I'm not even sure what the correct command is to read this file; the man page unfortunately doesn't say. I'd assumed it's perf trace -i perf.data, but that doesn't print anything:

server ~ # perf trace -i perf.data
server ~ # 

perf script does print something, but it doesn't look like the perf trace output:

server ~ # perf script | head
         apache2 10215 [002] 29556325.787512:          1 cycles:ppp:  ffffffff83e5a704 native_write_msr+0x4 ([kernel.kallsyms])
         apache2 20085 [006] 29556325.787597:          1 cycles:ppp:  ffffffff83e5a704 native_write_msr+0x4 ([kernel.kallsyms])
         apache2 20754 [000] 29556325.790512:          1 cycles:ppp:  ffffffff83e5a704 native_write_msr+0x4 ([kernel.kallsyms])
         apache2  7580 [007] 29556325.790757:          1 cycles:ppp:  ffffffff83e5a704 native_write_msr+0x4 ([kernel.kallsyms])
         apache2  8661 [001] 29556325.796044:          1 cycles:ppp:  ffffffff83e5a704 native_write_msr+0x4 ([kernel.kallsyms])
         apache2 10215 [006] 29556325.796845:          1 cycles:ppp:  ffffffff83e5a704 native_write_msr+0x4 ([kernel.kallsyms])
         apache2 20085 [004] 29556325.798481:          1 cycles:ppp:  ffffffff83e5a704 native_write_msr+0x4 ([kernel.kallsyms])
         apache2 10215 [004] 29556325.802922:          1 cycles:ppp:  ffffffff83e5a704 native_write_msr+0x4 ([kernel.kallsyms])
         apache2 20754 [001] 29556325.815999:          1 cycles:ppp:  ffffffff83e5a704 native_write_msr+0x4 ([kernel.kallsyms])
         apache2 20085 [003] 29556325.816025:          1 cycles:ppp:  ffffffff83e5a704 native_write_msr+0x4 ([kernel.kallsyms])
0

1 Answer 1

2

Your hunch is correct, perf trace record isn’t recording enough data; man perf-trace suggests that it takes care of it itself, but you need to record syscalls:

perf trace record -e 'raw_syscalls:*' ...

Then

perf trace -i perf.data

will work as you’d expect.

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .