[tip:perf/urgent] perf trace: Show only failing syscalls

2018-04-03 Thread tip-bot for Arnaldo Carvalho de Melo 
Commit-ID:  0a6545bda2756807a089c64352edfc5628c57e6c
Gitweb: https://git.kernel.org/tip/0a6545bda2756807a089c64352edfc5628c57e6c
Author: Arnaldo Carvalho de Melo 
AuthorDate: Thu, 29 Mar 2018 12:22:59 -0300
Committer:  Arnaldo Carvalho de Melo 
CommitDate: Mon, 2 Apr 2018 07:57:37 -0300

perf trace: Show only failing syscalls

For instance:

  # perf probe "vfs_getname=getname_flags:72 pathname=result->name:string"
  Added new event:
probe:vfs_getname(on getname_flags:72 with pathname=result->name:string)

  You can now use it in all perf tools, such as:

  perf record -e probe:vfs_getname -aR sleep 1

  # perf trace --failure sleep 1
 0.043 ( 0.010 ms): sleep/10978 access(filename: /etc/ld.so.preload, mode: 
R) = -1 ENOENT No such file or directory

For reference, here are all the syscalls in this case:

  # perf trace sleep 1
 ? ( ): sleep/10976  ... [continued]: execve()) = 0
   0.027 ( 0.001 ms): sleep/10976 brk() = 0x55bdc2d04000
   0.044 ( 0.010 ms): sleep/10976 access(filename: /etc/ld.so.preload, 
mode: R) = -1 ENOENT No such file or directory
   0.057 ( 0.006 ms): sleep/10976 openat(dfd: CWD, filename: 
/etc/ld.so.cache, flags: CLOEXEC) = 3
   0.064 ( 0.002 ms): sleep/10976 fstat(fd: 3, statbuf: 0x7fffac22b370) = 0
   0.067 ( 0.003 ms): sleep/10976 mmap(len: 111457, prot: READ, flags: 
PRIVATE, fd: 3) = 0x7feec8615000
   0.071 ( 0.001 ms): sleep/10976 close(fd: 3) = 0
   0.080 ( 0.007 ms): sleep/10976 openat(dfd: CWD, filename: 
/lib64/libc.so.6, flags: CLOEXEC) = 3
   0.088 ( 0.002 ms): sleep/10976 read(fd: 3, buf: 0x7fffac22b538, count: 
832) = 832
   0.092 ( 0.001 ms): sleep/10976 fstat(fd: 3, statbuf: 0x7fffac22b3d0) = 0
   0.094 ( 0.002 ms): sleep/10976 mmap(len: 8192, prot: READ|WRITE, flags: 
PRIVATE|ANONYMOUS) = 0x7feec8613000
   0.099 ( 0.004 ms): sleep/10976 mmap(len: 3889792, prot: EXEC|READ, 
flags: PRIVATE|DENYWRITE, fd: 3) = 0x7feec8057000
   0.104 ( 0.007 ms): sleep/10976 mprotect(start: 0x7feec8203000, len: 
2097152) = 0
   0.112 ( 0.005 ms): sleep/10976 mmap(addr: 0x7feec8403000, len: 24576, 
prot: READ|WRITE, flags: PRIVATE|DENYWRITE|FIXED, fd: 3, off: 1753088) = 
0x7feec8403000
   0.120 ( 0.003 ms): sleep/10976 mmap(addr: 0x7feec8409000, len: 14976, 
prot: READ|WRITE, flags: PRIVATE|ANONYMOUS|FIXED) = 0x7feec8409000
   0.128 ( 0.001 ms): sleep/10976 close(fd: 3) = 0
   0.139 ( 0.001 ms): sleep/10976 arch_prctl(option: 4098, arg2: 
140663540761856) = 0
   0.186 ( 0.004 ms): sleep/10976 mprotect(start: 0x7feec8403000, len: 
16384, prot: READ) = 0
   0.204 ( 0.003 ms): sleep/10976 mprotect(start: 0x55bdc0ec3000, len: 
4096, prot: READ) = 0
   0.209 ( 0.004 ms): sleep/10976 mprotect(start: 0x7feec8631000, len: 
4096, prot: READ) = 0
   0.214 ( 0.010 ms): sleep/10976 munmap(addr: 0x7feec8615000, len: 111457) 
