1. 08 3月, 2018 1 次提交
  2. 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
  3. 05 3月, 2018 1 次提交
  4. 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
  5. 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
  6. 23 1月, 2018 1 次提交
  7. 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
  8. 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
  9. 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
  10. 06 12月, 2017 1 次提交
  11. 29 11月, 2017 1 次提交
  12. 17 11月, 2017 1 次提交
  13. 09 11月, 2017 1 次提交
  14. 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
  15. 31 10月, 2017 2 次提交
  16. 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
  17. 24 10月, 2017 1 次提交
  18. 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
  19. 18 9月, 2017 2 次提交
  20. 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
  21. 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
  22. 18 8月, 2017 1 次提交
  23. 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
  24. 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
  25. 20 7月, 2017 7 次提交
    • A
      perf trace: Introduce filter_loop_pids() · dd1a5037
      Arnaldo Carvalho de Melo 提交于
      No change in functionality, just to make clearer that what we want when
      filtering the tracer pid in a system wide tracing session is to avoid a
      feedback loop.
      
      This also paves the way for a more interesting loop avoidance algorithm,
      one that tries to figure out if we are in a ssh session, xterm, etc.
      
      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-5fcttc5kdjkcyp9404ezkuy9@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      dd1a5037
    • A
      perf trace beauty clone: Beautify syscall arguments · 33396a3a
      Arnaldo Carvalho de Melo 提交于
      Now, syswide tracing, selected entries:
      
        # trace -e clone
        24417.203 ( 0.158 ms): bash/11323 clone(flags: CHILD_CLEARTID|CHILD_SETTID|0x11, child_stack: 0, parent_tidptr: 0, child_tidptr: 0x7f0778e5c9d0, tls: 0x7f0778e5c700) = 11325 (bash)
                ? (     ?   ): bash/11325  ... [continued]: clone()) = 0
        24419.355 ( 0.093 ms): bash/10586 clone(flags: CHILD_CLEARTID|CHILD_SETTID|0x11, child_stack: 0, parent_tidptr: 0, child_tidptr: 0x7f0778e5c9d0, tls: 0x7f0778e5c700) = 11326 (bash)
                ? (     ?   ): bash/11326  ... [continued]: clone()) = 0
        24419.744 ( 0.102 ms): bash/11326 clone(flags: CHILD_CLEARTID|CHILD_SETTID|0x11, child_stack: 0, parent_tidptr: 0, child_tidptr: 0x7f0778e5c9d0, tls: 0x7f0778e5c700) = 11327 (bash)
                ? (     ?   ): bash/11327  ... [continued]: clone()) = 0
        24420.138 ( 0.105 ms): bash/11327 clone(flags: CHILD_CLEARTID|CHILD_SETTID|0x11, child_stack: 0, parent_tidptr: 0, child_tidptr: 0x7f0778e5c9d0, tls: 0x7f0778e5c700) = 11328 (bash)
                ? (     ?   ): bash/11328  ... [continued]: clone()) = 0
        35747.722 ( 0.044 ms): gpg-agent/18087 clone(flags: VM|FS|FILES|SIGHAND|THREAD|SYSVSEM|SETTLS|PARENT_SETTID|CHILD_CLEARTID, child_stack: 0x7ff0755f6ff0, parent_tidptr: 0x7ff0755f79d0, child_tidptr: 0x7ff0755f79d0, tls: 0x7ff0755f7700) = 11329 (gpg-agent)
                ? (     ?   ): gpg-agent/11329  ... [continued]: clone()) = 0
        35748.359 ( 0.022 ms): gpg-agent/18087 clone(flags: VM|FS|FILES|SIGHAND|THREAD|SYSVSEM|SETTLS|PARENT_SETTID|CHILD_CLEARTID, child_stack: 0x7ff075df7ff0, parent_tidptr: 0x7ff075df89d0, child_tidptr: 0x7ff075df89d0, tls: 0x7ff075df8700) = 11330 (gpg-agent)
                ? (     ?   ): gpg-agent/11330  ... [continued]: clone()) = 0
        35781.422 ( 0.452 ms): NetworkManager/1112 clone(flags: VM|FS|FILES|SIGHAND|THREAD|SYSVSEM|SETTLS|PARENT_SETTID|CHILD_CLEARTID, child_stack: 0x7f2f1fffedb0, parent_tidptr: 0x7f2f1ffff9d0, child_tidptr: 0x7f2f1ffff9d0, tls: 0x7f2f1ffff700) = 11331 (NetworkManager)
                ? (     ?   ): NetworkManager/11331  ... [continued]: clone()) = 0
      
      Need to improve the formatting of the second return, to the child, this
      cset only focused on the argument formatting.
      
      If we trace just one pid:
      
        # trace -e clone -p 19863
           0.349 ( 0.025 ms): Chrome_IOThrea/19863 clone(flags: VM|FS|FILES|SIGHAND|THREAD|SYSVSEM|SETTLS|PARENT_SETTID|CHILD_CLEARTID, child_stack: 0x7ffb84eaac70, parent_tidptr: 0x7ffb84eab9d0, child_tidptr: 0x7ffb84eab9d0, tls: 0x7ffb84eab700) = 11637 (Chrome_IOThread)
           0.392 ( 0.013 ms): Chrome_IOThrea/19863 clone(flags: VM|FS|FILES|SIGHAND|THREAD|SYSVSEM|SETTLS|PARENT_SETTID|CHILD_CLEARTID, child_stack: 0x7ffb664b8c70, parent_tidptr: 0x7ffb664b99d0, child_tidptr: 0x7ffb664b99d0, tls: 0x7ffb664b9700) = 11638 (Chrome_IOThread)
           0.573 ( 0.015 ms): Chrome_IOThrea/19863 clone(flags: VM|FS|FILES|SIGHAND|THREAD|SYSVSEM|SETTLS|PARENT_SETTID|CHILD_CLEARTID, child_stack: 0x7ffb6046cc70, parent_tidptr: 0x7ffb6046d9d0, child_tidptr: 0x7ffb6046d9d0, tls: 0x7ffb6046d700) = 11639 (Chrome_IOThread)
           0.617 ( 0.014 ms): Chrome_IOThrea/19863 clone(flags: VM|FS|FILES|SIGHAND|THREAD|SYSVSEM|SETTLS|PARENT_SETTID|CHILD_CLEARTID, child_stack: 0x7ffb730dcc70, parent_tidptr: 0x7ffb730dd9d0, child_tidptr: 0x7ffb730dd9d0, tls: 0x7ffb730dd700) = 11640 (Chrome_IOThread)
           4.350 ( 0.065 ms): Chrome_IOThrea/19863 clone(flags: VM|FS|FILES|SIGHAND|THREAD|SYSVSEM|SETTLS|PARENT_SETTID|CHILD_CLEARTID, child_stack: 0x7ffb720d9c70, parent_tidptr: 0x7ffb720da9d0, child_tidptr: 0x7ffb720da9d0, tls: 0x7ffb720da700) = 11642 (Chrome_IOThread)
           5.642 ( 0.079 ms): Chrome_IOThrea/19863 clone(flags: VM|FS|FILES|SIGHAND|THREAD|SYSVSEM|SETTLS|PARENT_SETTID|CHILD_CLEARTID, child_stack: 0x7ffb718d8c70, parent_tidptr: 0x7ffb718d99d0, child_tidptr: 0x7ffb718d99d0, tls: 0x7ffb718d9700) = 11643 (Chrome_IOThread)
      ^C#
      
      We'll also have to fix the argument ordering in different arches,
      probably having multiple syscall_fmt entries with each possible order
      and then use perf_evsel__env_arch() (if dealing with a perf.data file)
      or the current system info, for live sessions.
      
      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-am068uyubgj83snepolwhbfe@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      33396a3a
    • A
      perf trace: Allow specifying names to syscall arguments formatters · c51bdfec
      Arnaldo Carvalho de Melo 提交于
      For tracepointless syscalls, like clone, otherwise get them from the
      tracepoint's /format file.
      
      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-ml5qvv1w5k96ghwhxpzzsmm3@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      c51bdfec
    • A
      perf trace: Allow specifying number of syscall args for tracepointless syscalls · 332337da
      Arnaldo Carvalho de Melo 提交于
      When we don't have syscalls:sys_{enter,exit}_NAME, we had to resort to
      dumping all the 6 syscall arguments, fix it by providing that info for
      such syscalls, like 'clone'.
      
      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-dfq1jtrxj8dqvqoeqqpr3slu@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      332337da
    • A
      perf trace: Ditch __syscall__arg_val() variant, not needed anymore · 325f5091
      Arnaldo Carvalho de Melo 提交于
      All callers now can use syscall__arg_val(arg, idx), be it to iterate
      thru the syscall arguments while taking into account alignment, or to
      get values for other arguments that affect how the current argument
      should be formatted (think of fcntl's 'cmd' and 'arg' arguments).
      
      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-wm5b156d8kro1r4y3b33eyta@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      325f5091
    • A
      perf trace: Use the syscall_fmt formatters without a tracepoint · d032d79e
      Arnaldo Carvalho de Melo 提交于
      Previously we only used the syscall_fmt when we had sc->tp_format set,
      i.e. when we found the (enter, exit) pair in tracefs/events/syscalls/.
      
      But we really only need to use what is in sc->arg_fmt to apply the arg
      beautifiers to the syscall argument values, so do it.
      
      With this we will be able to provide formatters to the "clone" syscall,
      which doesn't have entries in tracefs/events/syscalls/.
      
      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-y41nl41jrayjo5ucnde2peix@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      d032d79e
    • A
      perf trace: Allow allocating sc->arg_fmt even without the syscall tracepoint · 5e58fcfa
      Arnaldo Carvalho de Melo 提交于
      At least "clone" doesn't have (enter, exit) entries tracefs/events/syscalls/,
      but we can provide a syscall_fmt and use it instead, as will be done for
      "clone" in the next cset.
      
      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-o12kejgcxddyovn2hlg4gbim@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      5e58fcfa