Beautifying 'perf trace'
Author: Arnaldo Carvalho de Melo
Description: Beautifying syscall args using kernel headers and eBPF in 'perf > trace'.

Beautifying syscall args in 'perf trace'.
Using kernel header parsing and eBPF
Arnaldo Carvalho de Melo
Red Hat Inc.

## Goals

- Add to perf toolchest
- Explore tools synergies
- Not just syscalls
- Mix and match with other tracepoints
- Thread lifetime events
- eBPF integration
- No ptrace

### perf workflow

- record + report
- perf.data
- cross arch analysis
- live: top, annotate, trace

### perf record

    # perf record -a -e syscalls:sys_enter_futex sleep 10
    [ perf record: Woken up 1 times to write data ]
    [ perf record: Captured and wrote 1.645 MB perf.data (242 samples) ]
    #
    # ls -lah perf.data
    -rw-------. 1 root root 1.7M Jan 18 11:38 perf.data
    #

### perf evlist

    # perf evlist
    syscalls:sys_enter_futex
    # Tip: use 'perf evlist --trace-fields' to show fields for tracepoint events
    #

### perf evlist

    # perf evlist --trace-fields
    syscalls:sys_enter_futex: trace_fields: __syscall_nr,uaddr,op,val,utime,uaddr2,val3
    #

### perf script

    # perf script
       named 7012 1 09.524377 sys_enter_futex uaddr 0x7fea293940cc op 0x80 val 0 utime 0x0 uaddr2 0x1 val3 0x0
    CPU0/KVM 6767 1 11.177722 sys_enter_futex uaddr 0x55a101643560 op 0x80 val 2 utime 0x0 uaddr2 0x55a101643560 val3 0x8
    qemu-x86 6721 2 11.177766 sys_enter_futex uaddr 0x55a101643560 op 0x81 val 1 utime 0x7fc45807d4a0 uaddr2 0x0 val3 0x7fc458085f10
    CPU0/KVM 6767 1 11.177828 sys_enter_futex uaddr 0x55a101643560 op 0x81 val 1 utime 0x8 uaddr2 0x0 val3 0xffffffff
    CPU0/KVM 6767 0 12.141761 sys_enter_futex uaddr 0x55a101643560 op 0x80 val 2 utime 0x0 uaddr2 0x55a101643560 val3 0x2
    qemu-x86 6721 2 12.141766 sys_enter_futex uaddr 0x55a101643560 op 0x81 val 1 utime 0x7fc45807d4a0 uaddr2 0x0 val3 0x7fc458085f10

### targets

- Same as for 'record', 'top'
- -a, --all-cpus
- -C, --cpu cpu-list
- -p, --pid pid-list
- -t, --tid tid-list
- -u, --uid user

### system wide stracing

    # perf trace -e futex --duration 1
     200.139 (2999.515 ms) virt-manager/3384 futex(uaddr: 0x7fb9280039d0, op: WAIT_BITSET|PRIV|CLKRT, val3: MATCH_ANY) = 0
    3202.723 (3000.439 ms) virt-manager/3384 futex(uaddr: 0x7fb928001950, op: WAIT_BITSET|PRIV|CLKRT, val3: MATCH_ANY) = 0
     196.247 (6009.648 ms) libvirtd/1084 futex(uaddr: 0x5573466d9f60, op: WAIT|PRIV) = 0
    2029.069 (4999.934 ms) docker-contain/3259 futex(uaddr: 0xd7a718, utime: 0xc42001fed8) = -1 ETIMEDOUT Connection timed out
    2029.136 (4999.990 ms) docker-contain/2912 futex(uaddr: 0xc420027510) = 0
    2029.166 (4999.912 ms) docker-contain/2895 futex(uaddr: 0xd7acf8, utime: 0x7fcc5761adb8) = 0
    2029.156 (4999.940 ms) docker-contain/2898 futex(uaddr: 0xc420058110) = 0
    6207.427 (2999.572 ms) virt-manager/3384 futex(uaddr: 0x7fb928001f80, op: WAIT_BITSET|PRIV|CLKRT, val3: MATCH_ANY) = 0
    ^C#

### system wide stracing

- Uses tracepoint filter to exclude itself
- --filter-pids
- To avoid feedback loops
- Difficult in X session
- Combine --filter-pids + -e \!syscalls
- ssh + perf trace

