1. 18 12月, 2018 1 次提交
  2. 21 11月, 2018 4 次提交
  3. 03 11月, 2018 1 次提交
    • A
      perf trace: Fix setting of augmented payload when using eBPF + raw_syscalls · cd26ea6d
      Arnaldo Carvalho de Melo 提交于
      For now with BPF raw_augmented we hook into raw_syscalls:sys_enter and
      there we get all 6 syscall args plus the tracepoint common fields
      (sizeof(long)) and the syscall_nr (another long). So we check if that is
      the case and if so don't look after the sc->args_size, but always after
      the full raw_syscalls:sys_enter payload, which is fixed.
      
      We'll revisit this later to pass s->args_size to the BPF augmenter (now
      tools/perf/examples/bpf/augmented_raw_syscalls.c, so that it copies only
      what we need for each syscall, like what happens when we use
      syscalls:sys_enter_NAME, so that we reduce the kernel/userspace traffic
      to just what is needed for each syscall.
      
      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-nlslrg8apxdsobt4pwl3n7ur@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      cd26ea6d
  4. 02 11月, 2018 1 次提交
    • A
      perf trace: When augmenting raw_syscalls plug raw_syscalls:sys_exit too · 3c5e3dab
      Arnaldo Carvalho de Melo 提交于
      With just this commit we get to support all syscalls via hooking
      raw_syscalls:sys_{enter,exit} to the trace__sys_{enter,exit} routines
      to combine, strace-like, those tracepoints.
      
        # trace -e tools/perf/examples/bpf/augmented_raw_syscalls.c sleep 1
               ? (         ): sleep/31680  ... [continued]: execve()) = 0
           0.043 ( 0.004 ms): sleep/31680 brk() = 0x55652a851000
           0.070 ( 0.009 ms): sleep/31680 access(filename:, mode: R) = -1 ENOENT No such file or directory
           0.087 ( 0.006 ms): sleep/31680 openat(dfd: CWD, filename: , flags: CLOEXEC) = 3
           0.096 ( 0.003 ms): sleep/31680 fstat(fd: 3, statbuf: 0x7ffc5269e190) = 0
           0.101 ( 0.005 ms): sleep/31680 mmap(len: 103334, prot: READ, flags: PRIVATE, fd: 3) = 0x7f709c239000
           0.109 ( 0.002 ms): sleep/31680 close(fd: 3) = 0
           0.126 ( 0.006 ms): sleep/31680 openat(dfd: CWD, filename: , flags: CLOEXEC) = 3
           0.135 ( 0.003 ms): sleep/31680 read(fd: 3, buf: 0x7ffc5269e358, count: 832) = 832
           0.141 ( 0.002 ms): sleep/31680 fstat(fd: 3, statbuf: 0x7ffc5269e1f0) = 0
           0.146 ( 0.005 ms): sleep/31680 mmap(len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS) = 0x7f709c237000
           0.159 ( 0.007 ms): sleep/31680 mmap(len: 3889792, prot: EXEC|READ, flags: PRIVATE|DENYWRITE, fd: 3) = 0x7f709bc79000
           0.168 ( 0.009 ms): sleep/31680 mprotect(start: 0x7f709be26000, len: 2093056) = 0
           0.179 ( 0.010 ms): sleep/31680 mmap(addr: 0x7f709c025000, len: 24576, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 1753088) = 0x7f709c025000
           0.196 ( 0.005 ms): sleep/31680 mmap(addr: 0x7f709c02b000, len: 14976, prot: READ|WRITE, flags: PRIVATE|FIXED|ANONYMOUS) = 0x7f709c02b000
           0.210 ( 0.002 ms): sleep/31680 close(fd: 3) = 0
           0.230 ( 0.002 ms): sleep/31680 arch_prctl(option: 4098, arg2: 140121632638208) = 0
           0.306 ( 0.009 ms): sleep/31680 mprotect(start: 0x7f709c025000, len: 16384, prot: READ) = 0
           0.338 ( 0.005 ms): sleep/31680 mprotect(start: 0x556529607000, len: 4096, prot: READ) = 0
           0.348 ( 0.005 ms): sleep/31680 mprotect(start: 0x7f709c253000, len: 4096, prot: READ) = 0
           0.356 ( 0.019 ms): sleep/31680 munmap(addr: 0x7f709c239000, len: 103334) = 0
           0.463 ( 0.002 ms): sleep/31680 brk() = 0x55652a851000
           0.468 ( 0.004 ms): sleep/31680 brk(brk: 0x55652a872000) = 0x55652a872000
           0.474 ( 0.002 ms): sleep/31680 brk() = 0x55652a872000
           0.484 ( 0.008 ms): sleep/31680 open(filename: , flags: CLOEXEC) = 3
           0.497 ( 0.002 ms): sleep/31680 fstat(fd: 3, statbuf: 0x7f709c02aaa0) = 0
           0.501 ( 0.006 ms): sleep/31680 mmap(len: 113045344, prot: READ, flags: PRIVATE, fd: 3) = 0x7f70950aa000
           0.514 ( 0.002 ms): sleep/31680 close(fd: 3) = 0
           0.554 (1000.140 ms): sleep/31680 nanosleep(rqtp: 0x7ffc5269eed0) = 0
        1000.734 ( 0.007 ms): sleep/31680 close(fd: 1) = 0
        1000.748 ( 0.004 ms): sleep/31680 close(fd: 2) = 0
        1000.769 (         ): sleep/31680 exit_group()
        #
      
      Now to allow selecting which syscalls should be traced, using a map.
      
      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-votqqmqhag8e1i9mgyzfez3o@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      3c5e3dab
  5. 30 10月, 2018 5 次提交
    • A
      perf trace: Beautify mount's first pathname arg · 23c07a23
      Arnaldo Carvalho de Melo 提交于
      The pathname beautifiers so far support just one augmented pathname per
      syscall, so do it just for mount's first arg, later this will get fixed.
      
      With:
      
        # perf probe -l
        probe:vfs_getname    (on getname_flags:73@acme/git/linux/fs/namei.c with pathname)
        #
      
      Later this will get added to augmented_syscalls.c (eBPF):
      
      In one xterm:
      
        # perf trace -e mount,umount
        2687.331 ( 3.544 ms): mount/8892 mount(dev_name: /mnt, dir_name: 0x561f9ac184a0, type: 0x561f9ac1b170, flags: BIND) = 0
        3912.126 ( 8.807 ms): umount/8895 umount2(name: /mnt) = 0
        ^C#
      
      In the other:
      
        $ sudo mount --bind /proc /mnt
        $ sudo umount /mnt
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: Benjamin Peterson <benjamin@python.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: https://lkml.kernel.org/n/tip-qsvhrm2es635cl4zicqjeth2@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      23c07a23
    • A
      perf trace: Beautify the umount's 'name' argument · 476c92ca
      Arnaldo Carvalho de Melo 提交于
      By using the SCA_FILENAME beautifier, that works when either the
      probe:vfs_getname probe is in place or with the eBPF program
      tools/perf/examples/bpf/augmented_syscalls.c:
      
        # perf probe -l
        probe:vfs_getname (on getname_flags:73@acme/git/linux/fs/namei.c with pathname)
        # perf trace -e umount
        9630.332 ( 9.521 ms): umount/8082 umount2(name: /mnt) = 0
        #
      
      The augmented syscalls one will be done in the next patch.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: Benjamin Peterson <benjamin@python.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: https://lkml.kernel.org/n/tip-hegbzlpd2nrn584l5jxn7sy2@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      476c92ca
    • A
      perf trace: Consider syscall aliases too · f932184e
      Arnaldo Carvalho de Melo 提交于
      When trying to trace the 'umount' syscall on x86_64 I noticed that it
      was failing:
      
        # trace -e umount umount /mnt
        event syntax error: 'umount'
                             \___ parser error
        Run 'perf list' for a list of valid events
      
         Usage: perf trace [<options>] [<command>]
            or: perf trace [<options>] -- <command> [<options>]
            or: perf trace record [<options>] [<command>]
            or: perf trace record [<options>] -- <command> [<options>]
      
            -e, --event <event>   event/syscall selector. use 'perf list' to list available events
        #
      
      This is because in the x86-64 we have it just as 'umount2':
      
        $ grep umount arch/x86/entry/syscalls/syscall_64.tbl
        166	common	umount2			__x64_sys_umount
        $
      
      So if the syscall name fails, try fallbacking to looking at the aliases
      we have in the syscall_fmts table to then re-lookup, now:
      
        # trace -e umount umount -f /mnt
        umount: /mnt: not mounted.
           1.759 ( 0.004 ms): umount/18365 umount2(name: 0x55fbfcbc4480, flags: 1) = -1 EINVAL Invalid argument
        #
      
      Time to beautify the flags arg :-)
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: Benjamin Peterson <benjamin@python.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: https://lkml.kernel.org/n/tip-ukweodgzbmjd25lfkgryeft1@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      f932184e
    • A
      perf trace beauty: Beautify mount/umount's 'flags' argument · 73d141ad
      Arnaldo Carvalho de Melo 提交于
        # trace -e mount mount -o ro -t debugfs nodev /mnt
           0.000 ( 1.040 ms): mount/27235 mount(dev_name: 0x5601cc8c64e0, dir_name: 0x5601cc8c6500, type: 0x5601cc8c6480, flags: RDONLY) = 0
        # trace -e mount mount -o remount,relatime -t debugfs nodev /mnt
           0.000 ( 2.946 ms): mount/27262 mount(dev_name: 0x55f4a73d64e0, dir_name: 0x55f4a73d6500, type: 0x55f4a73d6480, flags: REMOUNT|RELATIME) = 0
        # trace -e mount mount -o remount,strictatime -t debugfs nodev /mnt
           0.000 ( 2.934 ms): mount/27265 mount(dev_name: 0x5617f71d94e0, dir_name: 0x5617f71d9500, type: 0x5617f71d9480, flags: REMOUNT|STRICTATIME) = 0
        # trace -e mount mount -o remount,suid,silent -t debugfs nodev /mnt
           0.000 ( 0.049 ms): mount/27273 mount(dev_name: 0x55ad65df24e0, dir_name: 0x55ad65df2500, type: 0x55ad65df2480, flags: REMOUNT|SILENT) = 0
        # trace -e mount mount -o remount,rw,sync,lazytime -t debugfs nodev /mnt
           0.000 ( 2.684 ms): mount/27281 mount(dev_name: 0x561216055530, dir_name: 0x561216055550, type: 0x561216055510, flags: SYNCHRONOUS|REMOUNT|LAZYTIME) = 0
        # trace -e mount mount -o remount,dirsync -t debugfs nodev /mnt
           0.000 ( 3.512 ms): mount/27314 mount(dev_name: 0x55c4e7188480, dir_name: 0x55c4e7188530, type: 0x55c4e71884a0, flags: REMOUNT|DIRSYNC, data: 0x55c4e71884e0) = 0
        #
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: Benjamin Peterson <benjamin@python.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: https://lkml.kernel.org/n/tip-i5ncao73c0bd02qprgrq6wb9@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      73d141ad
    • A
      perf trace beauty: Allow syscalls to mask an argument before considering it · 496fd346
      Arnaldo Carvalho de Melo 提交于
      Take mount's 'flags' arg, to cope with this semantic, as defined in do_mount in fs/namespace.c:
      
        /*
         * Pre-0.97 versions of mount() didn't have a flags word.  When the
         * flags word was introduced its top half was required to have the
         * magic value 0xC0ED, and this remained so until 2.4.0-test9.
         * Therefore, if this magic number is present, it carries no
         * information and must be discarded.
         */
      
      We need to mask this arg, and then see if it is zero, when we simply
      don't print the arg name and value.
      
      The next patch will use this for mount's 'flag' arg.
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: Benjamin Peterson <benjamin@python.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: https://lkml.kernel.org/n/tip-btue14k5jemayuykfrwsnh85@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      496fd346
  6. 23 10月, 2018 1 次提交
    • A
      perf trace: Introduce per-event maximum number of events property · a9c5e6c1
      Arnaldo Carvalho de Melo 提交于
      Call it 'nr', as in this context it should be expressive enough, i.e.:
      
        # perf trace -e sched:*waking/nr=8,call-graph=fp/
           0.000 :0/0 sched:sched_waking:comm=rcu_sched pid=10 prio=120 target_cpu=001
                                             try_to_wake_up ([kernel.kallsyms])
                                             sched_clock ([kernel.kallsyms])
           3.933 :0/0 sched:sched_waking:comm=rcu_sched pid=10 prio=120 target_cpu=001
                                             try_to_wake_up ([kernel.kallsyms])
                                             sched_clock ([kernel.kallsyms])
           3.970 IPDL Backgroun/3622 sched:sched_waking:comm=Gecko_IOThread pid=3569 prio=120 target_cpu=003
                                             try_to_wake_up ([kernel.kallsyms])
                                             __libc_write (/usr/lib64/libpthread-2.26.so)
          20.069 IPDL Backgroun/3622 sched:sched_waking:comm=Gecko_IOThread pid=3569 prio=120 target_cpu=003
                                             try_to_wake_up ([kernel.kallsyms])
                                             __libc_write (/usr/lib64/libpthread-2.26.so)
          37.170 IPDL Backgroun/3622 sched:sched_waking:comm=Gecko_IOThread pid=3569 prio=120 target_cpu=003
                                             try_to_wake_up ([kernel.kallsyms])
                                             __libc_write (/usr/lib64/libpthread-2.26.so)
          53.267 IPDL Backgroun/3622 sched:sched_waking:comm=Gecko_IOThread pid=3569 prio=120 target_cpu=003
                                             try_to_wake_up ([kernel.kallsyms])
                                             __libc_write (/usr/lib64/libpthread-2.26.so)
          70.365 IPDL Backgroun/3622 sched:sched_waking:comm=Gecko_IOThread pid=3569 prio=120 target_cpu=003
                                             try_to_wake_up ([kernel.kallsyms])
                                             __libc_write (/usr/lib64/libpthread-2.26.so)
          75.781 Web Content/3649 sched:sched_waking:comm=JS Helper pid=3670 prio=120 target_cpu=000
                                             try_to_wake_up ([kernel.kallsyms])
                                             try_to_wake_up ([kernel.kallsyms])
                                             wake_up_q ([kernel.kallsyms])
                                             futex_wake ([kernel.kallsyms])
                                             do_futex ([kernel.kallsyms])
                                             __x64_sys_futex ([kernel.kallsyms])
                                             do_syscall_64 ([kernel.kallsyms])
                                             entry_SYSCALL_64_after_hwframe ([kernel.kallsyms])
                                             pthread_cond_signal@@GLIBC_2.3.2 (/usr/lib64/libpthread-2.26.so)
        #
      
        # perf trace -e sched:*switch/nr=2/,block:*_plug/nr=4/,block:*_unplug/nr=1/,net:*dev_queue/nr=3,max-stack=16/
           0.000 :0/0 sched:sched_switch:swapper/0:0 [120] S ==> trace:3367 [120]
           0.046 :0/0 sched:sched_switch:swapper/1:0 [120] S ==> kworker/u16:58:2722 [120]
         570.670 irq/50-iwlwifi/680 net:net_dev_queue:dev=wlp3s0 skbaddr=0xffff93498051ef00 len=66
                                             __dev_queue_xmit ([kernel.kallsyms])
        1106.141 jbd2/dm-0-8/476 block:block_plug:[jbd2/dm-0-8]
        1106.175 jbd2/dm-0-8/476 block:block_unplug:[jbd2/dm-0-8] 1
        1618.088 kworker/u16:30/2694 block:block_plug:[kworker/u16:30]
        1810.000 :0/0 net:net_dev_queue:dev=vnet0 skbaddr=0xffff93498051ef00 len=52
                                             __dev_queue_xmit ([kernel.kallsyms])
        3857.974 :0/0 net:net_dev_queue:dev=vnet0 skbaddr=0xffff93498051f900 len=52
                                             __dev_queue_xmit ([kernel.kallsyms])
        4790.277 jbd2/dm-2-8/748 block:block_plug:[jbd2/dm-2-8]
        4790.448 jbd2/dm-2-8/748 block:block_plug:[jbd2/dm-2-8]
        #
      
      The global --max-events has precendence:
      
        # trace --max-events 3 -e sched:*switch/nr=2/,block:*_plug/nr=4/,block:*_unplug/nr=1/,net:*dev_queue/nr=3,max-stack=16/
           0.000 :0/0 sched:sched_switch:swapper/0:0 [120] S ==> qemu-system-x86:2252 [120]
           0.029 qemu-system-x8/2252 sched:sched_switch:qemu-system-x86:2252 [120] D ==> swapper/0:0 [120]
          58.047 DNS Res~er #14/31661 net:net_dev_queue:dev=wlp3s0 skbaddr=0xffff9346966af100 len=84
                                             __dev_queue_xmit ([kernel.kallsyms])
                                             __libc_send (/usr/lib64/libpthread-2.26.so)
        #
      
      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-s4jswltvh660ughvg9nwngah@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      a9c5e6c1
  7. 22 10月, 2018 2 次提交
  8. 19 10月, 2018 1 次提交
    • A
      perf trace: Introduce --max-events · 5067a8cd
      Arnaldo Carvalho de Melo 提交于
      Allow stopping tracing after a number of events take place, considering
      strace-like syscalls formatting as one event per enter/exit pair or when
      in a multi-process tracing session a syscall is interrupted and printed
      ending with '...'.
      
      Examples included in the documentation:
      
      Trace the first 4 open, openat or open_by_handle_at syscalls (in the future more syscalls may match here):
      
        $ perf trace -e open* --max-events 4
        [root@jouet perf]# trace -e open* --max-events 4
        2272.992 ( 0.037 ms): gnome-shell/1370 openat(dfd: CWD, filename: /proc/self/stat) = 31
        2277.481 ( 0.139 ms): gnome-shell/3039 openat(dfd: CWD, filename: /proc/self/stat) = 65
        3026.398 ( 0.076 ms): gnome-shell/3039 openat(dfd: CWD, filename: /proc/self/stat) = 65
        4294.665 ( 0.015 ms): sed/15879 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: CLOEXEC) = 3
        $
      
      Trace the first minor page fault when running a workload:
      
        # perf trace -F min --max-stack=7 --max-events 1 sleep 1
           0.000 ( 0.000 ms): sleep/18006 minfault [__clear_user+0x1a] => 0x5626efa56080 (?k)
                                             __clear_user ([kernel.kallsyms])
                                             load_elf_binary ([kernel.kallsyms])
                                             search_binary_handler ([kernel.kallsyms])
                                             __do_execve_file.isra.33 ([kernel.kallsyms])
                                             __x64_sys_execve ([kernel.kallsyms])
                                             do_syscall_64 ([kernel.kallsyms])
                                             entry_SYSCALL_64 ([kernel.kallsyms])
        #
      
      Trace the next min page page fault to take place on the first CPU:
      
        # perf trace -F min --call-graph=dwarf --max-events 1 --cpu 0
           0.000 ( 0.000 ms): Web Content/17136 minfault [js::gc::Chunk::fetchNextDecommittedArena+0x4b] => 0x7fbe6181b000 (?.)
                                             js::gc::FreeSpan::initAsEmpty (inlined)
                                             js::gc::Arena::setAsNotAllocated (inlined)
                                             js::gc::Chunk::fetchNextDecommittedArena (/usr/lib64/firefox/libxul.so)
                                             js::gc::Chunk::allocateArena (/usr/lib64/firefox/libxul.so)
                                             js::gc::GCRuntime::allocateArena (/usr/lib64/firefox/libxul.so)
                                             js::gc::ArenaLists::allocateFromArena (/usr/lib64/firefox/libxul.so)
                                             js::gc::GCRuntime::tryNewTenuredThing<JSString, (js::AllowGC)1> (inlined)
                                             js::AllocateString<JSString, (js::AllowGC)1> (/usr/lib64/firefox/libxul.so)
                                             js::Allocate<JSThinInlineString, (js::AllowGC)1> (inlined)
                                             JSThinInlineString::new_<(js::AllowGC)1> (inlined)
                                             AllocateInlineString<(js::AllowGC)1, unsigned char> (inlined)
                                             js::ConcatStrings<(js::AllowGC)1> (/usr/lib64/firefox/libxul.so)
                                             [0x18b26e6bc2bd] (/tmp/perf-17136.map)
      
      Tracing the next four ext4 operations on a specific CPU:
      
        # perf trace -e ext4:*/call-graph=fp/ --max-events 4 --cpu 3
           0.000 mutt/3849 ext4:ext4_es_lookup_extent_enter:dev 253,2 ino 57277 lblk 0
                                             ext4_es_lookup_extent ([kernel.kallsyms])
                                             read (/usr/lib64/libc-2.26.so)
           0.097 mutt/3849 ext4:ext4_es_lookup_extent_exit:dev 253,2 ino 57277 found 0 [0/0) 0
                                             ext4_es_lookup_extent ([kernel.kallsyms])
                                             read (/usr/lib64/libc-2.26.so)
           0.141 mutt/3849 ext4:ext4_ext_map_blocks_enter:dev 253,2 ino 57277 lblk 0 len 1 flags
                                             ext4_ext_map_blocks ([kernel.kallsyms])
                                             read (/usr/lib64/libc-2.26.so)
           0.184 mutt/3849 ext4:ext4_ext_load_extent:dev 253,2 ino 57277 lblk 1516511 pblk 18446744071750013657
                                             __read_extent_tree_block ([kernel.kallsyms])
                                             __read_extent_tree_block ([kernel.kallsyms])
                                             ext4_find_extent ([kernel.kallsyms])
                                             ext4_ext_map_blocks ([kernel.kallsyms])
                                             ext4_map_blocks ([kernel.kallsyms])
                                             ext4_mpage_readpages ([kernel.kallsyms])
                                             read_pages ([kernel.kallsyms])
                                             __do_page_cache_readahead ([kernel.kallsyms])
                                             ondemand_readahead ([kernel.kallsyms])
                                             generic_file_read_iter ([kernel.kallsyms])
                                             __vfs_read ([kernel.kallsyms])
                                             vfs_read ([kernel.kallsyms])
                                             ksys_read ([kernel.kallsyms])
                                             do_syscall_64 ([kernel.kallsyms])
                                             entry_SYSCALL_64 ([kernel.kallsyms])
                                             read (/usr/lib64/libc-2.26.so)
        #
      
      Cc: Adrian Hunter <adrian.hunter@intel.com>
      Cc: David Ahern <dsahern@gmail.com>
      Cc: Jiri Olsa <jolsa@kernel.org>
      Cc: Milian Wolff <milian.wolff@kdab.com>
      Cc: Namhyung Kim <namhyung@kernel.org>
      Cc: Rudá Moura <ruda.moura@gmail.com>
      Cc: Wang Nan <wangnan0@huawei.com>
      Link: https://lkml.kernel.org/n/tip-sweh107bs7ol5bzls0m4tqdz@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      5067a8cd
  9. 20 9月, 2018 3 次提交
  10. 05 9月, 2018 2 次提交
    • A
      perf trace: Use the raw_syscalls:sys_enter for the augmented syscalls · b1a9e253
      Arnaldo Carvalho de Melo 提交于
      Now we combine what comes from the "bpf-output" event, i.e. what is
      added in the augmented_syscalls.c BPF program via the
      __augmented_syscalls__ BPF map, i.e. the payload we get with
      raw_syscalls:sys_enter tracepoints plus the pointer contents, right
      after that payload, with the raw_syscall:sys_exit also added, without
      augmentation, in the augmented_syscalls.c program.
      
      The end result is that for the hooked syscalls, we get strace like
      output with pointer expansion, something that wasn't possible before
      with just raw_syscalls:sys_enter + raw_syscalls:sys_exit.
      
      E.g.:
      
        # perf trace -e tools/perf/examples/bpf/augmented_syscalls.c ping -c 2 ::1
           0.000 ( 0.008 ms): ping/19573 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: CLOEXEC) = 3
           0.036 ( 0.006 ms): ping/19573 openat(dfd: CWD, filename: /lib64/libcap.so.2, flags: CLOEXEC) = 3
           0.070 ( 0.004 ms): ping/19573 openat(dfd: CWD, filename: /lib64/libidn.so.11, flags: CLOEXEC) = 3
           0.095 ( 0.004 ms): ping/19573 openat(dfd: CWD, filename: /lib64/libcrypto.so.1.1, flags: CLOEXEC) = 3
           0.127 ( 0.004 ms): ping/19573 openat(dfd: CWD, filename: /lib64/libresolv.so.2, flags: CLOEXEC) = 3
           0.156 ( 0.004 ms): ping/19573 openat(dfd: CWD, filename: /lib64/libm.so.6, flags: CLOEXEC) = 3
           0.181 ( 0.004 ms): ping/19573 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: CLOEXEC) = 3
           0.212 ( 0.004 ms): ping/19573 openat(dfd: CWD, filename: /lib64/libz.so.1, flags: CLOEXEC) = 3
           0.242 ( 0.004 ms): ping/19573 openat(dfd: CWD, filename: /lib64/libdl.so.2, flags: CLOEXEC) = 3
           0.266 ( 0.003 ms): ping/19573 openat(dfd: CWD, filename: /lib64/libpthread.so.0, flags: CLOEXEC) = 3
           0.709 ( 0.006 ms): ping/19573 open(filename: /usr/lib/locale/locale-archive, flags: CLOEXEC) = 3
        PING ::1(::1) 56 data bytes
           1.133 ( 0.011 ms): ping/19573 connect(fd: 5, uservaddr: { .family: INET6, port: 1025, addr: ::1 }, addrlen: 28) = 0
        64 bytes from ::1: icmp_seq=1 ttl=64 time=0.033 ms
           1.234 ( 0.036 ms): ping/19573 sendto(fd: 4<socket:[1498931]>, buff: 0x555e5b975720, len: 64, addr: { .family: INET6, port: 58, addr: ::1 }, addr_len: 28) = 64
        64 bytes from ::1: icmp_seq=2 ttl=64 time=0.120 ms
      
        --- ::1 ping statistics ---
        2 packets transmitted, 2 received, 0% packet loss, time 1000ms
        rtt min/avg/max/mdev = 0.033/0.076/0.120/0.044 ms
        1002.060 ( 0.129 ms): ping/19573 sendto(fd: 4<socket:[1498931]>, buff: 0x555e5b975720, len: 64, flags: CONFIRM, addr: { .family: INET6, port: 58, addr: ::1 }, addr_len: 28) = 64
        #
        # perf trace -e tools/perf/examples/bpf/augmented_syscalls.c cat tools/perf/examples/bpf/hello.c
        #include <stdio.h>
      
        int syscall_enter(openat)(void *args)
        {
      	  puts("Hello, world\n");
      	  return 0;
        }
      
        license(GPL);
           0.000 ( 0.008 ms): cat/20054 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: CLOEXEC) = 3
           0.020 ( 0.005 ms): cat/20054 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: CLOEXEC) = 3
           0.176 ( 0.011 ms): cat/20054 open(filename: /usr/lib/locale/locale-archive, flags: CLOEXEC) = 3
           0.243 ( 0.006 ms): cat/20054 openat(dfd: CWD, filename: tools/perf/examples/bpf/hello.c) = 3
        #
      
      Now to think how to hook on all syscalls, fallbacking to the non-augmented
      raw_syscalls:sys_enter payload.
      
      Probably the best way is to use a BPF_MAP_TYPE_PROG_ARRAY just like
      samples/bpf/tracex5_kern.c does.
      
      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-nlt60y69o26xi59z5vtpdrj5@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      b1a9e253
    • A
      perf trace: Setup augmented_args in the raw_syscalls:sys_enter handler · db2da3f8
      Arnaldo Carvalho de Melo 提交于
      Without using something to augment the raw_syscalls:sys_enter tracepoint
      payload with the pointer contents, this will work just like before, i.e.
      the augmented_args arg will be NULL and the augmented_args_size will be
      0.
      
      This just paves the way for the next cset where we will associate the
      trace__sys_enter tracepoint handler with the augmented "bpf-output"
      event named "__augmented_args__".
      
      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-p8uvt2a6ug3uwlhja3cno4la@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      db2da3f8
  11. 04 9月, 2018 1 次提交
  12. 31 8月, 2018 10 次提交
    • B
      perf trace beauty: Alias 'umount' to 'umount2' · 3de3e8bb
      Benjamin Peterson 提交于
      Before:
      
        # perf trace -e *mount* umount /dev/mapper/fedora-home /s
          11.576 ( 0.004 ms) umount/3138 umount2(arg0: 94501956754656, arg1: 0, arg2: 1, arg3: 140051050083104, arg4: 4, arg5: 94501956755136) = -1 EINVAL Invalid argument
        #
      
      After:
      
        # perf trace -e *mount* umount /s
           0.000 ( 9.241 ms): umount/5251 umount2(name: 0x55f74a986480) = 0
      Signed-off-by: NBenjamin Peterson <benjamin@python.org>
      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>
      Cc: Peter Zijlstra <peterz@infradead.org>
      Link: http://lkml.kernel.org/r/20180828035344.31500-1-benjamin@python.org
      [ split from a larger patch ]
      Signed-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      3de3e8bb
    • A
      perf trace: Show comm and tid for tracepoint events · c4191e55
      Arnaldo Carvalho de Melo 提交于
      So that all events have that info, improving reading by having
      information better aligned, etc.
      
      Before:
      
        # echo 1 > /proc/sys/vm/drop_caches
        # perf trace -e block:*,ext4:*,tools/perf/examples/bpf/augmented_syscalls.c,close cat tools/perf/examples/bpf/hello.c
             0.000 (         ): #include <stdio.h>
      
        int syscall_enter(openat)(void *args)
        {
        	puts("Hello, world\n");
        	return 0;
        }
      
        license(GPL);
        cat/2731 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: CLOEXEC)
             0.025 (         ): syscalls:sys_exit_openat:0x3
             0.063 ( 0.022 ms): cat/2731 close(fd: 3) = 0
             0.110 (         ): cat/2731 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: CLOEXEC)
             0.123 (         ): syscalls:sys_exit_openat:0x3
             0.243 ( 0.008 ms): cat/2731 close(fd: 3) = 0
             0.485 (         ): cat/2731 open(filename: /usr/lib/locale/locale-archive, flags: CLOEXEC)
             0.500 (         ): syscalls:sys_exit_open:0x3
             0.531 ( 0.017 ms): cat/2731 close(fd: 3) = 0
             0.587 (         ): cat/2731 openat(dfd: CWD, filename: tools/perf/examples/bpf/hello.c)
             0.601 (         ): syscalls:sys_exit_openat:0x3
             0.631 (         ): ext4:ext4_es_lookup_extent_enter:dev 253,2 ino 1311399 lblk 0
             0.639 (         ): ext4:ext4_es_lookup_extent_exit:dev 253,2 ino 1311399 found 1 [0/1) 5276651 W0x10
             0.654 (         ): block:block_bio_queue:253,2 R 42213208 + 8 [cat]
             0.663 (         ): block:block_bio_remap:8,0 R 58206040 + 8 <- (253,2) 42213208
             0.671 (         ): block:block_bio_remap:8,0 R 175570776 + 8 <- (8,6) 58206040
             0.678 (         ): block:block_bio_queue:8,0 R 175570776 + 8 [cat]
             0.692 (         ): block:block_getrq:8,0 R 175570776 + 8 [cat]
             0.700 (         ): block:block_plug:[cat]
             0.708 (         ): block:block_rq_insert:8,0 R 4096 () 175570776 + 8 [cat]
             0.713 (         ): block:block_unplug:[cat] 1
             0.716 (         ): block:block_rq_issue:8,0 R 4096 () 175570776 + 8 [cat]
             0.949 ( 0.007 ms): cat/2731 close(fd: 3) = 0
             0.969 ( 0.006 ms): cat/2731 close(fd: 1) = 0
             0.982 ( 0.006 ms): cat/2731 close(fd: 2) = 0
        #
      
      After:
      
        # echo 1 > /proc/sys/vm/drop_caches
        # perf trace -e block:*,ext4:*,tools/perf/examples/bpf/augmented_syscalls.c,close cat tools/perf/examples/bpf/hello.c
             0.000 (         ): cat/1380 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: CLOEXEC)#include <stdio.h>
      
        int syscall_enter(openat)(void *args)
        {
        	puts("Hello, world\n");
        	return 0;
        }
      
        license(GPL);
      
             0.024 (         ): cat/1380 syscalls:sys_exit_openat:0x3
             0.063 ( 0.024 ms): cat/1380 close(fd: 3) = 0
             0.114 (         ): cat/1380 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: CLOEXEC)
             0.127 (         ): cat/1380 syscalls:sys_exit_openat:0x3
             0.247 ( 0.009 ms): cat/1380 close(fd: 3) = 0
             0.484 (         ): cat/1380 open(filename: /usr/lib/locale/locale-archive, flags: CLOEXEC)
             0.499 (         ): cat/1380 syscalls:sys_exit_open:0x3
             0.613 ( 0.010 ms): cat/1380 close(fd: 3) = 0
             0.662 (         ): cat/1380 openat(dfd: CWD, filename: tools/perf/examples/bpf/hello.c)
             0.678 (         ): cat/1380 syscalls:sys_exit_openat:0x3
             0.712 (         ): cat/1380 ext4:ext4_es_lookup_extent_enter:dev 253,2 ino 1311399 lblk 0
             0.721 (         ): cat/1380 ext4:ext4_es_lookup_extent_exit:dev 253,2 ino 1311399 found 1 [0/1) 5276651 W0x10
             0.734 (         ): cat/1380 block:block_bio_queue:253,2 R 42213208 + 8 [cat]
             0.745 (         ): cat/1380 block:block_bio_remap:8,0 R 58206040 + 8 <- (253,2) 42213208
             0.754 (         ): cat/1380 block:block_bio_remap:8,0 R 175570776 + 8 <- (8,6) 58206040
             0.761 (         ): cat/1380 block:block_bio_queue:8,0 R 175570776 + 8 [cat]
             0.780 (         ): cat/1380 block:block_getrq:8,0 R 175570776 + 8 [cat]
             0.791 (         ): cat/1380 block:block_plug:[cat]
             0.802 (         ): cat/1380 block:block_rq_insert:8,0 R 4096 () 175570776 + 8 [cat]
             0.806 (         ): cat/1380 block:block_unplug:[cat] 1
             0.810 (         ): cat/1380 block:block_rq_issue:8,0 R 4096 () 175570776 + 8 [cat]
             1.005 ( 0.011 ms): cat/1380 close(fd: 3) = 0
             1.031 ( 0.008 ms): cat/1380 close(fd: 1) = 0
             1.048 ( 0.008 ms): cat/1380 close(fd: 2) = 0
        #
      
      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-us1mwsupxffs4jlm3uqm5dvj@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      c4191e55
    • A
      perf trace augmented_syscalls: Augment sendto's 'addr' arg · 6ebb6862
      Arnaldo Carvalho de Melo 提交于
      Its a 'struct sockaddr' pointer, augment it with the same beautifier as
      for 'connect' and 'bind', that all receive from userspace that pointer.
      
      Doing it in the other direction remains to be done, hooking at the
      syscalls:sys_exit_{accept4?,recvmsg} tracepoints somehow.
      
      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-k2eu68lsphnm2fthc32gq76c@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      6ebb6862
    • A
      perf trace augmented_syscalls: Augment bind's 'myaddr' sockaddr arg · 02ef2884
      Arnaldo Carvalho de Melo 提交于
      One more, to reuse the augmented_sockaddr_syscall_enter() macro
      introduced from the augmentation of connect's sockaddr arg, also to get
      a subset of the struct arg augmentations done using the manual method,
      before switching to something automatic, using tracefs's format file or,
      even better, BTF containing the syscall args structs.
      
        # perf trace -e tools/perf/examples/bpf/augmented_syscalls.c
           0.000 sshd/11479 bind(fd: 3<socket:[170336]>, umyaddr: { .family: NETLINK }, addrlen: 12)
           1.752 sshd/11479 bind(fd: 3<socket:[170336]>, umyaddr: { .family: INET, port: 22, addr: 0.0.0.0 }, addrlen: 16)
           1.924 sshd/11479 bind(fd: 4<socket:[170338]>, umyaddr: { .family: INET6, port: 22, addr: :: }, addrlen: 28)
        ^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-a2drqpahpmc7uwb3n3gj2plu@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      02ef2884
    • A
      perf trace augmented_syscalls: Augment connect's 'sockaddr' arg · d5a7e661
      Arnaldo Carvalho de Melo 提交于
      As the first example of augmenting something other than a 'filename',
      augment the 'struct sockaddr' argument for the 'connect' syscall:
      
        # perf trace -e tools/perf/examples/bpf/augmented_syscalls.c ssh -6 fedorapeople.org
           0.000 ssh/29669 connect(fd: 3, uservaddr: { .family: LOCAL, path: /var/run/nscd/socket }, addrlen: 110)
           0.042 ssh/29669 connect(fd: 3, uservaddr: { .family: LOCAL, path: /var/run/nscd/socket }, addrlen: 110)
           1.329 ssh/29669 connect(fd: 3, uservaddr: { .family: LOCAL, path: /var/run/nscd/socket }, addrlen: 110)
           1.362 ssh/29669 connect(fd: 3, uservaddr: { .family: LOCAL, path: /var/run/nscd/socket }, addrlen: 110)
           1.458 ssh/29669 connect(fd: 3, uservaddr: { .family: LOCAL, path: /var/run/nscd/socket }, addrlen: 110)
           1.478 ssh/29669 connect(fd: 3, uservaddr: { .family: LOCAL, path: /var/run/nscd/socket }, addrlen: 110)
           1.683 ssh/29669 connect(fd: 3<socket:[125942]>, uservaddr: { .family: INET, port: 53, addr: 192.168.43.1 }, addrlen: 16)
           4.710 ssh/29669 connect(fd: 3<socket:[125942]>, uservaddr: { .family: INET6, port: 22, addr: 2610:28:3090:3001:5054:ff:fea7:9474 }, addrlen: 28)
        root@fedorapeople.org: Permission denied (publickey).
        #
      
      This is still just augmenting the syscalls:sys_enter_connect part, later
      we'll wire this up to augment the enter+exit combo, like in the
      tradicional 'perf trace' and 'strace' outputs.
      
      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-s7l541cbiqb22ifio6z7dpf6@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      d5a7e661
    • A
      perf trace: Use the augmented filename, expanding syscall enter pointers · 75d1e306
      Arnaldo Carvalho de Melo 提交于
      This is the final touch in showing how a syscall argument beautifier can
      access the augmented args put in place by the
      tools/perf/examples/bpf/augmented_syscalls.c eBPF script, right after
      the regular raw syscall args, i.e. the up to 6 long integer values in
      the syscall interface.
      
      With this we are able to show the 'openat' syscall arg, now with up to
      64 bytes, but in time this will be configurable, just like with the
      'strace -s strsize' argument, from 'strace''s man page:
      
        -s strsize  Specify the maximum string size to print (the default is 32).
      
      This actually is the maximum string to _collect_ and store in the ring
      buffer, not just print.
      
      Before:
      
        # perf trace -e tools/perf/examples/bpf/augmented_syscalls.c,openat cat /etc/passwd > /dev/null
           0.000 (         ): cat/9658 openat(dfd: CWD, filename: 0x6626eda8, flags: CLOEXEC)
           0.017 ( 0.007 ms): cat/9658 openat(dfd: CWD, filename: 0x6626eda8, flags: CLOEXEC) = 3
           0.049 (         ): cat/9658 openat(dfd: CWD, filename: 0x66476ce0, flags: CLOEXEC)
           0.051 ( 0.007 ms): cat/9658 openat(dfd: CWD, filename: 0x66476ce0, flags: CLOEXEC) = 3
           0.377 (         ): cat/9658 openat(dfd: CWD, filename: 0x1e8f806b)
           0.379 ( 0.005 ms): cat/9658 openat(dfd: CWD, filename: 0x1e8f806b) = 3
        #
      
      After:
      
        # perf trace -e tools/perf/examples/bpf/augmented_syscalls.c,openat cat /etc/passwd > /dev/null
           0.000 (         ): cat/11966 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: CLOEXEC)
           0.006 ( 0.006 ms): cat/11966 openat(dfd: CWD, filename: 0x4bfdcda8, flags: CLOEXEC) = 3
           0.034 (         ): cat/11966 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: CLOEXEC)
           0.036 ( 0.008 ms): cat/11966 openat(dfd: CWD, filename: 0x4c1e4ce0, flags: CLOEXEC) = 3
           0.375 (         ): cat/11966 openat(dfd: CWD, filename: /etc/passwd)
           0.377 ( 0.005 ms): cat/11966 openat(dfd: CWD, filename: 0xe87906b) = 3
        #
      
      This cset should show all the aspects of establishing a protocol between
      an eBPF syscall arg augmenter program, tools/perf/examples/bpf/augmented_syscalls.c and
      a 'perf trace' beautifier, the one associated with all 'char *' point
      syscall args with names that can heuristically be associated with
      filenames.
      
      Now to wire up 'open' to show a second syscall using this scheme, all we
      have to do now is to change tools/perf/examples/bpf/augmented_syscalls.c,
      as 'perf trace' will notice that the perf_sample.raw_size is more than
      what is expected for a particular syscall payload as defined by its
      tracefs format file and will then use the augmented payload in the
      'filename' syscall arg beautifier.
      
      The same protocol will be used for structs such as 'struct sockaddr *',
      'struct pollfd', etc, with additions for handling arrays.
      
      This will all be done under the hood when 'perf trace' realizes the
      system has the necessary components, and also can be done by providing
      a precompiled augmented_syscalls.c eBPF ELF object.
      
      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-gj9kqb61wo7m3shtpzercbcr@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      75d1e306
    • A
      perf trace: Show comm/tid for augmented_syscalls · c96f4edc
      Arnaldo Carvalho de Melo 提交于
      To get us a bit more like the sys_enter + sys_exit combo:
      
        # perf trace -e tools/perf/examples/bpf/augmented_syscalls.c,openat cat /etc/passwd > /dev/null
           0.000 (         ): openat(dfd: CWD, filename: 0x31b6dda8, flags: CLOEXEC)
           0.009 ( 0.009 ms): cat/3619 openat(dfd: CWD, filename: 0x31b6dda8, flags: CLOEXEC) = 3
           0.051 (         ): openat(dfd: CWD, filename: 0x31d75ce0, flags: CLOEXEC)
           0.054 ( 0.010 ms): cat/3619 openat(dfd: CWD, filename: 0x31d75ce0, flags: CLOEXEC) = 3
           0.539 (         ): openat(dfd: CWD, filename: 0xca71506b)
           0.543 ( 0.115 ms): cat/3619 openat(dfd: CWD, filename: 0xca71506b) = 3
        #
      
      After:
      
        # perf trace -e tools/perf/examples/bpf/augmented_syscalls.c,openat cat /etc/passwd > /dev/null
           0.000 (         ): cat/4919 openat(dfd: CWD, filename: 0xc8358da8, flags: CLOEXEC)
           0.007 ( 0.005 ms): cat/4919 openat(dfd: CWD, filename: 0xc8358da8, flags: CLOEXEC) = 3
           0.032 (         ): cat/4919 openat(dfd: CWD, filename: 0xc8560ce0, flags: CLOEXEC)
           0.033 ( 0.006 ms): cat/4919 openat(dfd: CWD, filename: 0xc8560ce0, flags: CLOEXEC) = 3
           0.301 (         ): cat/4919 openat(dfd: CWD, filename: 0x91fa306b)
           0.304 ( 0.004 ms): cat/4919 openat(dfd: CWD, filename: 0x91fa306b) = 3
        #
      
      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-6w8ytyo5y655a1hsyfpfily6@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      c96f4edc
    • A
      perf trace: Extract the comm/tid printing for syscall enter · 6dcbd212
      Arnaldo Carvalho de Melo 提交于
      Will be used with augmented syscalls, where we haven't transitioned
      completely to combining sys_enter_FOO with sys_exit_FOO, so we'll go
      as far as having it similar to the end result, strace like, as possible.
      
      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-canomaoiybkswwnhj69u9ae4@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      6dcbd212
    • A
      perf trace: Print the syscall name for augmented_syscalls · 1cdf618f
      Arnaldo Carvalho de Melo 提交于
      Since we copy all the payload for raw_syscalls:sys_enter plus add
      expanded pointers, we can use the syscall id to get its name, etc:
      
        # grep 'field:.* id' /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/format
      	field:long id;	offset:8;	size:8;	signed:1;
        #
      
      Before:
      
        # perf trace -e tools/perf/examples/bpf/augmented_syscalls.c,openat cat /etc/passwd > /dev/null
           0.000 (         ): __augmented_syscalls__:dfd: CWD, filename: 0xec9f9da8, flags: CLOEXEC
           0.006 ( 0.006 ms): cat/2395 openat(dfd: CWD, filename: 0xec9f9da8, flags: CLOEXEC) = 3
           0.041 (         ): __augmented_syscalls__:dfd: CWD, filename: 0xecc01ce0, flags: CLOEXEC
           0.042 ( 0.007 ms): cat/2395 openat(dfd: CWD, filename: 0xecc01ce0, flags: CLOEXEC) = 3
           0.376 (         ): __augmented_syscalls__:dfd: CWD, filename: 0xac0a806b
           0.379 ( 0.006 ms): cat/2395 openat(dfd: CWD, filename: 0xac0a806b) = 3
        #
      
      After:
      
        # perf trace -e tools/perf/examples/bpf/augmented_syscalls.c,openat cat /etc/passwd > /dev/null
           0.000 (         ): openat(dfd: CWD, filename: 0x31b6dda8, flags: CLOEXEC)
           0.009 ( 0.009 ms): cat/3619 openat(dfd: CWD, filename: 0x31b6dda8, flags: CLOEXEC) = 3
           0.051 (         ): openat(dfd: CWD, filename: 0x31d75ce0, flags: CLOEXEC)
           0.054 ( 0.010 ms): cat/3619 openat(dfd: CWD, filename: 0x31d75ce0, flags: CLOEXEC) = 3
           0.539 (         ): openat(dfd: CWD, filename: 0xca71506b)
           0.543 ( 0.115 ms): cat/3619 openat(dfd: CWD, filename: 0xca71506b) = 3
        #
      
      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-epz6y9i0eavmerc5ha98t7gn@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      1cdf618f
    • A
      perf trace: Pass augmented args to the arg formatters when available · 7a983a0f
      Arnaldo Carvalho de Melo 提交于
      If the tracepoint payload is bigger than what a syscall expected from
      what is in its format file in tracefs, then that will be used as
      augmented args, i.e. the expansion of syscall arg pointers, with things
      like a filename, structs, 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: https://lkml.kernel.org/n/tip-bsbqx7xi2ot4q9bf570f7tqs@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      7a983a0f
  13. 09 8月, 2018 4 次提交
    • A
      perf trace: Wire up the augmented syscalls with the syscalls:sys_enter_FOO beautifier · 88cf7084
      Arnaldo Carvalho de Melo 提交于
      We just check that the evsel is the one we associated with the
      bpf-output event associated with the "__augmented_syscalls__" eBPF map,
      to show that the formatting is done properly:
      
        # perf trace -e perf/tools/perf/examples/bpf/augmented_syscalls.c,openat cat /etc/passwd > /dev/null
           0.000 (         ): __augmented_syscalls__:dfd: CWD, filename: 0x43e06da8, flags: CLOEXEC
           0.006 (         ): syscalls:sys_enter_openat:dfd: CWD, filename: 0x43e06da8, flags: CLOEXEC
           0.007 ( 0.004 ms): cat/11486 openat(dfd: CWD, filename: 0x43e06da8, flags: CLOEXEC                 ) = 3
           0.029 (         ): __augmented_syscalls__:dfd: CWD, filename: 0x4400ece0, flags: CLOEXEC
           0.030 (         ): syscalls:sys_enter_openat:dfd: CWD, filename: 0x4400ece0, flags: CLOEXEC
           0.031 ( 0.004 ms): cat/11486 openat(dfd: CWD, filename: 0x4400ece0, flags: CLOEXEC                 ) = 3
           0.249 (         ): __augmented_syscalls__:dfd: CWD, filename: 0xc3700d6
           0.250 (         ): syscalls:sys_enter_openat:dfd: CWD, filename: 0xc3700d6
           0.252 ( 0.003 ms): cat/11486 openat(dfd: CWD, filename: 0xc3700d6                                  ) = 3
        #
      
      Now we just need to get the full blown enter/exit handlers to check if the
      evsel being processed is the augmented_syscalls one to go pick the pointer
      payloads from the end of the payload.
      
      We also need to state somehow what is the layout for multi pointer arg syscalls.
      
      Also handy would be to have a BTF file with the struct definitions used in
      syscalls, compact, generated at kernel built time and available for use in eBPF
      programs.
      
      Till we get there we can go on doing some manual coupling of the most relevant
      syscalls with some hand built beautifiers.
      
      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-r6ba5izrml82nwfmwcp7jpkm@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      88cf7084
    • A
      perf trace: Setup the augmented syscalls bpf-output event fields · d3d1c4bd
      Arnaldo Carvalho de Melo 提交于
      The payload that is put in place by the eBPF script attached to
      syscalls:sys_enter_openat (and other syscalls with pointers, in the
      future) can be consumed by the existing sys_enter beautifiers if
      evsel->priv is setup with a struct syscall_tp with struct tp_fields for
      the 'syscall_id' and 'args' fields expected by the beautifiers, this
      patch does just that.
      
      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-xfjyog8oveg2fjys9r1yy1es@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      d3d1c4bd
    • A
      perf bpf: Make bpf__setup_output_event() return the bpf-output event · 78e890ea
      Arnaldo Carvalho de Melo 提交于
      We're calling it to setup that event, and we'll need it later to decide
      if the bpf-output event we're handling is the one setup for a specific
      purpose, return it using ERR_PTR, 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: https://lkml.kernel.org/n/tip-zhachv7il2n1lopt9aonwhu7@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      78e890ea
    • A
      perf trace: Handle "bpf-output" events associated with "__augmented_syscalls__" BPF map · e0b6d2ef
      Arnaldo Carvalho de Melo 提交于
      Add an example BPF script that writes syscalls:sys_enter_openat raw
      tracepoint payloads augmented with the first 64 bytes of the "filename"
      syscall pointer arg.
      
      Then catch it and print it just like with things written to the
      "__bpf_stdout__" map associated with a PERF_COUNT_SW_BPF_OUTPUT software
      event, by just letting the default tracepoint handler in 'perf trace',
      trace__event_handler(), to use bpf_output__fprintf(trace, sample), just
      like it does with all other PERF_COUNT_SW_BPF_OUTPUT events, i.e. just
      do a dump on the payload, so that we can check if what is being printed
      has at least the first 64 bytes of the "filename" arg:
      
      The augmented_syscalls.c eBPF script:
      
        # cat tools/perf/examples/bpf/augmented_syscalls.c
        // SPDX-License-Identifier: GPL-2.0
      
        #include <stdio.h>
      
        struct bpf_map SEC("maps") __augmented_syscalls__ = {
             .type = BPF_MAP_TYPE_PERF_EVENT_ARRAY,
             .key_size = sizeof(int),
             .value_size = sizeof(u32),
             .max_entries = __NR_CPUS__,
        };
      
        struct syscall_enter_openat_args {
      	unsigned long long common_tp_fields;
      	long		   syscall_nr;
      	long		   dfd;
      	char		   *filename_ptr;
      	long		   flags;
      	long		   mode;
        };
      
        struct augmented_enter_openat_args {
      	struct syscall_enter_openat_args args;
      	char				 filename[64];
        };
      
        int syscall_enter(openat)(struct syscall_enter_openat_args *args)
        {
      	struct augmented_enter_openat_args augmented_args;
      
      	probe_read(&augmented_args.args, sizeof(augmented_args.args), args);
      	probe_read_str(&augmented_args.filename, sizeof(augmented_args.filename), args->filename_ptr);
      	perf_event_output(args, &__augmented_syscalls__, BPF_F_CURRENT_CPU,
      			  &augmented_args, sizeof(augmented_args));
      	return 1;
        }
      
        license(GPL);
        #
      
      So it will just prepare a raw_syscalls:sys_enter payload for the
      "openat" syscall.
      
      This will eventually be done for all syscalls with pointer args,
      globally or just when the user asks, using some spec, which args of
      which syscalls it wants "expanded" this way, we'll probably start with
      just all the syscalls that have char * pointers with familiar names, the
      ones we already handle with the probe:vfs_getname kprobe if it is in
      place hooking the kernel getname_flags() function used to copy from user
      the paths.
      
      Running it we get:
      
        # perf trace -e perf/tools/perf/examples/bpf/augmented_syscalls.c,openat cat /etc/passwd > /dev/null
           0.000 (         ): __augmented_syscalls__:X?.C......................`\..................../etc/ld.so.cache..#......,....ao.k...............k......1.".........
           0.006 (         ): syscalls:sys_enter_openat:dfd: CWD, filename: 0x5c600da8, flags: CLOEXEC
           0.008 ( 0.005 ms): cat/31292 openat(dfd: CWD, filename: 0x5c600da8, flags: CLOEXEC                 ) = 3
           0.036 (         ): __augmented_syscalls__:X?.C.......................\..................../lib64/libc.so.6......... .\....#........?.......=.C..../.".........
           0.037 (         ): syscalls:sys_enter_openat:dfd: CWD, filename: 0x5c808ce0, flags: CLOEXEC
           0.039 ( 0.007 ms): cat/31292 openat(dfd: CWD, filename: 0x5c808ce0, flags: CLOEXEC                 ) = 3
           0.323 (         ): __augmented_syscalls__:X?.C.....................P....................../etc/passwd......>.C....@................>.C.....,....ao.>.C........
           0.325 (         ): syscalls:sys_enter_openat:dfd: CWD, filename: 0xe8be50d6
           0.327 ( 0.004 ms): cat/31292 openat(dfd: CWD, filename: 0xe8be50d6                                 ) = 3
        #
      
      We need to go on optimizing this to avoid seding trash or zeroes in the
      pointer content payload, using the return from bpf_probe_read_str(), but
      to keep things simple at this stage and make incremental progress, lets
      leave it at that for now.
      
      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-g360n1zbj6bkbk6q0qo11c28@git.kernel.orgSigned-off-by: NArnaldo Carvalho de Melo <acme@redhat.com>
      e0b6d2ef
  14. 03 8月, 2018 4 次提交