= 0
   0.269 ( 0.001 ms): sleep/10976 brk() = 0x55bdc2d04000
   0.271 ( 0.002 ms): sleep/10976 brk(brk: 0x55bdc2d25000) = 0x55bdc2d25000
   0.274 ( 0.001 ms): sleep/10976 brk() = 0x55bdc2d25000
   0.278 ( 0.007 ms): sleep/10976 open(filename: 
/usr/lib/locale/locale-archive, flags: CLOEXEC) = 3
   0.288 ( 0.001 ms): sleep/10976 fstat(fd: 
3, statbuf: 0x7feec8408aa0) = 0
   0.290 ( 0.003 ms): sleep/10976 mmap(len: 113045344, prot: READ, flags: 
PRIVATE, fd: 3) = 0x7feec1488000
   0.297 ( 0.001 ms): sleep/10976 close(fd: 
3) = 0
   0.325 (1000.193 ms): sleep/10976 nanosleep(rqtp: 0x7fffac22c0b0) = 0
1000.560 ( 0.006 ms): sleep/10976 close(fd: 1) = 0
1000.573 ( 0.005 ms): sleep/10976 close(fd: 2) = 0
1000.596 ( ): sleep/10976 exit_group()
  #

And can be done systemwide, etc, with backtraces:

  # perf trace --max-stack=16 --failure sleep 1
 0.048 ( 0.015 ms): sleep/11092 access(filename: /etc/ld.so.preload, mode: 
R) = -1 ENOENT No such file or directory
   __access (inlined)
   dl_main (/usr/lib64/ld-2.26.so)
  #

Or for some specific syscalls:

  # perf trace --max-stack=16 -e openat --failure cat /tmp/rien
  cat: /tmp/rien: No such file or directory
   0.251 ( 0.012 ms): cat/11106 openat(dfd: CWD, filename: /tmp/rien) = -1 
ENOENT No such file or directory
 __libc_open64 (inlined)
 main (/usr/bin/cat)
 __libc_start_main 
(/usr/lib64/libc-2.26.so)
 _start (/usr/bin/cat)
  #

Look for inotify* syscalls that fail, system wide, for 2 seconds, with 
backtraces:

  # perf trace -a --max-stack=16 --failure -e inotify* sleep 2
   819.165 ( 0.058 ms): gmain/1724 inotify_add_watch(fd: 8, 
pathname: /home/acme/~, mask: 16789454) = -1 ENOENT No such file or directory
   __GI_inotify_add_watch (inlined)

[tip:perf/urgent] perf trace: Show only failing syscalls

2018-04-03 Thread tip-bot for Arnaldo Carvalho de Melo 
Commit-ID:  0a6545bda2756807a089c64352edfc5628c57e6c
Gitweb: https://git.kernel.org/tip/0a6545bda2756807a089c64352edfc5628c57e6c
Author: Arnaldo Carvalho de Melo 
AuthorDate: Thu, 29 Mar 2018 12:22:59 -0300
Committer:  Arnaldo Carvalho de Melo 
CommitDate: Mon, 2 Apr 2018 07:57:37 -0300

perf trace: Show only failing syscalls

For instance:

  # perf probe "vfs_getname=getname_flags:72 pathname=result->name:string"
  Added new event:
probe:vfs_getname(on getname_flags:72 with pathname=result->name:string)

  You can now use it in all perf tools, such as:

  perf record -e probe:vfs_getname -aR sleep 1

  # perf trace --failure sleep 1
 0.043 ( 0.010 ms): sleep/10978 access(filename: /etc/ld.so.preload, mode: 
R) = -1 ENOENT No such file or directory