### user stracing

- Enumerates threads owned by user
- Test: ping + named

    # trace --summary -u named -e *msg,futex sleep 2
    Summary of events:

    named (26671), 8 events, 9.5%
     syscall         calls  total    min     avg     max    stddev
                            (msec) (msec)  (msec)  (msec)      (%)
     --------------- ----- ------- ------ ------- -------   ------
     futex               4   0.551  0.000   0.138   0.537   96.59%
    named (26672), 10 events, 11.9%
     sendmsg              1   0.083  0.083   0.083   0.083   0.00%
     recvmsg              2   0.063  0.020   0.032   0.043  37.51%
     futex                2   0.004  0.000   0.002   0.004 100.00%
    named (26673), 22 events, 26.2%
     futex                4 821.565  0.000 205.391 821.555 100.00%
     sendmsg              2   0.113  0.043   0.056   0.070  24.05%
     recvmsg              5   0.053  0.006   0.011   0.017  21.22%
    named (26674), 18 events, 21.4%
     futex                7 821.973  0.000 117.425 821.588  99.95%
     recvmsg              2   0.013  0.006   0.007   0.007  11.32%
    named (26676), 26 events, 31.0%
     futex               13   0.287  0.005   0.022   0.064  22.43%
    #

pid, no children

    # trace -p 3384 --no-inherit -e futex --duration 1 --max-stack 8
    2.538 (3001.384 ms) virt-manager/3384 futex(uaddr: 0x7fb928005ee0, op: WAIT_BITSET|PRIV|CLKRT, val3: MATCH_ANY) = 0
    	      do_futex_wait.constprop.1 (/usr/lib64/libpthread-2.25.so)
    	      __new_sem_wait_slow.constprop.0 (/usr/lib64/libpthread-2.25.so)
    	      PyThread_acquire_lock (/usr/lib64/libpython2.7.so.1.0)
    	      [0xffff8046a2c02fd1] (/usr/lib64/libpython2.7.so.1.0)
    	      PyEval_EvalFrameEx (/usr/lib64/libpython2.7.so.1.0)
    	      PyEval_EvalCodeEx (/usr/lib64/libpython2.7.so.1.0)
    	      PyEval_EvalFrameEx (/usr/lib64/libpython2.7.so.1.0)
    	      PyEval_EvalCodeEx (/usr/lib64/libpython2.7.so.1.0)
    ^C[root@jouet ~]#

Perf recording

- Ring buffer
- No context switch
- Asyncrhonous
- May lose records
- But will state that

### strace overhead: baseline

    # dd if=/dev/zero of=/dev/null bs=1 count=500k
    512000+0 records in
    512000+0 records out
    512000 bytes (512 kB, 500 KiB) copied, 0.303143 s, 1.7 MB/s
    #

### strace overhead

    # strace -eaccept dd if=/dev/zero of=/dev/null bs=1 count=500k
    512000+0 records in
    512000+0 records out
    512000 bytes (512 kB, 500 KiB) copied, 12.2114 s, 41.9 kB/s
    +++ exited with 0 +++
    #

### strace

- 40x times slower
- In 2015 it was 173x slower
- Worst case, dd emits syscalls as fast as it can
- Brendan Gregg's article mentions 442x slow down, same example (2014)
- ptrace pauses the application twice
- syscall enter and exit
- www.brendangregg.com/blog/2014-05-11/strace-wow-much-syscall.html

### perf trace overhead

    # perf trace -e accept dd if=/dev/zero of=/dev/null bs=1 count=500k
    512000+0 records in
    512000+0 records out
    512000 bytes (512 kB, 500 KiB) copied, 0.412906 s, 1.2 MB/s
    #

### perf trace

- 1.36 times slower
- Again worst case, dd emits syscalls as fast as it can
- No workload stop at syscall enter/exit
- Collects info at syscall enter and exit
- Further optimizations possible
- Currently uses raw_syscalls:sys_{enter,exit} tracepoints
- But in this example could have used just syscalls:sys_{enter,exit}_accept

Perf metadata records

- In the ring buffer
- Together with PERF_RECORD_SAMPLE
- PERF_RECORD_COMM
- PERF_RECORD_MMAP
- PERF_RECORD_FORK
- PERF_RECORD_EXIT
- PERF_RECORD_LOST
- PERF_RECORD_CONTEXT_SWITCH
- Others

