1. 18 5月, 2018 1 次提交
  2. 27 4月, 2018 2 次提交
  3. 04 4月, 2018 1 次提交
  4. 02 4月, 2018 1 次提交
    • A
      perf trace: Show only failing syscalls · 0a6545bd
      Arnaldo Carvalho de Melo 提交于
      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</usr/lib/locale/locale-archive>, 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</usr/lib/locale/locale-archive>) = 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<anon_inode:inotify>, pathname: /home/acme/~, mask: 16789454) = -1 ENOENT No such file or directory
                                             __GI_inotify_add_watch (inlined)
                                             _ik_watch (/usr/lib64/libgio-2.0.so.0.5400.3)
                                             _ip_start_watching (/usr/lib64/libgio-2.0.so.0.5400.3)
                                             im_scan_missing (/usr/lib64/libgio-2.0.so.0.5400.3)
                                             g_timeout_dispatch (/usr/lib64/libglib-2.0.so.0.5400.3)
                                             g_main_context_dispatch (/usr/lib64/libglib-2.0.so.0.5400.3)
                                             g_main_context_iterate.isra.23 (/usr/lib64/libglib-2.0.so.0.5400.3)
                                             g_main_context_iteration (/usr/lib64/libglib-2.0.so.0.5400.3)
                                             glib_worker_main (/usr/lib64/libglib-2.0.so.0.5400.3)
                                             g_thread_proxy (/usr/lib64/libglib-2.0.so.0.5400.3)
                                             start_thread (/usr/lib64/libpthread-2.26.so)
                                             __GI___clone (inlined)
        #
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-8f7d3mngaxvi7tlzloz3n7cs@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      0a6545bd
  5. 08 3月, 2018 3 次提交
  6. 07 3月, 2018 1 次提交
    • A
      perf trace: Support setting cgroups as targets · 9ea42ba4
      Arnaldo Carvalho de Melo 提交于
      One can set a cgroup as a default cgroup to be used by all events or
      set cgroups with the 'perf stat' and 'perf record' behaviour, i.e.
      '-G A' will be the cgroup for events defined so far in the command line.
      
      Here in my main machine, with a kvm instance running a rhel6 guinea pig
      I have:
      
        # ls -la /sys/fs/cgroup/perf_event/ | grep drw
        drwxr-xr-x. 14 root root 360 Mar  6 12:04 ..
        drwxr-xr-x.  3 root root   0 Mar  6 15:05 machine.slice
        #
      
      So I can go ahead and use that cgroup hierarchy, say lets see what
      syscalls are being emitted by threads in that 'machine.slice' hierarchy
      that are taking more than 100ms:
      
        # perf trace --duration 100 -G machine.slice
           0.188 (249.850 ms): CPU 0/KVM/23744 ioctl(fd: 16<anon_inode:kvm-vcpu:0>, cmd: KVM_RUN) = 0
         250.274 (249.743 ms): CPU 0/KVM/23744 ioctl(fd: 16<anon_inode:kvm-vcpu:0>, cmd: KVM_RUN) = 0
         500.224 (249.755 ms): CPU 0/KVM/23744 ioctl(fd: 16<anon_inode:kvm-vcpu:0>, cmd: KVM_RUN) = 0
         750.097 (249.934 ms): CPU 0/KVM/23744 ioctl(fd: 16<anon_inode:kvm-vcpu:0>, cmd: KVM_RUN) = 0
        1000.244 (249.780 ms): CPU 0/KVM/23744 ioctl(fd: 16<anon_inode:kvm-vcpu:0>, cmd: KVM_RUN) = 0
        1250.197 (249.796 ms): CPU 0/KVM/23744 ioctl(fd: 16<anon_inode:kvm-vcpu:0>, cmd: KVM_RUN) = 0
        1500.124 (249.859 ms): CPU 0/KVM/23744 ioctl(fd: 16<anon_inode:kvm-vcpu:0>, cmd: KVM_RUN) = 0
        1750.076 (172.900 ms): CPU 0/KVM/23744 ioctl(fd: 16<anon_inode:kvm-vcpu:0>, cmd: KVM_RUN) = 0
         902.570 (1021.116 ms): qemu-system-x8/23667 ppoll(ufds: 0x558151e03180, nfds: 74, tsp: 0x7ffc00cd0900, sigsetsize: 8) = 1
        1923.825 (305.133 ms): qemu-system-x8/23667 ppoll(ufds: 0x558151e03180, nfds: 74, tsp: 0x7ffc00cd0900, sigsetsize: 8) = 1
        2000.172 (229.002 ms): CPU 0/KVM/23744 ioctl(fd: 16<anon_inode:kvm-vcpu:0>, cmd: KVM_RUN) = 0
      ^C  #
      
      If we look inside that cgroup hierarchy we get:
      
        # ls -la /sys/fs/cgroup/perf_event/machine.slice/ | grep drw
        drwxr-xr-x. 3 root root 0 Mar  6 15:05 .
        drwxr-xr-x. 2 root root 0 Mar  6 16:16 machine-qemu\x2d2\x2drhel6.sandy.scope
        #
      
      There is just one, but lets say there were more and we would want to see
      5 seconds worth of syscall summary for the threads in that cgroup:
      
        # perf trace --summary -G machine.slice/machine-qemu\\x2d2\\x2drhel6.sandy.scope/ -a sleep 5
      
         Summary of events:
      
           qemu-system-x86 (23667), 143858 events, 24.2%
      
           syscall            calls    total       min       avg       max      stddev
                                       (msec)    (msec)    (msec)    (msec)        (%)
           --------------- -------- --------- --------- --------- ---------     ------
           ppoll              28492  4348.631     0.000     0.153    11.616      1.05%
           futex              19661   140.801     0.001     0.007     2.993      3.20%
           read               18440    68.084     0.001     0.004     1.653      4.33%
           ioctl               5387    24.768     0.002     0.005     0.134      1.62%
      
           CPU 0/KVM (23744), 449455 events, 75.8%
      
           syscall            calls    total       min       avg       max      stddev
                                     (msec)    (msec)    (msec)    (msec)        (%)
           --------------- -------- --------- --------- --------- ---------     ------
           ioctl             148364  3401.812     0.000     0.023    11.801      1.15%
           futex              36131   404.127     0.001     0.011     7.377      2.63%
           writev             29452   339.688     0.003     0.012     1.740      1.36%
           write              11315    45.992     0.001     0.004     0.105      1.10%
      
        #
      
      See the documentation about how to set more than one cgroup for
      different events in the same command line.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Hendrik Brueckner <brueckner@linux.vnet.ibm.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Ravi Bangoria <ravi.bangoria@linux.vnet.ibm.com>
      Cc: Stephane Eranian <eranian@google.com>
      Cc: Thomas Richter <tmricht@linux.vnet.ibm.com>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-t126jh4occqvu0xdqlcjygex@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      9ea42ba4
  7. 05 3月, 2018 1 次提交
  8. 06 2月, 2018 1 次提交
    • R
      perf trace: Fix call-graph output · 3a9e9a47
      Ravi Bangoria 提交于
      Recently, Arnaldo fixed global vs event specific --max-stack usage with
      commit bd3dda9a ("perf trace: Allow overriding global --max-stack
      per event"). This commit is having a regression when we don't use
      --max-stack at all with perf trace. Ex,
      
        $ ./perf trace record -g ls
        $ ./perf trace -i perf.data
           0.076 ( 0.002 ms): ls/9109 brk(
           0.196 ( 0.008 ms): ls/9109 access(filename: 0x9f998b70, mode: R
           0.209 ( 0.031 ms): ls/9109 open(filename: 0x9f998978, flags: CLOEXEC
      
      This is missing call-traces.
      After patch:
      
        $ ./perf trace -i perf.data
           0.076 ( 0.002 ms): ls/9109 brk(
                                      do_syscall_trace_leave ([kernel.kallsyms])
                                      [0] ([unknown])
                                      syscall_exit_work ([kernel.kallsyms])
                                      brk (/usr/lib64/ld-2.17.so)
                                      _dl_sysdep_start (/usr/lib64/ld-2.17.so)
                                      _dl_start_final (/usr/lib64/ld-2.17.so)
                                      _dl_start (/usr/lib64/ld-2.17.so)
                                      _start (/usr/lib64/ld-2.17.so)
           0.196 ( 0.008 ms): ls/9109 access(filename: 0x9f998b70, mode: R
                                      do_syscall_trace_leave ([kernel.kallsyms])
                                      [0] ([unknown])
      Signed-off-by: NRavi Bangoria <ravi.bangoria@linux.vnet.ibm.com>
      Tested-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
      Cc: Jiri Olsa <jolsa@redhat.com>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Fixes: bd3dda9a ("perf trace: Allow overriding global --max-stack per event")
      Link: http://lkml.kernel.org/r/20180130053053.13214-3-ravi.bangoria@linux.vnet.ibm.comSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      3a9e9a47
  9. 25 1月, 2018 5 次提交
    • A
      perf trace beauty flock: Move to separate object file · c19d0847
      Arnaldo Carvalho de Melo 提交于
      To resolve some header conflicts that were preventing the build to
      succeed in the Alpine Linux distribution.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-bvud0dvzvip3kibeplupdbmc@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      c19d0847
    • A
      perf evlist: Remove fcntl.h from evlist.h · bafae98e
      Arnaldo Carvalho de Melo 提交于
      Not needed there, fixup the places where it is needed and was getting
      only by luck via evlist.h.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-yxjpetn64z8vjuguu84gr6x6@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      bafae98e
    • A
      perf trace beauty futex: Beautify FUTEX_BITSET_MATCH_ANY · 3258abe0
      Arnaldo Carvalho de Melo 提交于
      E.g.:
      
        # strace -e futex -p 14437
        strace: Process 14437 attached
        futex(0x7f46f4808d70, FUTEX_WAKE_PRIVATE, 1) = 0
        futex(0x7f46f24e68b0, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, {tv_sec=1516636744, tv_nsec=221969000}, 0xffffffff) = -1 ETIMEDOUT (Connection timed out)
       <detached ...>
        #
      
      Should pretty print that 0xffffffff value, like:
      
        # trace -e futex --tid 14437
           0.028 (   0.005 ms): futex(uaddr: 0x7f46f4808d70, op: WAKE|PRIV, val: 1                    ) = 0
           0.037 (1000.092 ms): futex(uaddr: 0x7f46f24e68b0, op: WAIT_BITSET|PRIV|CLKRT, utime: 0x7f46f23fedf0, val3: MATCH_ANY) = -1 ETIMEDOUT Connection timed out
      ^C#
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-raef6e352la90600yksthao1@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      3258abe0
    • A
      perf trace: Do not print from time delta for interrupted syscall lines · 522283fe
      Arnaldo Carvalho de Melo 提交于
      We were calculating the delta from a in-flight syscall that got its
      output interrupted by another syscall, which doesn't seem like useful
      information, we will print the syscall duration (sys_exit - sys_enter)
      when the raw_syscalls:sys_exit event happens.
      
      The problem here is how we're consuming the multiple ring buffers,
      without using the ordered_events code used by perf_session, which may
      cause some reordering of syscalls for diferent CPUs, so just stop
      printing that delta, to avoid things like:
      
        # trace --print-sample -p 9626 -e futex
        raw_syscalls:sys_enter 411967179.269 Timer 9609/9626 [2]
        raw_syscalls:sys_enter 411967179.213 file:// Content 9609/9609 [3]
           328.038 (18446744073709.496 ms): Timer/9626 futex(uaddr: 0x7fc0d4027044, op: WAIT|PRIV, utime: 0x7fc0b0ffdb50     ) ...
         raw_syscalls:sys_exit 411967179.225 file:// Content 9609/9609 [3]
           327.982 ( 0.012 ms): file:// Conten/9609 futex(uaddr: 0x7fc0d4027040, op: WAKE|PRIV, val: 1                    ) = 1
      
      This is a bandaid, we should better try and use the ordered_events code,
      possibly with some refactoring prep work, but for now at least we don't
      show those false long deltas for the lines ending in '...'.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-q6xgsqrju1sr6ltud9kjjhmb@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      522283fe
    • A
      perf trace: Add --print-sample · 591421e1
      Arnaldo Carvalho de Melo 提交于
      To help with debugging, like the interrupted out of order issue that
      will be dealt with in the next patch in this series, changing the code
      to deal with:
      
      raw_syscalls:sys_enter 411967179.269 Timer 9609/9626 [2]
      raw_syscalls:sys_enter 411967179.213 file:// Content 9609/9609 [3]
         328.038 (18446744073709.496 ms): Timer/9626 futex(uaddr: 0x7fc0d4027044, op: WAIT|PRIV, utime: 0x7fc0b0ffdb50     ) ...
       raw_syscalls:sys_exit 411967179.225 file:// Content 9609/9609 [3]
         327.982 ( 0.012 ms): file:// Conten/9609 futex(uaddr: 0x7fc0d4027040, op: WAKE|PRIV, val: 1                    ) = 1
      
      That long duration is the bug.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-fljqiibjn7wet24jd1ed7abc@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      591421e1
  10. 23 1月, 2018 1 次提交
  11. 17 1月, 2018 2 次提交
    • A
      perf trace: Allow overriding global --max-stack per event · bd3dda9a
      Arnaldo Carvalho de Melo 提交于
      The per-event max-stack setting wasn't overriding the global --max-stack
      setting:
      
        # perf trace --no-syscalls --max-stack 4 -e probe_libc:inet_pton/call-graph=dwarf,max-stack=2/ ping -6 -c 1 ::1
        PING ::1(::1) 56 data bytes
        64 bytes from ::1: icmp_seq=1 ttl=64 time=0.072 ms
      
        --- ::1 ping statistics ---
        1 packets transmitted, 1 received, 0% packet loss, time 0ms
        rtt min/avg/max/mdev = 0.072/0.072/0.072/0.000 ms
             0.000 probe_libc:inet_pton:(7feb7a998350))
                                               __inet_pton (inlined)
                                               gaih_inet.constprop.7 (/usr/lib64/libc-2.26.so)
                                               __GI_getaddrinfo (inlined)
                                               [0xffffaa39b6108f3f] (/usr/bin/ping)
        #
      
      Fix it:
      
        # perf trace --no-syscalls --max-stack 4 -e probe_libc:inet_pton/call-graph=dwarf,max-stack=2/ ping -6 -c 1 ::1
        PING ::1(::1) 56 data bytes
        64 bytes from ::1: icmp_seq=1 ttl=64 time=0.073 ms
      
        --- ::1 ping statistics ---
        1 packets transmitted, 1 received, 0% packet loss, time 0ms
        rtt min/avg/max/mdev = 0.073/0.073/0.073/0.000 ms
             0.000 probe_libc:inet_pton:(7f1083221350))
                                               __inet_pton (inlined)
                                               gaih_inet.constprop.7 (/usr/lib64/libc-2.26.so)
        #
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Hendrick Brueckner <brueckner@linux.vnet.ibm.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Thomas Richter <tmricht@linux.vnet.ibm.com>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-ic3g837xg8ob3kcpkspxwz0g@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      bd3dda9a
    • A
      perf trace: Setup DWARF callchains for non-syscall events when --max-stack is used · 75d50117
      Arnaldo Carvalho de Melo 提交于
      If we use:
      
      	perf trace --max-stack=4
      
      then the syscall events will use DWARF callchains, when available
      (libunwind enabled in the build) and the printing will stop at 4 levels.
      
      When we introduced support for tracepoint events this ended up not
      applying for them, fix it.
      
      Before:
      
        # perf trace --call-graph=dwarf --no-syscalls -e probe_libc:inet_pton ping -6 -c 1 ::1
        PING ::1(::1) 56 data bytes
        64 bytes from ::1: icmp_seq=1 ttl=64 time=0.058 ms
      
        --- ::1 ping statistics ---
        1 packets transmitted, 1 received, 0% packet loss, time 0ms
        rtt min/avg/max/mdev = 0.058/0.058/0.058/0.000 ms
             0.000 probe_libc:inet_pton:(7fc6c2a16350))
        #
      
      After:
      
        # perf trace --call-graph=dwarf --no-syscalls -e probe_libc:inet_pton ping -6 -c 1 ::1
        PING ::1(::1) 56 data bytes
        64 bytes from ::1: icmp_seq=1 ttl=64 time=0.087 ms
      
        --- ::1 ping statistics ---
        1 packets transmitted, 1 received, 0% packet loss, time 0ms
        rtt min/avg/max/mdev = 0.087/0.087/0.087/0.000 ms
             0.000 probe_libc:inet_pton:(7fbf9a041350))
                                               __inet_pton (inlined)
                                               gaih_inet.constprop.7 (/usr/lib64/libc-2.26.so)
                                               __GI_getaddrinfo (inlined)
                                               [0xffffaa947cb67f3f] (/usr/bin/ping)
                                               __libc_start_main (/usr/lib64/libc-2.26.so)
                                               [0xffffaa947cb68379] (/usr/bin/ping)
        #
      Reported-by: NThomas Richter <tmricht@linux.vnet.ibm.com>
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Hendrick Brueckner <brueckner@linux.vnet.ibm.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-afsu9eegd43ppihiuafhh9qv@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      75d50117
  12. 13 1月, 2018 2 次提交
    • A
      perf trace: Fix setting of --call-graph/--max-stack for non-syscall events · 08e26396
      Arnaldo Carvalho de Melo 提交于
      The raw_syscalls:sys_{enter,exit} were first supported in 'perf trace',
      together with minor and major page faults, then we supported
      --call-graph, then --max-stack, but when the other tracepoints got
      supported, and bpf, etc, I forgot to make those global call-graph
      settings apply to them.
      
      Fix it by realizing that the global --max-stack and --call-graph
      settings are done via:
      
              OPT_CALLBACK(0, "call-graph", &trace.opts,
                           "record_mode[,record_size]", record_callchain_help,
                           &record_parse_callchain_opt),
      
      And then, when we go to parse the events in -e via:
      
              OPT_CALLBACK('e', "event", &trace, "event",
                           "event/syscall selector. use 'perf list' to list available events",
                           trace__parse_events_option),
      
      And trace__parse_sevents_option() calls:
      
                      struct option o = OPT_CALLBACK('e', "event", &trace->evlist, "event",
                                                     "event selector. use 'perf list' to list available events",
                                                     parse_events_option);
                      err = parse_events_option(&o, lists[0], 0);
      
      parse_events_option() will override the global --call-graph and
      --max-stack if the "call-graph" and/or "max-stack" terms are in the
      event definition, such as in the probe_libc:inet_pton event in one of the
      examples below (-e probe_libc:inet_pton/max-stack=2).
      
      Before:
      
        # perf trace --mmap 1024 --call-graph dwarf -e sendto,probe_libc:inet_pton ping -6 -c 1 ::1
             1.525 (         ): probe_libc:inet_pton:(7f77f3ac9350))
        PING ::1(::1) 56 data bytes
        64 bytes from ::1: icmp_seq=1 ttl=64 time=0.071 ms
      
        --- ::1 ping statistics ---
        1 packets transmitted, 1 received, 0% packet loss, time 0ms
        rtt min/avg/max/mdev = 0.071/0.071/0.071/0.000 ms
             1.677 ( 0.081 ms): ping/31296 sendto(fd: 3, buff: 0x55681b652720, len: 64, addr: 0x55681b650640, addr_len: 28) = 64
                                               __libc_sendto (/usr/lib64/libc-2.26.so)
                                               [0xffffaa97e4bc9cef] (/usr/bin/ping)
                                               [0xffffaa97e4bc656d] (/usr/bin/ping)
                                               [0xffffaa97e4bc7d0a] (/usr/bin/ping)
                                               [0xffffaa97e4bca447] (/usr/bin/ping)
                                               [0xffffaa97e4bc2f91] (/usr/bin/ping)
                                               __libc_start_main (/usr/lib64/libc-2.26.so)
                                               [0xffffaa97e4bc3379] (/usr/bin/ping)
        #
      
      After:
      
        # perf trace --mmap 1024 --call-graph dwarf -e sendto,probe_libc:inet_pton ping -6 -c 1 ::1
        PING ::1(::1) 56 data bytes
        64 bytes from ::1: icmp_seq=1 ttl=64 time=0.089 ms
      
        --- ::1 ping statistics ---
        1 packets transmitted, 1 received, 0% packet loss, time 0ms
        rtt min/avg/max/mdev = 0.089/0.089/0.089/0.000 ms
             1.955 (         ): probe_libc:inet_pton:(7f383a311350))
                                               __inet_pton (inlined)
                                               gaih_inet.constprop.7 (/usr/lib64/libc-2.26.so)
                                               __GI_getaddrinfo (inlined)
                                               [0xffffaa5d91444f3f] (/usr/bin/ping)
                                               __libc_start_main (/usr/lib64/libc-2.26.so)
                                               [0xffffaa5d91445379] (/usr/bin/ping)
             2.140 ( 0.101 ms): ping/32047 sendto(fd: 3, buff: 0x55a26edd0720, len: 64, addr: 0x55a26edce640, addr_len: 28) = 64
                                               __libc_sendto (/usr/lib64/libc-2.26.so)
                                               [0xffffaa5d9144bcef] (/usr/bin/ping)
                                               [0xffffaa5d9144856d] (/usr/bin/ping)
                                               [0xffffaa5d91449d0a] (/usr/bin/ping)
                                               [0xffffaa5d9144c447] (/usr/bin/ping)
                                               [0xffffaa5d91444f91] (/usr/bin/ping)
                                               __libc_start_main (/usr/lib64/libc-2.26.so)
                                               [0xffffaa5d91445379] (/usr/bin/ping)
        #
      
      Same thing for --max-stack, the global one:
      
        # perf trace --max-stack 3 -e sendto,probe_libc:inet_pton ping -6 -c 1 ::1
        PING ::1(::1) 56 data bytes
        64 bytes from ::1: icmp_seq=1 ttl=64 time=0.097 ms
      
        --- ::1 ping statistics ---
        1 packets transmitted, 1 received, 0% packet loss, time 0ms
        rtt min/avg/max/mdev = 0.097/0.097/0.097/0.000 ms
             1.577 (         ): probe_libc:inet_pton:(7f32f3957350))
                                               __inet_pton (inlined)
                                               gaih_inet.constprop.7 (/usr/lib64/libc-2.26.so)
                                               __GI_getaddrinfo (inlined)
             1.738 ( 0.108 ms): ping/32103 sendto(fd: 3, buff: 0x55c3132d7720, len: 64, addr: 0x55c3132d5640, addr_len: 28) = 64
                                               __libc_sendto (/usr/lib64/libc-2.26.so)
                                               [0xffffaa3cecf44cef] (/usr/bin/ping)
                                               [0xffffaa3cecf4156d] (/usr/bin/ping)
        #
      
      And then setting up a global setting (dwarf, max-stack=4), that will
      affect the raw_syscall:sys_enter for the 'sendto' syscall and that will
      be overriden in the probe_libc:inet_pton call to just one entry.
      
        # perf trace --max-stack=4 --call-graph dwarf -e sendto -e probe_libc:inet_pton/max-stack=1/ ping -6 -c 1 ::1
        PING ::1(::1) 56 data bytes
        64 bytes from ::1: icmp_seq=1 ttl=64 time=0.090 ms
      
        --- ::1 ping statistics ---
        1 packets transmitted, 1 received, 0% packet loss, time 0ms
        rtt min/avg/max/mdev = 0.090/0.090/0.090/0.000 ms
             2.140 (         ): probe_libc:inet_pton:(7f9fe9337350))
                                               __GI___inet_pton (/usr/lib64/libc-2.26.so)
             2.283 ( 0.103 ms): ping/31804 sendto(fd: 3, buff: 0x55c7f3e19720, len: 64, addr: 0x55c7f3e17640, addr_len: 28) = 64
                                               __libc_sendto (/usr/lib64/libc-2.26.so)
                                               [0xffffaa380c402cef] (/usr/bin/ping)
                                               [0xffffaa380c3ff56d] (/usr/bin/ping)
                                               [0xffffaa380c400d0a] (/usr/bin/ping)
        #
      
      Install iputils-debuginfo to get those /usr/bin/ping addresses resolved,
      those routines are not on its .dymsym nor .symtab :-)
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Hendrick Brueckner <brueckner@linux.vnet.ibm.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Thomas Richter <tmricht@linux.vnet.ibm.com>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-qgl2gse8elhh9zztw4ajopg3@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      08e26396
    • A
      perf trace: No need to set PERF_SAMPLE_IDENTIFIER explicitely · 236d812c
      Arnaldo Carvalho de Melo 提交于
      Since 75562573 ("perf tools: Add support for
      PERF_SAMPLE_IDENTIFIER") we don't need explicitely set
      PERF_SAMPLE_IDENTIFIER, as perf_evlist__config() will do this for us,
      i.e. when there are more than one evsel in an evlist, it will check if
      some evsel has a sample_type different than the one on the first evsel
      in the list, setting PERF_SAMPLE_IDENTIFIER in that case.
      
      So, to simplify 'perf trace' codebase, ditch that check.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Hendrick Brueckner <brueckner@linux.vnet.ibm.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Thomas Richter <tmricht@linux.vnet.ibm.com>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-12xq6orhwttee2tdtu96ucrp@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      236d812c
  13. 10 1月, 2018 1 次提交
    • A
      perf trace: Beautify 'gettid' syscall result · 2d1073de
      Arnaldo Carvalho de Melo 提交于
      Before:
      
        # trace -a -e gettid sleep 0.01
      <SNIP>
           4.863 ( 0.005 ms): Chrome_ChildIO/26241 gettid() = 26241
           4.931 ( 0.004 ms): Chrome_IOThrea/26154 gettid() = 26154
           4.942 ( 0.001 ms): Chrome_IOThrea/26154 gettid() = 26154
           4.946 ( 0.001 ms): Chrome_IOThrea/26154 gettid() = 26154
           4.970 ( 0.002 ms): Chrome_IOThrea/26154 gettid() = 26154
        #
      
      After:
      
        # trace -a -e gettid sleep 0.01
           0.000 ( 0.009 ms): Chrome_IOThrea/26154 gettid() = 26154 (Chrome_IOThread)
      <SNIP>
           3.416 ( 0.002 ms): Chrome_ChildIO/26241 gettid() = 26241 (Chrome_ChildIOT)
           3.424 ( 0.001 ms): Chrome_ChildIO/26241 gettid() = 26241 (Chrome_ChildIOT)
           3.343 ( 0.002 ms): chrome/26116 gettid() = 26116 (chrome)
           3.386 ( 0.002 ms): Chrome_IOThrea/26154 gettid() = 26154 (Chrome_IOThread)
           4.003 ( 0.003 ms): Chrome_ChildIO/26241 gettid() = 26241 (Chrome_ChildIOT)
           4.031 ( 0.002 ms): Chrome_IOThrea/26154 gettid() = 26154 (Chrome_IOThread)
        #
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-kyg4gz2yy0vkrrh2vtq29u71@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      2d1073de
  14. 06 12月, 2017 1 次提交
  15. 29 11月, 2017 1 次提交
  16. 17 11月, 2017 1 次提交
  17. 09 11月, 2017 1 次提交
  18. 01 11月, 2017 2 次提交
    • A
      perf trace beauty kcmp: Beautify arguments · 1de3038d
      Arnaldo Carvalho de Melo 提交于
      For some unknown reason there is no entry in tracefs's syscalls for
      kcmp, i.e. no tracefs/events/syscalls/sys_{enter,exit}_kcmp, so we need
      to provide a data dictionary for the fields.
      
      To beautify the 'type' argument we automatically generate a strarray
      from tools/include/uapi/kcmp.h, the idx1 and idx2 args, nowadays used
      only if type == KCMP_FILE, are masked for all the other types and a
      lookup is made for the thread and fd to show the path, if possible,
      getting it from the probe:vfs_getname if in place or from procfs, races
      allowing.
      
      A system wide strace like tracing session, with callchains shows just
      one user so far in this fedora 25 machine:
      
        # perf trace --max-stack 5 -e kcmp
        <SNIP>
        1502914.400 ( 0.001 ms): systemd/1 kcmp(pid1: 1 (systemd), pid2: 1 (systemd), type: FILE, idx1: 271<socket:[4723475]>, idx2: 25<socket:[4788686]>) = -1 ENOSYS Function not implemented
                                               syscall (/usr/lib64/libc-2.25.so)
                                               same_fd (/usr/lib/systemd/libsystemd-shared-233.so)
                                               service_add_fd_store (/usr/lib/systemd/systemd)
                                               service_notify_message.lto_priv.127 (/usr/lib/systemd/systemd)
        1502914.407 ( 0.001 ms): systemd/1 kcmp(pid1: 1 (systemd), pid2: 1 (systemd), type: FILE, idx1: 270<socket:[4726396]>, idx2: 25<socket:[4788686]>) = -1 ENOSYS Function not implemented
                                               syscall (/usr/lib64/libc-2.25.so)
                                               same_fd (/usr/lib/systemd/libsystemd-shared-233.so)
                                               service_add_fd_store (/usr/lib/systemd/systemd)
                                               service_notify_message.lto_priv.127 (/usr/lib/systemd/systemd)
        <SNIP>
      
      The backtraces seem to agree this is really kcmp(), but this system
      doesn't have the sys_kcmp(), bummer:
      
        # uname -a
        Linux jouet 4.14.0-rc3+ #1 SMP Fri Oct 13 12:21:12 -03 2017 x86_64 x86_64 x86_64 GNU/Linux
        # grep kcmp /proc/kallsyms
        ffffffffb60b8890 W sys_kcmp
        $ grep CONFIG_CHECKPOINT_RESTORE ../build/v4.14.0-rc3+/.config
        # CONFIG_CHECKPOINT_RESTORE is not set
        $
      
      So systemd uses it, good fedora kernel config has it:
      
        $ grep CONFIG_CHECKPOINT_RESTORE /boot/config-4.13.4-200.fc26.x86_64
        CONFIG_CHECKPOINT_RESTORE=y
        [acme@jouet linux]$
      
      /me goes to rebuild a kernel...
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: Andrey Vagin <avagin@openvz.org>
      Cc: Cyrill Gorcunov <gorcunov@openvz.org>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: http://lkml.kernel.org/n/tip-gz5fca968viw8m7hryjqvrln@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      1de3038d
    • A
      perf trace beauty: Implement pid_fd beautifier · 0a2f7540
      Arnaldo Carvalho de Melo 提交于
      One that given a pid and a fd, will try to get the path for that fd.
      Will be used in the upcoming kcmp's KCMP_FILE beautifier.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: Andrey Vagin <avagin@openvz.org>
      Cc: Cyrill Gorcunov <gorcunov@openvz.org>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: http://lkml.kernel.org/n/tip-7ketygp2dvs9h13wuakfncws@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      0a2f7540
  19. 31 10月, 2017 2 次提交
  20. 27 10月, 2017 1 次提交
    • A
      perf trace beauty prctl: Generate 'option' string table from kernel headers · d688d037
      Arnaldo Carvalho de Melo 提交于
      This is one more case where the way that syscall parameter values are
      defined in kernel headers are easy to parse using a shell script that
      will then generate the string table that gets used by the prctl 'option'
      argument beautifier.
      
      This way as soon as the header syncronization mechanism in perf's build
      system detects a change in a copy of a kernel ABI header and that file
      is syncronized, we get 'perf trace' updated automagically.
      
      Further work needed for the PR_SET_ values, as well for using eBPF to
      copy the non-integer arguments to/from the kernel.
      
      E.g.: System wide prctl tracing:
      
        # perf trace -e prctl
        1668.028 ( 0.025 ms): TaskSchedulerR/10649 prctl(option: SET_NAME, arg2: 0x2b61d5db15d0) = 0
        3365.663 ( 0.018 ms): chrome/10650 prctl(option: SET_SECCOMP, arg2: 2, arg4: 8         ) = -1 EFAULT Bad address
        3366.585 ( 0.010 ms): chrome/10650 prctl(option: SET_NO_NEW_PRIVS, arg2: 1             ) = 0
        3367.173 ( 0.009 ms): TaskSchedulerR/10652 prctl(option: SET_NAME, arg2: 0x2b61d2aaa300) = 0
        3367.222 ( 0.003 ms): TaskSchedulerR/10653 prctl(option: SET_NAME, arg2: 0x2b61d2aaa1e0) = 0
        3367.244 ( 0.002 ms): TaskSchedulerR/10654 prctl(option: SET_NAME, arg2: 0x2b61d2aaa0c0) = 0
        3367.265 ( 0.002 ms): TaskSchedulerR/10655 prctl(option: SET_NAME, arg2: 0x2b61d2ac7f90) = 0
        3367.281 ( 0.002 ms): Chrome_ChildIO/10656 prctl(option: SET_NAME, arg2: 0x7efbe406bb11) = 0
        3367.220 ( 0.004 ms): TaskSchedulerS/10651 prctl(option: SET_NAME, arg2: 0x2b61d2ac1be0) = 0
        3370.906 ( 0.010 ms): GpuMemoryThrea/10657 prctl(option: SET_NAME, arg2: 0x7efbe386ab11) = 0
        3370.983 ( 0.003 ms): File/10658 prctl(option: SET_NAME, arg2: 0x7efbe3069b11          ) = 0
        3384.272 ( 0.020 ms): Compositor/10659 prctl(option: SET_NAME, arg2: 0x7efbe2868b11    ) = 0
        3612.091 ( 0.012 ms): DOM Worker/11489 prctl(option: SET_NAME, arg2: 0x7f49ab97ebf2    ) = 0
      <SNIP>
        4512.437 ( 0.004 ms): (sa1)/11490 prctl(option: SET_NAME, arg2: 0x7ffca15af844         ) = 0
        4512.468 ( 0.002 ms): (sa1)/11490 prctl(option: SET_MM, arg2: ARG_START, arg3: 0x7f5cb7c81000) = 0
        4512.472 ( 0.001 ms): (sa1)/11490 prctl(option: SET_MM, arg2: ARG_END, arg3: 0x7f5cb7c81006) = 0
        4514.667 ( 0.002 ms): (sa1)/11490 prctl(option: GET_SECUREBITS                         ) = 0
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: Andy Lutomirski <luto@kernel.org>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: http://lkml.kernel.org/n/tip-q0s2uw579o5ei6xlh2zjirgz@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      d688d037
  21. 24 10月, 2017 1 次提交
  22. 03 10月, 2017 1 次提交
    • K
      perf top: Implement multithreading for perf_event__synthesize_threads · 340b47f5
      Kan Liang 提交于
      The proc files which is sorted with alphabetical order are evenly
      assigned to several synthesize threads to be processed in parallel.
      
      For 'perf top', the threads number hard code to online CPU number. The
      following patch will introduce an option to set it.
      
      For other perf tools, the thread number is 1. Because the process
      function is not ready for multithreading, e.g.
      process_synthesized_event.
      
      This patch series only support event synthesize multithreading for 'perf
      top'. For other tools, it can be done separately later.
      
      With multithread applied, the total processing time can get up to 1.56x
      speedup on Knights Mill for 'perf top'.
      
      For specific single event processing, the processing time could increase
      because of the lock contention. So proc_map_timeout may need to be
      increased. Otherwise some proc maps will be truncated.
      
      Based on my test, increasing the proc_map_timeout has small impact
      on the total processing time. The total processing time still get 1.49x
      speedup on Knights Mill after increasing the proc_map_timeout.
      The patch itself doesn't increase the proc_map_timeout.
      
      Doesn't need to implement multithreading for per task monitoring,
      perf_event__synthesize_thread_map. It doesn't have performance issue.
      
      Committer testing:
      
        # getconf _NPROCESSORS_ONLN
        4
        # perf trace --no-inherit -e clone -o /tmp/output perf top
        # tail -4 /tmp/bla
           0.124 ( 0.041 ms): clone(flags: VM|FS|FILES|SIGHAND|THREAD|SYSVSEM|SETTLS|PARENT_SETTID|CHILD_CLEARTID, child_stack: 0x7fc3eb3a8f30, parent_tidptr: 0x7fc3eb3a99d0, child_tidptr: 0x7fc3eb3a99d0, tls: 0x7fc3eb3a9700) = 9548 (perf)
           0.246 ( 0.023 ms): clone(flags: VM|FS|FILES|SIGHAND|THREAD|SYSVSEM|SETTLS|PARENT_SETTID|CHILD_CLEARTID, child_stack: 0x7fc3eaba7f30, parent_tidptr: 0x7fc3eaba89d0, child_tidptr: 0x7fc3eaba89d0, tls: 0x7fc3eaba8700) = 9549 (perf)
           0.286 ( 0.019 ms): clone(flags: VM|FS|FILES|SIGHAND|THREAD|SYSVSEM|SETTLS|PARENT_SETTID|CHILD_CLEARTID, child_stack: 0x7fc3ea3a6f30, parent_tidptr: 0x7fc3ea3a79d0, child_tidptr: 0x7fc3ea3a79d0, tls: 0x7fc3ea3a7700) = 9550 (perf)
         246.540 ( 0.047 ms): clone(flags: VM|FS|FILES|SIGHAND|THREAD|SYSVSEM|SETTLS|PARENT_SETTID|CHILD_CLEARTID, child_stack: 0x7fc3ea3a6f30, parent_tidptr: 0x7fc3ea3a79d0, child_tidptr: 0x7fc3ea3a79d0, tls: 0x7fc3ea3a7700) = 9551 (perf)
        #
      Signed-off-by: NKan Liang <kan.liang@intel.com>
      Tested-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      Acked-by: NJiri Olsa <jolsa@kernel.org>
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: Alexei Starovoitov <ast@kernel.org>
      Cc: Andi Kleen <ak@linux.intel.com>
      Cc: He Kuang <hekuang@huawei.com>
      Cc: Lukasz Odzioba <lukasz.odzioba@intel.com>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Peter Zijlstra <peterz@infradead.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: http://lkml.kernel.org/r/1506696477-146932-4-git-send-email-kan.liang@intel.comSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      340b47f5
  23. 18 9月, 2017 2 次提交
  24. 02 9月, 2017 1 次提交
    • A
      perf trace: Support syscall name globbing · 27702bcf
      Arnaldo Carvalho de Melo 提交于
      So now we can use:
      
        # perf trace -e pkey_*
         532.784 ( 0.006 ms): pkey/16018 pkey_alloc(init_val: DISABLE_WRITE) = -1 EINVAL Invalid argument
         532.795 ( 0.004 ms): pkey/16018 pkey_mprotect(start: 0x7f380d0a6000, len: 4096, prot: READ|WRITE, pkey: -1) = 0
         532.801 ( 0.002 ms): pkey/16018 pkey_free(pkey: -1                ) = -1 EINVAL Invalid argument
        ^C[root@jouet ~]#
      
      Or '-e epoll*', '-e *msg*', etc.
      
      Combining syscall names with perf events, tracepoints, etc, continues to
      be valid, i.e. this is possible:
      
        # perf probe -L sys_nanosleep
        <SyS_nanosleep@/home/acme/git/linux/kernel/time/hrtimer.c:0>
            0  SYSCALL_DEFINE2(nanosleep, struct timespec __user *, rqtp,
                              struct timespec __user *, rmtp)
               {
                      struct timespec64 tu;
      
            5         if (get_timespec64(&tu, rqtp))
            6                 return -EFAULT;
      
                      if (!timespec64_valid(&tu))
            9                 return -EINVAL;
      
           11         current->restart_block.nanosleep.type = rmtp ? TT_NATIVE : TT_NONE;
           12         current->restart_block.nanosleep.rmtp = rmtp;
           13         return hrtimer_nanosleep(&tu, HRTIMER_MODE_REL, CLOCK_MONOTONIC);
               }
      
        # perf probe my_probe="sys_nanosleep:12 rmtp"
        Added new event:
          probe:my_probe       (on sys_nanosleep:12 with rmtp)
      
        You can now use it in all perf tools, such as:
      
      	perf record -e probe:my_probe -aR sleep 1
      
        #
        # perf trace -e probe:my_probe/max-stack=5/,*sleep sleep 1
           0.427 ( 0.003 ms): sleep/16690 nanosleep(rqtp: 0x7ffefc245090) ...
           0.430 (         ): probe:my_probe:(ffffffffbd112923) rmtp=0)
                                             sys_nanosleep ([kernel.kallsyms])
                                             do_syscall_64 ([kernel.kallsyms])
                                             return_from_SYSCALL_64 ([kernel.kallsyms])
                                             __nanosleep_nocancel (/usr/lib64/libc-2.25.so)
           0.427 (1000.208 ms): sleep/16690  ... [continued]: nanosleep()) = 0
        #
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: http://lkml.kernel.org/n/tip-elycoi8wy6y0w9dkj7ox1mzz@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      27702bcf
  25. 29 8月, 2017 1 次提交
    • A
      perf trace beauty: Beautify pkey_{alloc,free,mprotect} arguments · 83bc9c37
      Arnaldo Carvalho de Melo 提交于
      Reuse 'mprotect' beautifiers for 'pkey_mprotect'.
      
      System wide tracing pkey_alloc, pkey_free and pkey_mprotect calls, with
      backtraces:
      
        # perf trace -e pkey_alloc,pkey_mprotect,pkey_free --max-stack=5
           0.000 ( 0.011 ms): pkey/7818 pkey_alloc(init_val: DISABLE_ACCESS|DISABLE_WRITE) = -1 EINVAL Invalid argument
                                             syscall (/usr/lib64/libc-2.25.so)
                                             pkey_alloc (/home/acme/c/pkey)
           0.022 ( 0.003 ms): pkey/7818 pkey_mprotect(start: 0x7f28c3890000, len: 4096, prot: READ|WRITE, pkey: -1) = 0
                                             syscall (/usr/lib64/libc-2.25.so)
                                             pkey_mprotect (/home/acme/c/pkey)
           0.030 ( 0.002 ms): pkey/7818 pkey_free(pkey: -1                               ) = -1 EINVAL Invalid argument
                                             syscall (/usr/lib64/libc-2.25.so)
                                             pkey_free (/home/acme/c/pkey)
      
      The tools/include/uapi/asm-generic/mman-common.h file is used to find
      the access rights defines for the pkey_alloc syscall second argument.
      
      Since we have the detector of changes for the tools/include header files
      versus its kernel origin (include/uapi/asm-generic/mman-common.h), we'll
      get whatever new flag appears for that argument automatically.
      
      This method should be used in other cases where it is easy to generate
      those flags tables because the header has properly namespaced defines
      like PKEY_DISABLE_ACCESS and PKEY_DISABLE_WRITE.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: Arnd Bergmann <arnd@arndb.de>
      Cc: Dave Hansen <dave.hansen@linux.intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: http://lkml.kernel.org/n/tip-3xq5312qlks7wtfzv2sk3nct@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      83bc9c37
  26. 18 8月, 2017 1 次提交
  27. 01 8月, 2017 1 次提交
    • A
      perf trace beauty ioctl: Improve 'cmd' beautifier · 1cc47f2d
      Arnaldo Carvalho de Melo 提交于
      By using the _IOC_(DIR,NR,TYPE,SIZE) macros to lookup a 'type' keyed
      table that then gets indexed by 'nr', falling back to a notation similar
      to the one used by 'strace', only more compact, i.e.:
      
         474.356 ( 0.007 ms): gnome-shell/22401 ioctl(fd: 8</dev/dri/card0>, cmd: (READ|WRITE, 0x64, 0xae, 0x1c), arg: 0x7ffc934f7880) = 0
         474.369 ( 0.053 ms): gnome-shell/22401 ioctl(fd: 8</dev/dri/card0>, cmd: (READ|WRITE, 0x64, 0xb0, 0x18), arg: 0x7ffc934f77d0) = 0
         505.055 ( 0.014 ms): gnome-shell/22401 ioctl(fd: 8</dev/dri/card0>, cmd: (READ|WRITE, 0x64, 0xaf, 0x4), arg: 0x7ffc934f741c) = 0
      
      This also moves it out of builtin-trace.c and into trace/beauty/ioctl.c
      to better compartimentalize all these formatters.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: http://lkml.kernel.org/n/tip-s3enursdxsvnhdomh6qlte4g@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      1cc47f2d
  28. 21 7月, 2017 1 次提交
    • A
      perf trace: Filter out 'sshd' in the tracer ancestry in syswide tracing · 082ab9a1
      Arnaldo Carvalho de Melo 提交于
      Avoiding a loop, so now its quite convenient to ssh to a machine and
      then simply do:
      
      	# perf trace
      
      To trace all syscalls without causing a loop.
      
      This was possible using --filter-pids, i.e. once you noticed the loop,
      get the sshd pid and add it to --filter-pids, restarting the 'perf
      trace'.
      
      Now to figure out how to do that in a X terminal, the other common
      scenario, which is way more involved, as there are multiple processes
      communicating to process terminal activity...
      
      Using --filter-pids + '-e \!syscall,names,you,dont,need' may be a good
      approximation when having to do syswide tracing on your workstation.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: http://lkml.kernel.org/n/tip-68rjeao9wnpylla41htk7xps@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      082ab9a1