For reference, here are all the syscalls in this case:

  # perf trace sleep 1
 ? ( ): sleep/10976  ... [continued]: execve()) = 0
   0.027 ( 0.001 ms): sleep/10976 brk() = 0x55bdc2d04000
   0.044 ( 0.010 ms): sleep/10976 access(filename: /etc/ld.so.preload, 
mode: R) = -1 ENOENT No such file or directory
   0.057 ( 0.006 ms): sleep/10976 openat(dfd: CWD, filename: 
/etc/ld.so.cache, flags: CLOEXEC) = 3
   0.064 ( 0.002 ms): sleep/10976 fstat(fd: 3, statbuf: 0x7fffac22b370) = 0
   0.067 ( 0.003 ms): sleep/10976 mmap(len: 111457, prot: READ, flags: 
PRIVATE, fd: 3) = 0x7feec8615000
   0.071 ( 0.001 ms): sleep/10976 close(fd: 3) = 0
   0.080 ( 0.007 ms): sleep/10976 openat(dfd: CWD, filename: 
/lib64/libc.so.6, flags: CLOEXEC) = 3
   0.088 ( 0.002 ms): sleep/10976 read(fd: 3, buf: 0x7fffac22b538, count: 
832) = 832
   0.092 ( 0.001 ms): sleep/10976 fstat(fd: 3, statbuf: 0x7fffac22b3d0) = 0
   0.094 ( 0.002 ms): sleep/10976 mmap(len: 8192, prot: READ|WRITE, flags: 
PRIVATE|ANONYMOUS) = 0x7feec8613000
   0.099 ( 0.004 ms): sleep/10976 mmap(len: 3889792, prot: EXEC|READ, 
flags: PRIVATE|DENYWRITE, fd: 3) = 0x7feec8057000
   0.104 ( 0.007 ms): sleep/10976 mprotect(start: 0x7feec8203000, len: 
2097152) = 0
   0.112 ( 0.005 ms): sleep/10976 mmap(addr: 0x7feec8403000, len: 24576, 
prot: READ|WRITE, flags: PRIVATE|DENYWRITE|FIXED, fd: 3, off: 1753088) = 
0x7feec8403000
   0.120 ( 0.003 ms): sleep/10976 mmap(addr: 0x7feec8409000, len: 14976, 
prot: READ|WRITE, flags: PRIVATE|ANONYMOUS|FIXED) = 0x7feec8409000
   0.128 ( 0.001 ms): sleep/10976 close(fd: 3) = 0
   0.139 ( 0.001 ms): sleep/10976 arch_prctl(option: 4098, arg2: 
140663540761856) = 0
   0.186 ( 0.004 ms): sleep/10976 mprotect(start: 0x7feec8403000, len: 
16384, prot: READ) = 0
   0.204 ( 0.003 ms): sleep/10976 mprotect(start: 0x55bdc0ec3000, len: 
4096, prot: READ) = 0
   0.209 ( 0.004 ms): sleep/10976 mprotect(start: 0x7feec8631000, len: 
4096, prot: READ) = 0
   0.214 ( 0.010 ms): sleep/10976 munmap(addr: 0x7feec8615000, len: 111457) 
= 0
   0.269 ( 0.001 ms): sleep/10976 brk() = 0x55bdc2d04000
   0.271 ( 0.002 ms): sleep/10976 brk(brk: 0x55bdc2d25000) = 0x55bdc2d25000
   0.274 ( 0.001 ms): sleep/10976 brk() = 0x55bdc2d25000
   0.278 ( 0.007 ms): sleep/10976 open(filename: 
/usr/lib/locale/locale-archive, flags: CLOEXEC) = 3
   0.288 ( 0.001 ms): sleep/10976 fstat(fd: 
3, statbuf: 0x7feec8408aa0) = 0
   0.290 ( 0.003 ms): sleep/10976 mmap(len: 113045344, prot: READ, flags: 
PRIVATE, fd: 3) = 0x7feec1488000
   0.297 ( 0.001 ms): sleep/10976 close(fd: 
3) = 0
   0.325 (1000.193 ms): sleep/10976 nanosleep(rqtp: 0x7fffac22c0b0) = 0
1000.560 ( 0.006 ms): sleep/10976 close(fd: 1) = 0
1000.573 ( 0.005 ms): sleep/10976 close(fd: 2) = 0
1000.596 ( ): sleep/10976 exit_group()
  #

And can be done systemwide, etc, with backtraces:

  # perf trace --max-stack=16 --failure sleep 1
 0.048 ( 0.015 ms): sleep/11092 access(filename: /etc/ld.so.preload, mode: 
R) = -1 ENOENT No such file or directory
   __access (inlined)
   dl_main (/usr/lib64/ld-2.26.so)
  #

Or for some specific syscalls:

  # perf trace --max-stack=16 -e openat --failure cat /tmp/rien
  cat: /tmp/rien: No such file or directory
   0.251 ( 0.012 ms): cat/11106 openat(dfd: CWD, filename: /tmp/rien) = -1 
ENOENT No such file or directory
 __libc_open64 (inlined)
 main (/usr/bin/cat)
 __libc_start_main 
(/usr/lib64/libc-2.26.so)
 _start (/usr/bin/cat)
  #

Look for inotify* syscalls that fail, system wide, for 2 seconds, with 
backtraces:

  # perf trace -a --max-stack=16 --failure -e inotify* sleep 2
   819.165 ( 0.058 ms): gmain/1724 inotify_add_watch(fd: 8, 
pathname: /home/acme/~, mask: 16789454) = -1 ENOENT No such file or directory
   __GI_inotify_add_watch (inlined)