Simple beautifiers

- Associated from field types and names
- pid_t shows COMM
- fd shows file name

### syscall tracepoints

Field types

    # cd /sys/kernel/debug/tracing/events
    # cat syscalls/sys_enter_kill/format
    name: sys_enter_kill
    ID: 161
    format:
    	field:pid_t pid;  offset:16;  size:8;  signed:0;
    	field:int   sig;  offset:24;  size:8;  signed:0;
    #

syscalls operating on pids

    # cd /sys/kernel/debug/tracing/events/syscalls/
    # grep pid_t sys_enter_*/format | head -5
    sys_enter_getpgid/format:  field:pid_t pid;  offset:16;	size:8;
    sys_enter_getsid/format:   field:pid_t pid;  offset:16;	size:8;
    sys_enter_kcmp/format:     field:pid_t pid1; offset:16;	size:8;
    sys_enter_kcmp/format:     field:pid_t pid2; offset:24;	size:8;
    sys_enter_kill/format:     field:pid_t pid;  offset:16;	size:8;
    #

Augment what is provided by the tracepoints

    # trace -a -e wait4,kill,prlimit64,kcmp sleep 30
    1951.840 (3.789 ms) dhclient/17755 wait4(upid: -1, stat_addr: 0x7ffc2da5631c) ...
    1955.629 (0.004 ms) nm-dhcp-helper/23015 prlimit64(resource: STACK, old_rlim: 0x7ffff632cc20) = 0
    1951.840 (7.986 ms) dhclient/17755  ... [continued]: wait4()) = 23015 (nm-dhcp-helper)
    1965.011 (0.002 ms) (spatcher)/23020 prlimit64(resource: NOFILE, new_rlim: 0x55e291bf6fd0) = 0
    1965.471 (0.003 ms) systemd/1 kcmp(pid1: 1 (systemd), pid2: 1 (systemd),
          			           idx1: 253<socket:[7330361]>; idx2: 254<socket:[7663370]> = 1
    1965.476 (0.002 ms) systemd/1 kcmp(pid1: 1 (systemd), pid2: 1 (systemd),
          			           idx1: 252<socket:[7330360]> idx2: 254<socket:[7663370]> = 1
    1974.334 (0.004 ms) nm-dispatcher/23020 prlimit64(resource: STACK, old_rlim: 0x7ffc2c307cc0) = 0
    1992.604 (0.021 ms) nm-dispatcher/23020 wait4(upid: 23023 (nm-dispatcher),
    					      stat_addr: 0x55cdc5602544, options: NOHANG) = 0
    1997.427 (0.004 ms) 00-netreport/23023 prlimit64(resource: NPROC, old_rlim: 0x7ffc752a1010) = 0

kernel source tree

- Do not use headers directly
- Keep a copy
- Build time check of UAPI changes: check_headers.sh
- Faster support for new ABI

kernel source tree

- Automatic creation of simple beautifiers
- Use to automatically create string tables
- For beautifying args
- Allow building the tools on older distros
- Where recent defines/structs/etc are not present

Automatic creation of string tables

- grep + sed on headers
- E.g.: tools/include/uapi/linux/prctl.h
- tools/perf/trace/beauty/prctl_option.sh

Automatic creation of string tables

    # head /tmp/build/perf/trace/beauty/generated/prctl_option_array.c
    static const char *prctl_options[] = {
    	[1] = "SET_PDEATHSIG",
    	[2] = "GET_PDEATHSIG",
    	[3] = "GET_DUMPABLE",
    	[4] = "SET_DUMPABLE",
    	[5] = "GET_UNALIGN",
    	[6] = "SET_UNALIGN",
    	[7] = "GET_KEEPCAPS",
    	[8] = "SET_KEEPCAPS",
    	[9] = "GET_FPEMU",
    #

Automatic creation of string tables

    # trace -e prctl
    27097.185 (0.007 ms) SSL Cert #196/23393 prctl(option: SET_NAME, arg2: 0x7efce67eb868) = 0
    29741.170 (0.009 ms) StreamTrans #1/23394 prctl(option: SET_NAME, arg2: 0x7f46d51fff08) = 0
    30086.642 (0.014 ms) IndexedDB #18/23395 prctl(option: SET_NAME, arg2: 0x7efce7747908) = 0
    30151.534 (0.009 ms) IndexedDB #19/23396 prctl(option: SET_NAME, arg2: 0x7efce7d2c8e8) = 0
    44595.727 (0.010 ms) systemd-udevd/23400 prctl(option: SET_PDEATHSIG, arg2: 15) = 0

#### Use same libraries, coding style

- rbtree, refcount_t, atomic_t, list.h, etc
- Facilitate hacking on tools/ by kernel folks
- Write kernel facility...
- ... Show how it is used in tools/
- Not just perf, objtool, etc

Running 'perf trace' as non-root

    $ trace usleep 1
    Error: No permission to read events/raw_syscalls/sys_(enter|exit)
    Hint:  Try 'sudo mount -o remount,mode=755 /sys/kernel/tracing'
    $

Running 'perf trace' as non-root: 2

    $ sudo mount -o remount,mode=755 /sys/kernel/tracing
    $ trace usleep 1
    Error: Permission denied.
    Hint:  Check /proc/sys/kernel/perf_event_paranoid setting.
    Hint:  For your workloads it needs to be <= 1
    Hint:  For system wide tracing it needs to be set to -1.
    Hint:  Try: 'sudo sh -c "echo -1 > /proc/sys/kernel/perf_event_paranoid"'
    Hint:  The current value is 2.

Running 'perf trace' as non-root: 3

    $ sudo sh -c "echo -1 > /proc/sys/kernel/perf_event_paranoid"
    $ trace usleep 1
    ...
    0.357 (0.001ms) usleep/18517 brk() = 0x55e44d210000
    0.373 (0.058ms) usleep/18517 nanosleep(rqtp: 0x7ffca6c566c0) = 0
    ...
    $

Specifying syscalls

    $ trace -e nanosleep sleep 1
       0.000 (1000.195ms) sleep/22896 nanosleep(rqtp: 0x7ffd03270f10) = 0
    $

With backtraces!

    $ trace -e nanosleep --call-graph dwarf sleep 1
    0.000 (1000.143ms) sleep/22906 nanosleep(rqtp: 0x7ffe91fed9c0) = 0
    				 __nanosleep_nocancel (/usr/lib64/libc-2.25.so)
    				 rpl_nanosleep (/usr/bin/sleep)
    				 xnanosleep (/usr/bin/sleep)
    				 main (/usr/bin/sleep)
    				 __libc_start_main (/usr/lib64/libc-2.25.so)
    				 _start (/usr/bin/sleep)
    $

## callchains

- fp: cheap but not always available
- dwarf: expensive, but works
- dwarf: Collects user stack + registers, per sample
- To reduce the cost: use just in some events
- Reduce the stack sampled

Reducing stack sampled: drastically

    $ trace -e nanosleep --call-graph dwarf,128 sleep 1
    0.000 (1000.135ms) sleep/23073 nanosleep(rqtp: 0x7ffc90169e70) = 0
    				 __nanosleep_nocancel (/usr/lib64/libc-2.25.so)
    				 rpl_nanosleep (/usr/bin/sleep)
    				 xnanosleep (/usr/bin/sleep)
    				 [0] ([unknown])
    $

Reducing stack sampled: 2

    $ trace -e nanosleep --call-graph dwarf,256 sleep 1
    0.000 (1000.192ms) sleep/23133 nanosleep(rqtp: 0x7fff7fb7e9e0) = 0
    				 __nanosleep_nocancel (/usr/lib64/libc-2.25.so)
    				 rpl_nanosleep (/usr/bin/sleep)
    				 xnanosleep (/usr/bin/sleep)
    				 main (/usr/bin/sleep)
    				 __libc_start_main (/usr/lib64/libc-2.25.so)
    				 [0] ([unknown])
    $

Reducing stack sampled: rigthsized

    $ trace -e nanosleep --call-graph dwarf,512 sleep 1
    0.000 (1000.125ms) sleep/23146 nanosleep(rqtp: 0x7ffd896eea50) = 0
               			__nanosleep_nocancel (/usr/lib64/libc-2.25.so)
    				rpl_nanosleep (/usr/bin/sleep)
           				xnanosleep (/usr/bin/sleep)
    				main (/usr/bin/sleep)
    				__libc_start_main (/usr/lib64/libc-2.25.so)
    				_start (/usr/bin/sleep)
    $

Measuring DWARF callgraphs cost

    $ perf record -a --call dwarf sleep 5s
    [ perf record: Woken up 30 times to write data ]
    [ perf record: Captured and wrote 11.043 MB perf.data (1955 samples) ]
    $ perf evlist -v
    cycles:ppp: sample_freq: 4000,
    sample_type: IP|TID|TIME|ADDR|CALLCHAIN|CPU|PERIOD|REGS_USER|STACK_USER|DATA_SRC,
    mmap: 1, comm: 1, task: 1, precise_ip: 3, exclude_guest: 1,
    exclude_callchain_user: 1, comm_exec: 1, sample_regs_user: 0xff0fff,
    sample_stack_user: 8192
    $

Measuring DWARF callgraphs cost

    $ perf record -a --call dwarf,128 sleep 5s
    [ perf record: Woken up 1 times to write data ]
    [ perf record: Captured and wrote 4.033 MB perf.data (1821 samples) ]
    $ perf evlist -v
    cycles:ppp: ..., sample_stack_user: 128
    $

using max-stack

- Use max-stack to reduce sample size and postprocessing cost
- attr.sample_max_stack tells kernel entries to sample
- Ask for callgraphs for just some of the events
- And mix syscalls with other events, say tracepoints
- Use wildcards to type less

    $ trace -e *sleep -e sched:*wakeup,sched:*switch/max-stack=8/ sleep 1
       1.195 (0.017ms) sleep/23575 nanosleep(rqtp: 0x7ffcf19a17d0) ...
       1.211 (       ) sched:sched_switch:sleep:23575 [120] S ==> swapper/2:0 [120])
                              __schedule ([kernel])
                              __schedule ([kernel])
                              schedule ([kernel])
                              do_nanosleep ([kernel])
                              hrtimer_nanosleep ([kernel])
                              sys_nanosleep ([kernel])
                              do_syscall_64 ([kernel])
                              return_from_SYSCALL_64 ([kernel])
    1001.369 (       ) d_wakeup:sleep:23575 [120] success=1 CPU:002)
       1.195 (1000.226ms) sleep/23575  ... [continued]: nanosleep()) = 0
    $

Features present in various tools

- We saw callchains in 'perf trace'
- It is also present in other tools
- As lots of other concepts, reused

syscall args: pointers

    # trace -e open touch /tmp/bla
    0.000 (0.020ms) touch open(filename: 0x8992e37, flags: CLOEXEC) = 3
    0.051 (0.012ms) touch open(filename: 0x8b96640, flags: CLOEXEC) = 3
    0.440 (0.018ms) touch open(filename: 0x873cc70, flags: CLOEXEC) = 3
    0.532 (0.311ms) touch open(filename: 0x66a9340,
                                flags: CREAT|NOCTTY|NONBLOCK|WRONLY,
                                mode: IRUGO|IWUGO) = 3
    #

Copying pointer contents

- Use 'perf probe'
- Where it is copied from/to userspace
- Fragile, these places change overtime
- Later will use eBPF for that

Copying that data

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

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

      perf record -e probe:vfs_getname -aR sleep 1

    #

Tracing syscalls + probe

    # trace --no-syscalls -e syscalls:sys_enter_open*,probe:vfs_getname touch /etc/passwd
    0.000 probe:vfs_getname:(ffffffff812799e3) pathname="/etc/ld.so.preload")
    0.010 syscalls:sys_enter_openat:dfd: 0xffffffffffffff9c, filename: 0x7f19fa31a726, flags: 0x80000, mode: 0x0)
    0.013 probe:vfs_getname:(ffffffff812799e3) pathname="/etc/ld.so.cache")
    0.032 syscalls:sys_enter_openat:dfd: 0xffffffffffffff9c, filename: 0x7f19fa522ce0, flags: 0x80000, mode: 0x0)
    0.034 probe:vfs_getname:(ffffffff812799e3) pathname="/lib64/libc.so.6")
    0.258 syscalls:sys_enter_open:filename: 0x7f19fa0c44d0, flags: 0x80000, mode: 0x0)
    0.261 probe:vfs_getname:(ffffffff812799e3) pathname="/usr/lib/locale/locale-archive")
    0.304 syscalls:sys_enter_openat:dfd: 0xffffffffffffff9c, filename: 0x7ffe33a81379, flags: 0x941, mode: 0x1b6)
    0.306 probe:vfs_getname:(ffffffff812799e3) pathname="/etc/passwd")
    #

Use probe:vfs_getname when available

    # trace --no-inherit -e open* touch /etc/passwd
    0.054 (0.036 ms) openat(dfd: CWD, filename: /etc/ld.so.cache, flags: CLOEXEC) = 3
    0.159 (0.051 ms) openat(dfd: CWD, filename: /lib64/libc.so.6, flags: CLOEXEC) = 3
    1.188 (0.050 ms) open(filename: /usr/lib/locale/locale-archive, flags: CLOEXEC) = 3
    1.390 (0.036 ms) openat(dfd: CWD, filename: /etc/passwd,
    			flags: CREAT|NOCTTY|NONBLOCK|WRONLY, mode: IRUGO|IWUGO) = 3
    #

eBPF

- clang + llvm
- sys_ebpf()
- Attach to kprobes, uprobes, tracepoints
- Work as filters
- Should be used for filtering by syscall args
- Also to copy pointer payloads for beautification

eBPF Integration

    # cat filter.c

    #include <uapi/linux/bpf.h>
    #define SEC(NAME) __attribute__((section(NAME), used))

    SEC("func=hrtimer_nanosleep rqtp->tv_nsec")
    int func(void *ctx, int err, long nsec)
    {
    	return nsec > 1000;
    }
    char _license[] SEC("license") = "GPL";
    int _version SEC("version") = LINUX_VERSION_CODE;

1000ns

    # trace -e *sleep,filter.c  usleep 1
    0.000 (0.096ms) usleep/7978 nanosleep(rqtp: 0x7fff3ac3cb00) = 0
    #

2000ns

    # trace -e nanosleep,filter.c  usleep 2
    0.000 (0.012ms) usleep/7564 nanosleep(rqtp: 0x7ffec11bbd20) ...
    0.012 (       ) perf_bpf_probe:func:(ffffffff9f10cb30) tv_nsec=2000)
    0.000 (0.071ms) usleep/7564  ... [continued]: nanosleep()) = 0
    #

With a backtrace

    # trace -e nanosleep,filter.c/max-stack=5/ usleep 1001
    0.000 (0.018ms) usleep/963 nanosleep(rqtp: 0x7ffdc6421410) ...
    0.018 (       ) perf_bpf_probe:func:(ffffffff9f10cb30) tv_nsec=1001000)
                          hrtimer_nanosleep ([kernel])
                          SyS_nanosleep ([kernel])
                          do_syscall_64 ([kernel])
                          return_from_SYSCALL_64 ([kernel])
                          __GI_nanosleep (/usr/lib64/libc-2.25.so)
    0.000 (1.095ms) usleep/963  ... [continued]: nanosleep()) = 0
    [root@jouet bpf]#

eBPF

- Can attach to tracepoints
- And copy pointer contents
- To perf ring buffer
- For beautification

### Hooking into a tracepoint

    # cat sys_enter_openat.c

    #include "bpf.h"
    SEC("syscalls:sys_enter_openat")
    int func(void *ctx)
    {
        char filename[256];
        char *filename_ptr = *((char **)(ctx + 24));
        int len = bpf_probe_read_str(filename, sizeof(filename), filename_ptr);
        if (len > 0 && len < 256) {
           perf_event_output(ctx, &__bpf_stdout__, BPF_F_CURRENT_CPU,
                             &filename, len & (256 - 1));
        }
        return 0;
    }

    #

- Offsets from tracefs
- No need for DWARF
- Not hardcoded in 'perf trace'

    /*
     * /sys/kernel/debug/tracing/events/syscalls/sys_enter_openat/format:
     * ...
     * field:const char * filename;	offset:24;  size:8;  signed:0;
     * ...
     * ctx + 24 selects 'filename'
     */

#### Running it

    # trace -e openat,sys_enter_openat.c touch /tmp/bla
    LLVM: dumping sys_enter_openat.o
    0.000 (         ): __bpf_stdout__:/etc/ld.so.cache....)
    0.006 ( 0.005 ms): touch/17545 openat(dfd: CWD, filename: 0x6887726, flags: CLOEXEC) = 3
    0.024 (         ): __bpf_stdout__:/lib64/libc.so.6....)
    0.026 ( 0.005 ms): touch/17545 openat(dfd: CWD, filename: 0x6a8fce0, flags: CLOEXEC) = 3
    0.282 (         ): __bpf_stdout__:/tmp/bla....)
    0.283 ( 0.005 ms): touch/17545 openat(dfd: CWD, filename: 0x7cd0413c,
    				      flags: CREAT|NOCTTY|NONBLOCK|WRONLY,
    				      mode: IRUGO|IWUGO) = 3

#### Running it + vfs_getname

    # trace -e openat,sys_enter_openat.c touch /tmp/bla
    0.098 (         ): __bpf_stdout__:/etc/ld.so.cache....)
    0.108 ( 0.033 ms): touch/24825 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: CLOEXEC) = 3
    0.217 (         ): __bpf_stdout__:/lib64/libc.so.6....)
    0.222 ( 0.035 ms): touch/24825 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: CLOEXEC) = 3
    1.403 (         ): __bpf_stdout__:/tmp/bla....)
    1.411 ( 0.038 ms): touch/24825 openat(dfd: CWD, filename: /tmp/bla,
    				      flags: CREAT|NOCTTY|NONBLOCK|WRONLY, mode: IRUGO|IWUGO) = 3
    #

#### Compile errors:

    # trace -e sys_enter_open.c
    sys_enter_open.c:14:20: error: expected ';' at end of declaration
            char *filename_ptr *((char **)(ctx + 16));
                              ^
                              ;
    1 error generated.
    ERROR:	unable to compile sys_enter_open.c
    Hint:	Check error message shown above.
    Hint:	You can also pre-compile it into .o using:
         		clang -target bpf -O2 -c sys_enter_open.c
         	with proper -I and -D options.
    event syntax error: 'sys_enter_open.c'
                         \___ Failed to load sys_enter_open.c from source:
    			  Error when compiling BPF scriptlet

    (add -v to see detail)
    #

#### Pre-compiled eBPF programs

    # file sys_enter_openat.o
    sys_enter_openat.o: ELF 64-bit LSB relocatable, eBPF, version 1 (SYSV), not stripped
    #
    # trace -e openat,sys_enter_openat.o touch /tmp/bla
    0.098 (         ): __bpf_stdout__:/etc/ld.so.cache....)
    0.108 ( 0.033 ms): touch/24825 openat(dfd: CWD, filename: /etc/ld.so.cache, flags: CLOEXEC) = 3
    0.217 (         ): __bpf_stdout__:/lib64/libc.so.6....)
    0.222 ( 0.035 ms): touch/24825 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: CLOEXEC) = 3
    1.403 (         ): __bpf_stdout__:/tmp/bla....)
    1.411 ( 0.038 ms): touch/24825 openat(dfd: CWD, filename: /tmp/bla,
    				      flags: CREAT|NOCTTY|NONBLOCK|WRONLY, mode: IRUGO|IWUGO) = 3
    #

#### Next steps

- Auto generate eBPF for pointer collection
- Restricted C or directly in eBPF ASM
- Refactor vfs_getname in 'perf trace' to use it
- Auto generate struct beautifiers
- From DWARF
- Extending pahole

    $ pahole -C pevent_function_handler ~/bin/perf struct pevent_function_handler {
    	struct pevent_function_handler * next;   /*  0  8 */
    	enum pevent_func_arg_type  ret_type;     /*  8  4 */

    	/* XXX 4 bytes hole, try to pack */

    	char *                     name;         /* 16  8 */
    	pevent_func_handler        func;         /* 24  8 */
    	struct pevent_func_params * params;      /* 32  8 */
    	int                        nr_args;      /* 40  4 */

    	/* size: 48, cachelines: 1, members: 6 */
    	/* sum members: 40, holes: 1, sum holes: 4 */
    	/* padding: 4 */
    	/* last cacheline: 48 bytes */
    };

# THE END

- Documentation/networking/filter.txt
- Documentation/bpf/bpf_design_QA.txt
- vger.kernel.org/~acme/perf/devconf.cz.2018
- perf.wiki.kernel.org
- linux-perf-users@vger.kernel.org
- Arnaldo Carvalho de Melo <acme@redhat.com>