perf BPF annotation output validation

tldr; more to the end there are some annotation for all sorts of cache level misses trying to validate the 'perf annotation' output for disassembled BPF programs.

[root@quaco ~]# uname -a
Linux quaco 5.1.0-rc5+ #4 SMP Wed Apr 17 19:33:00 -03 2019 x86_64 x86_64 x86_64 GNU/Linux

Running perf trace with:

[root@quaco ~]# cat ~/.perfconfig
[llvm]
dump-obj = true
clang-opt = -g
[trace]
add_events = /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.c #add_events = /wb/augmented_raw_syscalls.o
show_zeros = yes
show_duration = no
no_inherit = yes
show_timestamp = no
show_arg_names = no
args_alignment = 40
show_prefix = yes

[annotate]

hide_src_code = false
[root@quaco ~]#

clang/llvm 9:

[root@quaco perf]# eu-readelf -winfo /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o | grep compile_unit
[ b] compile_unit abbrev: 1
[root@quaco perf]# eu-readelf -winfo /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o | grep compile_unit -B1 -A10
Version: 4, Abbreviation section offset: 0, Address size: 8, Offset size: 4

[     b]  compile_unit         abbrev: 1
          producer             (strp) "clang version 9.0.0 (https://urldefense.proofpoint.com/v2/url?u=https-3A__git.llvm.org_git_clang.git_&d=DwIDaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=dR8692q0_uaizy0jkrBJQM5k2hfm4CiFxYT8KaysFrg&m=8ymLhVNE6vfRn0KCyz7xlPkm7i1H4ttMrMYmeHEP1Cg&s=3_k_sPaZo7mwxQMoYhgd4hBUmCoS3TboKrw15yws6mA&e= 7906282d3afec5dfdc2b27943fd6c0309086c507) (https://urldefense.proofpoint.com/v2/url?u=https-3A__git.llvm.org_git_llvm.git_&d=DwIDaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=dR8692q0_uaizy0jkrBJQM5k2hfm4CiFxYT8KaysFrg&m=8ymLhVNE6vfRn0KCyz7xlPkm7i1H4ttMrMYmeHEP1Cg&s=jutQ4xaAa5FePXthz5gHAgdx6kVlrPI64pnpqWWt59Q&e= a1b5de1ff8ae8bc79dc8e86e1f82565229bd0500)"
          language             (data2) C99 (12)
          name                 (strp) "/home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.c"
          stmt_list            (sec_offset) 0
          comp_dir             (strp) "/root"
          low_pc               (addr) raw_syscalls:sys_enter+000000000000000000 <sys_enter>
          ranges               (sec_offset) range list [     0]
[    2a]    variable             abbrev: 2
            name                 (strp) "__augmented_syscalls__"
            type                 (ref4) [    3f]

[root@quaco perf]#

I then leave this running doing system wide syscall tracing using that augmented_raw_syscalls.c eBPF program hooked into the syscall enter and exit tracepoints, so that I have something to profile and further test the BPF support in perf top/annotate/report (slides for LSFMM anyone? :-)) then I get:

# perf trace -a sleep 100h

<SNIP>
tmux: server/11597 ioctl(8</dev/ptmx>, TIOCLINUX, 0x7ffe1b49abf8) = 0
tmux: server/11597 readv(8, 0x7ffe1b49ac00, 1) = 101
tmux: server/11597 ioctl(8</dev/ptmx>, TIOCSPGRP, 0x7ffe1b49a9f4) = 0
tmux: server/11597 openat(AT_FDCWD, "/proc/30339/cmdline", O_RDONLY) = 5
tmux: server/11597 fstat(5, 0x7ffe1b49a8e0) = 0
tmux: server/11597 read(5, 0x5571aaeb2c10, 1024) = 10
tmux: server/11597 close(5) = 0
gnome-shell/19195 ... [continued]: ioctl()) = 0
tmux: server/11597 poll(0x5571aad38e50, 6, 11997) ...
gnome-shell/19195 ioctl(11</dev/dri/card0>, DRM_MODE_RMFB, 0x7ffc2129c25c) = 0
gnome-shell/19195 recvmsg(39<socket:[18671390]>, 0x7ffc2129c440, NONE) = -1 EAGAIN (Resource temporarily unavailable) <SNIP>

With that running, I do:

[root@quaco perf]# perf record -a sleep 2s
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.647 MB perf.data (3698 samples) ] [root@quaco perf]#

I.e. collect 2 seconds worth of CPU cycles samples, system wide.

[root@quaco perf]# perf record -a sleep 2s
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 2.328 MB perf.data (17764 samples) ] [root@quaco perf]# perf report --header-only perf.data | grep -i b[pt]f

# event : name = cycles, , id = { 266608, 266609, 266610, 266611, 266612, 266613, 266614, 266615 }, size = 112, { sample_period, sample_freq } = 4000, sample_type = IP|TID|TIME|CPU|PERIOD, read_format = ID, disabled = 1, inherit = 1, mmap = 1, comm = 1, freq = 1, task = 1, precise_ip = 3, sample_id_all = 1, exclude_guest = 1, mmap2 = 1, comm_exec = 1, ksymbol = 1, bpf_event = 1
# bpf_prog_info 13: bpf_prog_7be49e3934a125ba addr 0xffffffffc0437f01 size 229
# bpf_prog_info 14: bpf_prog_2a142ef67aaad174 addr 0xffffffffc04393cd size 229
# bpf_prog_info 17: bpf_prog_7be49e3934a125ba addr 0xffffffffc052ca3c size 229
# bpf_prog_info 18: bpf_prog_2a142ef67aaad174 addr 0xffffffffc0531218 size 229
# bpf_prog_info 21: bpf_prog_7be49e3934a125ba addr 0xffffffffc0cb8010 size 229
# bpf_prog_info 22: bpf_prog_2a142ef67aaad174 addr 0xffffffffc0cba8be size 229
# bpf_prog_info 65: bpf_prog_7be49e3934a125ba addr 0xffffffffc03f6bc2 size 229
# bpf_prog_info 66: bpf_prog_2a142ef67aaad174 addr 0xffffffffc03f87f6 size 229
# bpf_prog_info 125: bpf_prog_819967866022f1e1_sys_enter addr 0xffffffffc0c6e5a1 size 381
# bpf_prog_info 126: bpf_prog_c1bd85c092d6e4aa_sys_exit addr 0xffffffffc0c953a8 size 191
[root@quaco perf]# 

So everything seems in order, but then:

[root@quaco perf]# perf report | grep bpf_prog

    0.14%  perf             bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.08%  gnome-terminal-  bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.06%  perf             bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.04%  gnome-terminal-  bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.01%  alsa-sink-ALC25  bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.01%  Web Content      bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.01%  lvmetad          bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.00%  alsa-sink-ALC25  bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.00%  sssd_kcm         bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.00%  gnome-shell      bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.00%  firefox          bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.00%  weechat          bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.00%  WebExtensions    bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.00%  Timer            bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.00%  Web Content      bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter

[root@quaco perf]#

Ok, lets check that bpf_prog_819967866022f1e1_sys_enter symbol, 38% of the samples at just at that %rbp, more in a previous run...

[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 25 of event 'cycles', 4000 Hz, Event count (approx.): 7248318, [percent: local period] bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
38.00 push %rbp

 2.72         mov    %rsp,%rbp
              sub    $0x170,%rsp
13.19         sub    $0x28,%rbp
 3.30         mov    %rbx,0x0(%rbp)
20.33         mov    %r13,0x8(%rbp)
              mov    %r14,0x10(%rbp)
              mov    %r15,0x18(%rbp)
              xor    %eax,%eax
              mov    %rax,0x20(%rbp)
              mov    %rdi,%rbx
13.34       → callq  *ffffffffd359487f
              mov    %eax,-0x148(%rbp)

So I ended up trying with a event group to check what could be that:

[root@quaco perf]# perf record -a -e '{cycles,instructions,cache-misses}' sleep 2s
[ perf record: Woken up 18 times to write data ]
[ perf record: Captured and wrote 6.619 MB perf.data (91964 samples) ]
[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 314 of events 'anon group { cycles, instructions, cache-misses }', 4000 Hz, Event count (approx.): 118106063, [percent: local period] bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
20.88 24.58 49.11 push %rbp

47.37  31.62  26.71         mov    %rsp,%rbp
 1.16   0.00   0.00         sub    $0x170,%rsp
                            sub    $0x28,%rbp
 0.58   2.48   0.00         mov    %rbx,0x0(%rbp)
 7.10   5.92   0.00         mov    %r13,0x8(%rbp)
 0.51   0.96   7.96         mov    %r14,0x10(%rbp)
 0.00   1.10   0.00         mov    %r15,0x18(%rbp)
 0.58   0.00   0.00         xor    %eax,%eax
                            mov    %rax,0x20(%rbp)
 2.39   0.85   0.00         mov    %rdi,%rbx
 0.58   1.96   0.00       → callq  *ffffffffd359487f
                            mov    %eax,-0x148(%rbp)
 2.88   0.89   3.50         mov    %rbp,%rsi
                            add    $0xfffffffffffffeb8,%rsi

So seems ok? I.e. that big cost at right the start of the BPF program is just cache pressure, probably, right?

[root@quaco perf]# perf record -a -e '{L1-icache-load-misses,L1-dcache-load-misses}' sleep 2s
[ perf record: Woken up 14 times to write data ]
[ perf record: Captured and wrote 5.557 MB perf.data (72026 samples) ]
[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 376 of events 'anon group { L1-icache-load-misses, L1-dcache-load-misses }', 4000 Hz, Event count (approx.): 3715276, [percent: local p> bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
1.54 63.01 push %rbp

53.09  28.13         mov    %rsp,%rbp      
 0.58   0.00         sub    $0x170,%rsp    
 0.00   0.55         sub    $0x28,%rbp     
 6.96   0.00         mov    %rbx,0x0(%rbp) 
10.25   0.00         mov    %r13,0x8(%rbp) 
 0.73   0.00         mov    %r14,0x10(%rbp)
 3.04   0.00         mov    %r15,0x18(%rbp)

Looks like. furthermore:

[root@quaco perf]# perf record -a -e '{L1-icache-load-misses,L1-dcache-load-misses,dTLB-load-misses,iTLB-load-misses}' sleep 2s [ perf record: Woken up 21 times to write data ]
[ perf record: Captured and wrote 7.708 MB perf.data (112323 samples) ]
[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 391 of events 'anon group { L1-icache-load-misses, L1-dcache-load-misses, dTLB-load-misses, iTLB-load-misses }', 4000 Hz, Event count (> bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
1.98 64.42 100.00 13.66 push %rbp

50.79  23.91   0.00  82.23         mov    %rsp,%rbp
                                   sub    $0x170,%rsp
 0.24   0.00   0.00   0.00         sub    $0x28,%rbp
 7.73   0.00   0.00   0.00         mov    %rbx,0x0(%rbp)
11.13   0.44   0.00   0.00         mov    %r13,0x8(%rbp)
                                   mov    %r14,0x10(%rbp)
 1.64   0.46   0.00   0.00         mov    %r15,0x18(%rbp)

Do these numbers look sane to you guys?

Song, I also noticed that source code is not being intermixed for the --stdio annotation, while it works, to some degree, for '--tui', i.e. when you do 'perf top', press '/bpf' to show just symbols with that substring and then press enter or 'A' to annotate, we can see the original C source code for the BPF program, but it is mangling the screen sometimes, I need to try and fix, please take a look if you have the time.

Also things like the callq targets need some work to tell what function is that, which as I said isn't appearing on the --stdio2 output, but appears on the --tui, i.e. we need to resolve that symbol to check how to map back to a BPF helper or any othe callq target.

Also, what about those 'je 0', i.e. the target is being misinterpreted or is this some BPF construct I should've know about? :)

2.68 0.00 0.00 0.00 mov %rdi,%rbx
→ callq *ffffffffd359487f
mov %eax,-0x148(%rbp)
9.61 0.00 0.00 0.00 mov %rbp,%rsi

                                   add    $0xfffffffffffffeb8,%rsi     
                                   movabs $0xffff9d556c776c00,%rdi

                                 → callq  *ffffffffd3595b2f            
                                   cmp    $0x0,%rax                    
                                 → je     0                            
 0.00   1.25   0.00   0.00         add    $0x38,%rax                   
 0.80   0.21   0.00   0.00         xor    %r13d,%r13d                  
                                   cmp    $0x0,%rax                    

→ jne 0
mov %rbp,%rdi
add $0xfffffffffffffeb8,%rdi

- Arnaldo

Quoted 56 lines · Arnaldo Carvalho de Melo

tldr; more to the end there are some annotation for all sorts of cache level misses trying to validate the 'perf annotation' output for disassembled BPF programs.

[root@quaco ~]# uname -a
Linux quaco 5.1.0-rc5+ #4 SMP Wed Apr 17 19:33:00 -03 2019 x86_64 x86_64 x86_64 GNU/Linux

Running perf trace with:

[root@quaco ~]# cat ~/.perfconfig
[llvm]
dump-obj = true
clang-opt = -g
[trace]
add_events = /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.c #add_events = /wb/augmented_raw_syscalls.o
show_zeros = yes
show_duration = no
no_inherit = yes
show_timestamp = no
show_arg_names = no
args_alignment = 40
show_prefix = yes

[annotate]

hide_src_code = false
[root@quaco ~]#

clang/llvm 9:

[root@quaco perf]# eu-readelf -winfo /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o | grep compile_unit
[ b] compile_unit abbrev: 1
[root@quaco perf]# eu-readelf -winfo /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o | grep compile_unit -B1 -A10
Version: 4, Abbreviation section offset: 0, Address size: 8, Offset size: 4

[     b]  compile_unit         abbrev: 1
          producer             (strp) "clang version 9.0.0 (https://urldefense.proofpoint.com/v2/url?u=https-3A__git.llvm.org_git_clang.git_&d=DwIDaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=dR8692q0_uaizy0jkrBJQM5k2hfm4CiFxYT8KaysFrg&m=8ymLhVNE6vfRn0KCyz7xlPkm7i1H4ttMrMYmeHEP1Cg&s=3_k_sPaZo7mwxQMoYhgd4hBUmCoS3TboKrw15yws6mA&e= 7906282d3afec5dfdc2b27943fd6c0309086c507) (https://urldefense.proofpoint.com/v2/url?u=https-3A__git.llvm.org_git_llvm.git_&d=DwIDaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=dR8692q0_uaizy0jkrBJQM5k2hfm4CiFxYT8KaysFrg&m=8ymLhVNE6vfRn0KCyz7xlPkm7i1H4ttMrMYmeHEP1Cg&s=jutQ4xaAa5FePXthz5gHAgdx6kVlrPI64pnpqWWt59Q&e= a1b5de1ff8ae8bc79dc8e86e1f82565229bd0500)"
          language             (data2) C99 (12)
          name                 (strp) "/home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.c"
          stmt_list            (sec_offset) 0
          comp_dir             (strp) "/root"
          low_pc               (addr) raw_syscalls:sys_enter+000000000000000000 <sys_enter>
          ranges               (sec_offset) range list [     0]
[    2a]    variable             abbrev: 2
            name                 (strp) "__augmented_syscalls__"
            type                 (ref4) [    3f]

[root@quaco perf]#

I then leave this running doing system wide syscall tracing using that augmented_raw_syscalls.c eBPF program hooked into the syscall enter and exit tracepoints, so that I have something to profile and further test the BPF support in perf top/annotate/report (slides for LSFMM anyone? :-)) then I get:

Quoted 1 line

# perf trace -a sleep 100h

wow, I never tried to run sleep with "100h". ;-)

Quoted 144 lines

<SNIP>
tmux: server/11597 ioctl(8</dev/ptmx>, TIOCLINUX, 0x7ffe1b49abf8) = 0
tmux: server/11597 readv(8, 0x7ffe1b49ac00, 1) = 101
tmux: server/11597 ioctl(8</dev/ptmx>, TIOCSPGRP, 0x7ffe1b49a9f4) = 0
tmux: server/11597 openat(AT_FDCWD, "/proc/30339/cmdline", O_RDONLY) = 5
tmux: server/11597 fstat(5, 0x7ffe1b49a8e0) = 0
tmux: server/11597 read(5, 0x5571aaeb2c10, 1024) = 10
tmux: server/11597 close(5) = 0
gnome-shell/19195 ... [continued]: ioctl()) = 0
tmux: server/11597 poll(0x5571aad38e50, 6, 11997) ...
gnome-shell/19195 ioctl(11</dev/dri/card0>, DRM_MODE_RMFB, 0x7ffc2129c25c) = 0
gnome-shell/19195 recvmsg(39<socket:[18671390]>, 0x7ffc2129c440, NONE) = -1 EAGAIN (Resource temporarily unavailable) <SNIP>

With that running, I do:

[root@quaco perf]# perf record -a sleep 2s
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.647 MB perf.data (3698 samples) ] [root@quaco perf]#

I.e. collect 2 seconds worth of CPU cycles samples, system wide.

[root@quaco perf]# perf record -a sleep 2s
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 2.328 MB perf.data (17764 samples) ] [root@quaco perf]# perf report --header-only perf.data | grep -i b[pt]f

# event : name = cycles, , id = { 266608, 266609, 266610, 266611, 266612, 266613, 266614, 266615 }, size = 112, { sample_period, sample_freq } = 4000, sample_type = IP|TID|TIME|CPU|PERIOD, read_format = ID, disabled = 1, inherit = 1, mmap = 1, comm = 1, freq = 1, task = 1, precise_ip = 3, sample_id_all = 1, exclude_guest = 1, mmap2 = 1, comm_exec = 1, ksymbol = 1, bpf_event = 1
# bpf_prog_info 13: bpf_prog_7be49e3934a125ba addr 0xffffffffc0437f01 size 229
# bpf_prog_info 14: bpf_prog_2a142ef67aaad174 addr 0xffffffffc04393cd size 229
# bpf_prog_info 17: bpf_prog_7be49e3934a125ba addr 0xffffffffc052ca3c size 229
# bpf_prog_info 18: bpf_prog_2a142ef67aaad174 addr 0xffffffffc0531218 size 229
# bpf_prog_info 21: bpf_prog_7be49e3934a125ba addr 0xffffffffc0cb8010 size 229
# bpf_prog_info 22: bpf_prog_2a142ef67aaad174 addr 0xffffffffc0cba8be size 229
# bpf_prog_info 65: bpf_prog_7be49e3934a125ba addr 0xffffffffc03f6bc2 size 229
# bpf_prog_info 66: bpf_prog_2a142ef67aaad174 addr 0xffffffffc03f87f6 size 229
# bpf_prog_info 125: bpf_prog_819967866022f1e1_sys_enter addr 0xffffffffc0c6e5a1 size 381
# bpf_prog_info 126: bpf_prog_c1bd85c092d6e4aa_sys_exit addr 0xffffffffc0c953a8 size 191
[root@quaco perf]# 

So everything seems in order, but then:

[root@quaco perf]# perf report | grep bpf_prog

    0.14%  perf             bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.08%  gnome-terminal-  bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.06%  perf             bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.04%  gnome-terminal-  bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.01%  alsa-sink-ALC25  bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.01%  Web Content      bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.01%  lvmetad          bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.00%  alsa-sink-ALC25  bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.00%  sssd_kcm         bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.00%  gnome-shell      bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.00%  firefox          bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.00%  weechat          bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.00%  WebExtensions    bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.00%  Timer            bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.00%  Web Content      bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter

[root@quaco perf]#

Ok, lets check that bpf_prog_819967866022f1e1_sys_enter symbol, 38% of the samples at just at that %rbp, more in a previous run...

[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 25 of event 'cycles', 4000 Hz, Event count (approx.): 7248318, [percent: local period] bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
38.00 push %rbp

 2.72         mov    %rsp,%rbp
              sub    $0x170,%rsp
13.19         sub    $0x28,%rbp
 3.30         mov    %rbx,0x0(%rbp)
20.33         mov    %r13,0x8(%rbp)
              mov    %r14,0x10(%rbp)
              mov    %r15,0x18(%rbp)
              xor    %eax,%eax
              mov    %rax,0x20(%rbp)
              mov    %rdi,%rbx
13.34       → callq  *ffffffffd359487f
              mov    %eax,-0x148(%rbp)

So I ended up trying with a event group to check what could be that:

[root@quaco perf]# perf record -a -e '{cycles,instructions,cache-misses}' sleep 2s
[ perf record: Woken up 18 times to write data ]
[ perf record: Captured and wrote 6.619 MB perf.data (91964 samples) ]
[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 314 of events 'anon group { cycles, instructions, cache-misses }', 4000 Hz, Event count (approx.): 118106063, [percent: local period] bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
20.88 24.58 49.11 push %rbp

47.37  31.62  26.71         mov    %rsp,%rbp
 1.16   0.00   0.00         sub    $0x170,%rsp
                            sub    $0x28,%rbp
 0.58   2.48   0.00         mov    %rbx,0x0(%rbp)
 7.10   5.92   0.00         mov    %r13,0x8(%rbp)
 0.51   0.96   7.96         mov    %r14,0x10(%rbp)
 0.00   1.10   0.00         mov    %r15,0x18(%rbp)
 0.58   0.00   0.00         xor    %eax,%eax
                            mov    %rax,0x20(%rbp)
 2.39   0.85   0.00         mov    %rdi,%rbx
 0.58   1.96   0.00       → callq  *ffffffffd359487f
                            mov    %eax,-0x148(%rbp)
 2.88   0.89   3.50         mov    %rbp,%rsi
                            add    $0xfffffffffffffeb8,%rsi

So seems ok? I.e. that big cost at right the start of the BPF program is just cache pressure, probably, right?

[root@quaco perf]# perf record -a -e '{L1-icache-load-misses,L1-dcache-load-misses}' sleep 2s
[ perf record: Woken up 14 times to write data ]
[ perf record: Captured and wrote 5.557 MB perf.data (72026 samples) ]
[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 376 of events 'anon group { L1-icache-load-misses, L1-dcache-load-misses }', 4000 Hz, Event count (approx.): 3715276, [percent: local p> bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
1.54 63.01 push %rbp

53.09  28.13         mov    %rsp,%rbp      
 0.58   0.00         sub    $0x170,%rsp    
 0.00   0.55         sub    $0x28,%rbp     
 6.96   0.00         mov    %rbx,0x0(%rbp) 
10.25   0.00         mov    %r13,0x8(%rbp) 
 0.73   0.00         mov    %r14,0x10(%rbp)
 3.04   0.00         mov    %r15,0x18(%rbp)

Looks like. furthermore:

[root@quaco perf]# perf record -a -e '{L1-icache-load-misses,L1-dcache-load-misses,dTLB-load-misses,iTLB-load-misses}' sleep 2s [ perf record: Woken up 21 times to write data ]
[ perf record: Captured and wrote 7.708 MB perf.data (112323 samples) ]
[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 391 of events 'anon group { L1-icache-load-misses, L1-dcache-load-misses, dTLB-load-misses, iTLB-load-misses }', 4000 Hz, Event count (> bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
1.98 64.42 100.00 13.66 push %rbp

50.79  23.91   0.00  82.23         mov    %rsp,%rbp
                                   sub    $0x170,%rsp
 0.24   0.00   0.00   0.00         sub    $0x28,%rbp
 7.73   0.00   0.00   0.00         mov    %rbx,0x0(%rbp)
11.13   0.44   0.00   0.00         mov    %r13,0x8(%rbp)
                                   mov    %r14,0x10(%rbp)
 1.64   0.46   0.00   0.00         mov    %r15,0x18(%rbp)

Quoted 1 line

Do these numbers look sane to you guys?

From my experiments, mov is often the top time consumer. But

mov %rsp,%rbp

is a little weird. It does not access cache, right?

Quoted 7 lines

Song, I also noticed that source code is not being intermixed for the --stdio annotation, while it works, to some degree, for '--tui', i.e. when you do 'perf top', press '/bpf' to show just symbols with that substring and then press enter or 'A' to annotate, we can see the original C source code for the BPF program, but it is mangling the screen sometimes, I need to try and fix, please take a look if you have the time.

I will take a look at this, most likely after LSFMM.

Quoted 4 lines

Also things like the callq targets need some work to tell what function is that, which as I said isn't appearing on the --stdio2 output, but appears on the --tui, i.e. we need to resolve that symbol to check how to map back to a BPF helper or any othe callq target.

I am aware of missing callq symbol. I was thinking they are less critical with source code.

Quoted 2 lines

Also, what about those 'je 0', i.e. the target is being misinterpreted or is this some BPF construct I should've know about? :)

I didn't notice the je 0 before. Let me try reproduce it.

Thanks,
Song

Quoted 19 lines

2.68 0.00 0.00 0.00 mov %rdi,%rbx
→ callq *ffffffffd359487f
mov %eax,-0x148(%rbp)
9.61 0.00 0.00 0.00 mov %rbp,%rsi

                                   add    $0xfffffffffffffeb8,%rsi     
                                   movabs $0xffff9d556c776c00,%rdi

                                 → callq  *ffffffffd3595b2f            
                                   cmp    $0x0,%rax                    
                                 → je     0                            
 0.00   1.25   0.00   0.00         add    $0x38,%rax                   
 0.80   0.21   0.00   0.00         xor    %r13d,%r13d                  
                                   cmp    $0x0,%rax                    

→ jne 0
mov %rbp,%rdi
add $0xfffffffffffffeb8,%rdi

- Arnaldo

Em Fri, Apr 26, 2019 at 07:11:37PM +0000, Song Liu escreveu:

Quoted 56 lines

Quoted 56 lines · Arnaldo Carvalho de Melo

tldr; more to the end there are some annotation for all sorts of cache level misses trying to validate the 'perf annotation' output for disassembled BPF programs.

[root@quaco ~]# uname -a
Linux quaco 5.1.0-rc5+ #4 SMP Wed Apr 17 19:33:00 -03 2019 x86_64 x86_64 x86_64 GNU/Linux

Running perf trace with:

[root@quaco ~]# cat ~/.perfconfig
[llvm]
dump-obj = true
clang-opt = -g
[trace]
add_events = /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.c #add_events = /wb/augmented_raw_syscalls.o
show_zeros = yes
show_duration = no
no_inherit = yes
show_timestamp = no
show_arg_names = no
args_alignment = 40
show_prefix = yes

[annotate]

hide_src_code = false
[root@quaco ~]#

clang/llvm 9:

[root@quaco perf]# eu-readelf -winfo /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o | grep compile_unit
[ b] compile_unit abbrev: 1
[root@quaco perf]# eu-readelf -winfo /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o | grep compile_unit -B1 -A10
Version: 4, Abbreviation section offset: 0, Address size: 8, Offset size: 4
[ b] compile_unit abbrev: 1

           producer             (strp) "clang version 9.0.0 (https://urldefense.proofpoint.com/v2/url?u=https-3A__git.llvm.org_git_clang.git_&d=DwIDaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=dR8692q0_uaizy0jkrBJQM5k2hfm4CiFxYT8KaysFrg&m=8ymLhVNE6vfRn0KCyz7xlPkm7i1H4ttMrMYmeHEP1Cg&s=3_k_sPaZo7mwxQMoYhgd4hBUmCoS3TboKrw15yws6mA&e= 7906282d3afec5dfdc2b27943fd6c0309086c507) (https://urldefense.proofpoint.com/v2/url?u=https-3A__git.llvm.org_git_llvm.git_&d=DwIDaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=dR8692q0_uaizy0jkrBJQM5k2hfm4CiFxYT8KaysFrg&m=8ymLhVNE6vfRn0KCyz7xlPkm7i1H4ttMrMYmeHEP1Cg&s=jutQ4xaAa5FePXthz5gHAgdx6kVlrPI64pnpqWWt59Q&e= a1b5de1ff8ae8bc79dc8e86e1f82565229bd0500)"
           language             (data2) C99 (12)
           name                 (strp) "/home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.c"
           stmt_list            (sec_offset) 0
           comp_dir             (strp) "/root"
           low_pc               (addr) raw_syscalls:sys_enter+000000000000000000 <sys_enter>
           ranges               (sec_offset) range list [     0]

[ 2a] variable abbrev: 2
name (strp) "__augmented_syscalls__"
type (ref4) [ 3f]
[root@quaco perf]#

I then leave this running doing system wide syscall tracing using that augmented_raw_syscalls.c eBPF program hooked into the syscall enter and exit tracepoints, so that I have something to profile and further test the BPF support in perf top/annotate/report (slides for LSFMM anyone? :-)) then I get:

Quoted 3 lines

Quoted 1 line

# perf trace -a sleep 100h

wow, I never tried to run sleep with "100h". ;-)

This is me dreaming of the long night sleeps I don't have for about 3.3 years by now ;-)

Quoted 146 lines

Quoted 145 lines

<SNIP>
tmux: server/11597 ioctl(8</dev/ptmx>, TIOCLINUX, 0x7ffe1b49abf8) = 0
tmux: server/11597 readv(8, 0x7ffe1b49ac00, 1) = 101
tmux: server/11597 ioctl(8</dev/ptmx>, TIOCSPGRP, 0x7ffe1b49a9f4) = 0
tmux: server/11597 openat(AT_FDCWD, "/proc/30339/cmdline", O_RDONLY) = 5
tmux: server/11597 fstat(5, 0x7ffe1b49a8e0) = 0
tmux: server/11597 read(5, 0x5571aaeb2c10, 1024) = 10
tmux: server/11597 close(5) = 0
gnome-shell/19195 ... [continued]: ioctl()) = 0
tmux: server/11597 poll(0x5571aad38e50, 6, 11997) ...
gnome-shell/19195 ioctl(11</dev/dri/card0>, DRM_MODE_RMFB, 0x7ffc2129c25c) = 0
gnome-shell/19195 recvmsg(39<socket:[18671390]>, 0x7ffc2129c440, NONE) = -1 EAGAIN (Resource temporarily unavailable) <SNIP>

With that running, I do:

[root@quaco perf]# perf record -a sleep 2s
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.647 MB perf.data (3698 samples) ] [root@quaco perf]#

I.e. collect 2 seconds worth of CPU cycles samples, system wide.

[root@quaco perf]# perf record -a sleep 2s
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 2.328 MB perf.data (17764 samples) ] [root@quaco perf]# perf report --header-only perf.data | grep -i b[pt]f

# event : name = cycles, , id = { 266608, 266609, 266610, 266611, 266612, 266613, 266614, 266615 }, size = 112, { sample_period, sample_freq } = 4000, sample_type = IP|TID|TIME|CPU|PERIOD, read_format = ID, disabled = 1, inherit = 1, mmap = 1, comm = 1, freq = 1, task = 1, precise_ip = 3, sample_id_all = 1, exclude_guest = 1, mmap2 = 1, comm_exec = 1, ksymbol = 1, bpf_event = 1
# bpf_prog_info 13: bpf_prog_7be49e3934a125ba addr 0xffffffffc0437f01 size 229
# bpf_prog_info 14: bpf_prog_2a142ef67aaad174 addr 0xffffffffc04393cd size 229
# bpf_prog_info 17: bpf_prog_7be49e3934a125ba addr 0xffffffffc052ca3c size 229
# bpf_prog_info 18: bpf_prog_2a142ef67aaad174 addr 0xffffffffc0531218 size 229
# bpf_prog_info 21: bpf_prog_7be49e3934a125ba addr 0xffffffffc0cb8010 size 229
# bpf_prog_info 22: bpf_prog_2a142ef67aaad174 addr 0xffffffffc0cba8be size 229
# bpf_prog_info 65: bpf_prog_7be49e3934a125ba addr 0xffffffffc03f6bc2 size 229
# bpf_prog_info 66: bpf_prog_2a142ef67aaad174 addr 0xffffffffc03f87f6 size 229
# bpf_prog_info 125: bpf_prog_819967866022f1e1_sys_enter addr 0xffffffffc0c6e5a1 size 381
# bpf_prog_info 126: bpf_prog_c1bd85c092d6e4aa_sys_exit addr 0xffffffffc0c953a8 size 191
[root@quaco perf]#

So everything seems in order, but then:

[root@quaco perf]# perf report | grep bpf_prog

     0.14%  perf             bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.08%  gnome-terminal-  bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
     0.06%  perf             bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
     0.04%  gnome-terminal-  bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.01%  alsa-sink-ALC25  bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
     0.01%  Web Content      bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.01%  lvmetad          bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
     0.00%  alsa-sink-ALC25  bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.00%  sssd_kcm         bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.00%  gnome-shell      bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
     0.00%  firefox          bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.00%  weechat          bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.00%  WebExtensions    bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.00%  Timer            bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
     0.00%  Web Content      bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter

[root@quaco perf]#

Ok, lets check that bpf_prog_819967866022f1e1_sys_enter symbol, 38% of the samples at just at that %rbp, more in a previous run...

[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 25 of event 'cycles', 4000 Hz, Event count (approx.): 7248318, [percent: local period] bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
38.00 push %rbp

2.72 mov %rsp,%rbp

               sub    $0x170,%rsp
13.19         sub    $0x28,%rbp
  3.30         mov    %rbx,0x0(%rbp)
20.33         mov    %r13,0x8(%rbp)
               mov    %r14,0x10(%rbp)
               mov    %r15,0x18(%rbp)
               xor    %eax,%eax
               mov    %rax,0x20(%rbp)
               mov    %rdi,%rbx
13.34       → callq  *ffffffffd359487f
               mov    %eax,-0x148(%rbp)

So I ended up trying with a event group to check what could be that:

[root@quaco perf]# perf record -a -e '{cycles,instructions,cache-misses}' sleep 2s
[ perf record: Woken up 18 times to write data ]
[ perf record: Captured and wrote 6.619 MB perf.data (91964 samples) ]
[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 314 of events 'anon group { cycles, instructions, cache-misses }', 4000 Hz, Event count (approx.): 118106063, [percent: local period] bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
20.88 24.58 49.11 push %rbp

47.37 31.62 26.71 mov %rsp,%rbp

  1.16   0.00   0.00         sub    $0x170,%rsp
                             sub    $0x28,%rbp
  0.58   2.48   0.00         mov    %rbx,0x0(%rbp)
  7.10   5.92   0.00         mov    %r13,0x8(%rbp)
  0.51   0.96   7.96         mov    %r14,0x10(%rbp)
  0.00   1.10   0.00         mov    %r15,0x18(%rbp)
  0.58   0.00   0.00         xor    %eax,%eax
                             mov    %rax,0x20(%rbp)
  2.39   0.85   0.00         mov    %rdi,%rbx
  0.58   1.96   0.00       → callq  *ffffffffd359487f
                             mov    %eax,-0x148(%rbp)
  2.88   0.89   3.50         mov    %rbp,%rsi
                             add    $0xfffffffffffffeb8,%rsi

So seems ok? I.e. that big cost at right the start of the BPF program is just cache pressure, probably, right?

[root@quaco perf]# perf record -a -e '{L1-icache-load-misses,L1-dcache-load-misses}' sleep 2s
[ perf record: Woken up 14 times to write data ]
[ perf record: Captured and wrote 5.557 MB perf.data (72026 samples) ]
[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 376 of events 'anon group { L1-icache-load-misses, L1-dcache-load-misses }', 4000 Hz, Event count (approx.): 3715276, [percent: local p> bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
1.54 63.01 push %rbp

53.09 28.13 mov %rsp,%rbp

  0.58   0.00         sub    $0x170,%rsp
  0.00   0.55         sub    $0x28,%rbp
  6.96   0.00         mov    %rbx,0x0(%rbp)
10.25   0.00         mov    %r13,0x8(%rbp)
  0.73   0.00         mov    %r14,0x10(%rbp)
  3.04   0.00         mov    %r15,0x18(%rbp)

Looks like. furthermore:

[root@quaco perf]# perf record -a -e '{L1-icache-load-misses,L1-dcache-load-misses,dTLB-load-misses,iTLB-load-misses}' sleep 2s [ perf record: Woken up 21 times to write data ]
[ perf record: Captured and wrote 7.708 MB perf.data (112323 samples) ]
[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 391 of events 'anon group { L1-icache-load-misses, L1-dcache-load-misses, dTLB-load-misses, iTLB-load-misses }', 4000 Hz, Event count (> bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
1.98 64.42 100.00 13.66 push %rbp

50.79 23.91 0.00 82.23 mov %rsp,%rbp

                                    sub    $0x170,%rsp
  0.24   0.00   0.00   0.00         sub    $0x28,%rbp
  7.73   0.00   0.00   0.00         mov    %rbx,0x0(%rbp)
11.13   0.44   0.00   0.00         mov    %r13,0x8(%rbp)
                                    mov    %r14,0x10(%rbp)

1.64 0.46 0.00 0.00 mov %r15,0x18(%rbp)

Do these numbers look sane to you guys?

Quoted 5 lines

From my experiments, mov is often the top time consumer. But

mov %rsp,%rbp

is a little weird. It does not access cache, right?

Right, but its like the code for bpf_prog_819967866022f1e1_sys_enter is being sucked into L1 icache at that point, no?

Quoted 10 lines

Quoted 8 lines

Song, I also noticed that source code is not being intermixed for the --stdio annotation, while it works, to some degree, for '--tui', i.e. when you do 'perf top', press '/bpf' to show just symbols with that substring and then press enter or 'A' to annotate, we can see the original C source code for the BPF program, but it is mangling the screen sometimes, I need to try and fix, please take a look if you have the time.

I will take a look at this, most likely after LSFMM.

mmkay

Quoted 4 lines

Quoted 4 lines

Also things like the callq targets need some work to tell what function is that, which as I said isn't appearing on the --stdio2 output, but appears on the --tui, i.e. we need to resolve that symbol to check how to map back to a BPF helper or any othe callq target.

Quoted 2 lines

I am aware of missing callq symbol. I was thinking they are less critical with source code.

Some people dislikes intermixing C and assembly, Linus is one, IIRC, so if we can augment the assembly resolving those addresses to the helper, that would be best.

Quoted 4 lines

Quoted 2 lines

Also, what about those 'je 0', i.e. the target is being misinterpreted or is this some BPF construct I should've know about? :)

I didn't notice the je 0 before. Let me try reproduce it.

Ok!

Quoted 23 lines

Thanks,
Song

Quoted 19 lines

2.68 0.00 0.00 0.00 mov %rdi,%rbx
→ callq *ffffffffd359487f
mov %eax,-0x148(%rbp)
9.61 0.00 0.00 0.00 mov %rbp,%rsi

                                    add    $0xfffffffffffffeb8,%rsi
                                    movabs $0xffff9d556c776c00,%rdi

                                  → callq  *ffffffffd3595b2f
                                    cmp    $0x0,%rax
                                  → je     0
  0.00   1.25   0.00   0.00         add    $0x38,%rax
  0.80   0.21   0.00   0.00         xor    %r13d,%r13d
                                    cmp    $0x0,%rax

→ jne 0
mov %rbp,%rdi
add $0xfffffffffffffeb8,%rdi

- Arnaldo

Quoted 212 lines

Em Fri, Apr 26, 2019 at 07:11:37PM +0000, Song Liu escreveu:

Quoted 56 lines

Quoted 56 lines · Arnaldo Carvalho de Melo

tldr; more to the end there are some annotation for all sorts of cache level misses trying to validate the 'perf annotation' output for disassembled BPF programs.

[root@quaco ~]# uname -a
Linux quaco 5.1.0-rc5+ #4 SMP Wed Apr 17 19:33:00 -03 2019 x86_64 x86_64 x86_64 GNU/Linux

Running perf trace with:

[root@quaco ~]# cat ~/.perfconfig
[llvm]
dump-obj = true
clang-opt = -g
[trace]
add_events = /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.c #add_events = /wb/augmented_raw_syscalls.o
show_zeros = yes
show_duration = no
no_inherit = yes
show_timestamp = no
show_arg_names = no
args_alignment = 40
show_prefix = yes

[annotate]

hide_src_code = false
[root@quaco ~]#

clang/llvm 9:

[root@quaco perf]# eu-readelf -winfo /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o | grep compile_unit
[ b] compile_unit abbrev: 1
[root@quaco perf]# eu-readelf -winfo /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o | grep compile_unit -B1 -A10
Version: 4, Abbreviation section offset: 0, Address size: 8, Offset size: 4
[ b] compile_unit abbrev: 1

           producer             (strp) "clang version 9.0.0 (https://urldefense.proofpoint.com/v2/url?u=https-3A__git.llvm.org_git_clang.git_&d=DwIDaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=dR8692q0_uaizy0jkrBJQM5k2hfm4CiFxYT8KaysFrg&m=8ymLhVNE6vfRn0KCyz7xlPkm7i1H4ttMrMYmeHEP1Cg&s=3_k_sPaZo7mwxQMoYhgd4hBUmCoS3TboKrw15yws6mA&e= 7906282d3afec5dfdc2b27943fd6c0309086c507) (https://urldefense.proofpoint.com/v2/url?u=https-3A__git.llvm.org_git_llvm.git_&d=DwIDaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=dR8692q0_uaizy0jkrBJQM5k2hfm4CiFxYT8KaysFrg&m=8ymLhVNE6vfRn0KCyz7xlPkm7i1H4ttMrMYmeHEP1Cg&s=jutQ4xaAa5FePXthz5gHAgdx6kVlrPI64pnpqWWt59Q&e= a1b5de1ff8ae8bc79dc8e86e1f82565229bd0500)"
           language             (data2) C99 (12)
           name                 (strp) "/home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.c"
           stmt_list            (sec_offset) 0
           comp_dir             (strp) "/root"
           low_pc               (addr) raw_syscalls:sys_enter+000000000000000000 <sys_enter>
           ranges               (sec_offset) range list [     0]

[ 2a] variable abbrev: 2
name (strp) "__augmented_syscalls__"
type (ref4) [ 3f]
[root@quaco perf]#

I then leave this running doing system wide syscall tracing using that augmented_raw_syscalls.c eBPF program hooked into the syscall enter and exit tracepoints, so that I have something to profile and further test the BPF support in perf top/annotate/report (slides for LSFMM anyone? :-)) then I get:

Quoted 3 lines

Quoted 1 line

# perf trace -a sleep 100h

wow, I never tried to run sleep with "100h". ;-)

This is me dreaming of the long night sleeps I don't have for about 3.3 years by now ;-)

Quoted 148 lines

Quoted 137 lines

<SNIP>
tmux: server/11597 ioctl(8</dev/ptmx>, TIOCLINUX, 0x7ffe1b49abf8) = 0
tmux: server/11597 readv(8, 0x7ffe1b49ac00, 1) = 101
tmux: server/11597 ioctl(8</dev/ptmx>, TIOCSPGRP, 0x7ffe1b49a9f4) = 0
tmux: server/11597 openat(AT_FDCWD, "/proc/30339/cmdline", O_RDONLY) = 5
tmux: server/11597 fstat(5, 0x7ffe1b49a8e0) = 0
tmux: server/11597 read(5, 0x5571aaeb2c10, 1024) = 10
tmux: server/11597 close(5) = 0
gnome-shell/19195 ... [continued]: ioctl()) = 0
tmux: server/11597 poll(0x5571aad38e50, 6, 11997) ...
gnome-shell/19195 ioctl(11</dev/dri/card0>, DRM_MODE_RMFB, 0x7ffc2129c25c) = 0
gnome-shell/19195 recvmsg(39<socket:[18671390]>, 0x7ffc2129c440, NONE) = -1 EAGAIN (Resource temporarily unavailable) <SNIP>

With that running, I do:

[root@quaco perf]# perf record -a sleep 2s
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.647 MB perf.data (3698 samples) ] [root@quaco perf]#

I.e. collect 2 seconds worth of CPU cycles samples, system wide.

[root@quaco perf]# perf record -a sleep 2s
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 2.328 MB perf.data (17764 samples) ] [root@quaco perf]# perf report --header-only perf.data | grep -i b[pt]f

# event : name = cycles, , id = { 266608, 266609, 266610, 266611, 266612, 266613, 266614, 266615 }, size = 112, { sample_period, sample_freq } = 4000, sample_type = IP|TID|TIME|CPU|PERIOD, read_format = ID, disabled = 1, inherit = 1, mmap = 1, comm = 1, freq = 1, task = 1, precise_ip = 3, sample_id_all = 1, exclude_guest = 1, mmap2 = 1, comm_exec = 1, ksymbol = 1, bpf_event = 1
# bpf_prog_info 13: bpf_prog_7be49e3934a125ba addr 0xffffffffc0437f01 size 229
# bpf_prog_info 14: bpf_prog_2a142ef67aaad174 addr 0xffffffffc04393cd size 229
# bpf_prog_info 17: bpf_prog_7be49e3934a125ba addr 0xffffffffc052ca3c size 229
# bpf_prog_info 18: bpf_prog_2a142ef67aaad174 addr 0xffffffffc0531218 size 229
# bpf_prog_info 21: bpf_prog_7be49e3934a125ba addr 0xffffffffc0cb8010 size 229
# bpf_prog_info 22: bpf_prog_2a142ef67aaad174 addr 0xffffffffc0cba8be size 229
# bpf_prog_info 65: bpf_prog_7be49e3934a125ba addr 0xffffffffc03f6bc2 size 229
# bpf_prog_info 66: bpf_prog_2a142ef67aaad174 addr 0xffffffffc03f87f6 size 229
# bpf_prog_info 125: bpf_prog_819967866022f1e1_sys_enter addr 0xffffffffc0c6e5a1 size 381
# bpf_prog_info 126: bpf_prog_c1bd85c092d6e4aa_sys_exit addr 0xffffffffc0c953a8 size 191
[root@quaco perf]#

So everything seems in order, but then:

[root@quaco perf]# perf report | grep bpf_prog

     0.14%  perf             bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.08%  gnome-terminal-  bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
     0.06%  perf             bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
     0.04%  gnome-terminal-  bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.01%  alsa-sink-ALC25  bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
     0.01%  Web Content      bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.01%  lvmetad          bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
     0.00%  alsa-sink-ALC25  bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.00%  sssd_kcm         bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.00%  gnome-shell      bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
     0.00%  firefox          bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.00%  weechat          bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.00%  WebExtensions    bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
     0.00%  Timer            bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
     0.00%  Web Content      bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter

[root@quaco perf]#

Ok, lets check that bpf_prog_819967866022f1e1_sys_enter symbol, 38% of the samples at just at that %rbp, more in a previous run...

[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 25 of event 'cycles', 4000 Hz, Event count (approx.): 7248318, [percent: local period] bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
38.00 push %rbp

2.72 mov %rsp,%rbp

               sub    $0x170,%rsp
13.19         sub    $0x28,%rbp
  3.30         mov    %rbx,0x0(%rbp)
20.33         mov    %r13,0x8(%rbp)
               mov    %r14,0x10(%rbp)
               mov    %r15,0x18(%rbp)
               xor    %eax,%eax
               mov    %rax,0x20(%rbp)
               mov    %rdi,%rbx
13.34       → callq  *ffffffffd359487f
               mov    %eax,-0x148(%rbp)

So I ended up trying with a event group to check what could be that:

[root@quaco perf]# perf record -a -e '{cycles,instructions,cache-misses}' sleep 2s
[ perf record: Woken up 18 times to write data ]
[ perf record: Captured and wrote 6.619 MB perf.data (91964 samples) ]
[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 314 of events 'anon group { cycles, instructions, cache-misses }', 4000 Hz, Event count (approx.): 118106063, [percent: local period] bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
20.88 24.58 49.11 push %rbp

47.37 31.62 26.71 mov %rsp,%rbp

  1.16   0.00   0.00         sub    $0x170,%rsp
                             sub    $0x28,%rbp
  0.58   2.48   0.00         mov    %rbx,0x0(%rbp)
  7.10   5.92   0.00         mov    %r13,0x8(%rbp)
  0.51   0.96   7.96         mov    %r14,0x10(%rbp)
  0.00   1.10   0.00         mov    %r15,0x18(%rbp)
  0.58   0.00   0.00         xor    %eax,%eax
                             mov    %rax,0x20(%rbp)
  2.39   0.85   0.00         mov    %rdi,%rbx
  0.58   1.96   0.00       → callq  *ffffffffd359487f
                             mov    %eax,-0x148(%rbp)
  2.88   0.89   3.50         mov    %rbp,%rsi
                             add    $0xfffffffffffffeb8,%rsi

So seems ok? I.e. that big cost at right the start of the BPF program is just cache pressure, probably, right?

[root@quaco perf]# perf record -a -e '{L1-icache-load-misses,L1-dcache-load-misses}' sleep 2s
[ perf record: Woken up 14 times to write data ]
[ perf record: Captured and wrote 5.557 MB perf.data (72026 samples) ]
[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 376 of events 'anon group { L1-icache-load-misses, L1-dcache-load-misses }', 4000 Hz, Event count (approx.): 3715276, [percent: local p> bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
1.54 63.01 push %rbp

53.09 28.13 mov %rsp,%rbp

  0.58   0.00         sub    $0x170,%rsp
  0.00   0.55         sub    $0x28,%rbp
  6.96   0.00         mov    %rbx,0x0(%rbp)
10.25   0.00         mov    %r13,0x8(%rbp)
  0.73   0.00         mov    %r14,0x10(%rbp)
  3.04   0.00         mov    %r15,0x18(%rbp)

Looks like. furthermore:

[root@quaco perf]# perf record -a -e '{L1-icache-load-misses,L1-dcache-load-misses,dTLB-load-misses,iTLB-load-misses}' sleep 2s [ perf record: Woken up 21 times to write data ]
[ perf record: Captured and wrote 7.708 MB perf.data (112323 samples) ]
[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 391 of events 'anon group { L1-icache-load-misses, L1-dcache-load-misses, dTLB-load-misses, iTLB-load-misses }', 4000 Hz, Event count (> bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
1.98 64.42 100.00 13.66 push %rbp

50.79 23.91 0.00 82.23 mov %rsp,%rbp

Quoted 8 lines

                                    sub    $0x170,%rsp
  0.24   0.00   0.00   0.00         sub    $0x28,%rbp
  7.73   0.00   0.00   0.00         mov    %rbx,0x0(%rbp)
11.13   0.44   0.00   0.00         mov    %r13,0x8(%rbp)
                                    mov    %r14,0x10(%rbp)

1.64 0.46 0.00 0.00 mov %r15,0x18(%rbp)

Do these numbers look sane to you guys?

From my experiments, mov is often the top time consumer. But

Quoted 6 lines

Quoted 3 lines

mov %rsp,%rbp

is a little weird. It does not access cache, right?

Right, but its like the code for bpf_prog_819967866022f1e1_sys_enter is being sucked into L1 icache at that point, no?

do you need to enable pebs (precise event-based sampling)?

Quoted 24 lines

Quoted 9 lines

Quoted 7 lines

Song, I also noticed that source code is not being intermixed for the --stdio annotation, while it works, to some degree, for '--tui', i.e. when you do 'perf top', press '/bpf' to show just symbols with that substring and then press enter or 'A' to annotate, we can see the original C source code for the BPF program, but it is mangling the screen sometimes, I need to try and fix, please take a look if you have the time.

I will take a look at this, most likely after LSFMM.

mmkay

Quoted 7 lines

Quoted 4 lines

Also things like the callq targets need some work to tell what function is that, which as I said isn't appearing on the --stdio2 output, but appears on the --tui, i.e. we need to resolve that symbol to check how to map back to a BPF helper or any othe callq target.

I am aware of missing callq symbol. I was thinking they are less critical with source code.

Some people dislikes intermixing C and assembly, Linus is one, IIRC, so if we can augment the assembly resolving those addresses to the helper, that would be best.

Quoted 4 lines

Quoted 4 lines

Quoted 2 lines

Also, what about those 'je 0', i.e. the target is being misinterpreted or is this some BPF construct I should've know about? :)

I didn't notice the je 0 before. Let me try reproduce it.

Did you see these je 0 when you use bpftool dump jited instructions? With dumping source annotated jited/xlated instructions, you can get rough idea where this je 0 is coming from. Want to give a try?

Quoted 27 lines

Ok!

Quoted 23 lines

Thanks,
Song

Quoted 19 lines

2.68 0.00 0.00 0.00 mov %rdi,%rbx
→ callq *ffffffffd359487f
mov %eax,-0x148(%rbp)
9.61 0.00 0.00 0.00 mov %rbp,%rsi

                                    add    $0xfffffffffffffeb8,%rsi
                                    movabs $0xffff9d556c776c00,%rdi

                                  → callq  *ffffffffd3595b2f
                                    cmp    $0x0,%rax
                                  → je     0
  0.00   1.25   0.00   0.00         add    $0x38,%rax
  0.80   0.21   0.00   0.00         xor    %r13d,%r13d
                                    cmp    $0x0,%rax

→ jne 0
mov %rbp,%rdi
add $0xfffffffffffffeb8,%rdi

- Arnaldo

Em Fri, Apr 26, 2019 at 08:51:09PM +0000, Yonghong Song escreveu:

Quoted 213 lines · Arnaldo Carvalho de Melo

Quoted 212 lines

Em Fri, Apr 26, 2019 at 07:11:37PM +0000, Song Liu escreveu:

Quoted 56 lines

Quoted 56 lines · Arnaldo Carvalho de Melo

tldr; more to the end there are some annotation for all sorts of cache level misses trying to validate the 'perf annotation' output for disassembled BPF programs.

[root@quaco ~]# uname -a
Linux quaco 5.1.0-rc5+ #4 SMP Wed Apr 17 19:33:00 -03 2019 x86_64 x86_64 x86_64 GNU/Linux

Running perf trace with:

[root@quaco ~]# cat ~/.perfconfig
[llvm]
dump-obj = true
clang-opt = -g
[trace]
add_events = /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.c #add_events = /wb/augmented_raw_syscalls.o
show_zeros = yes
show_duration = no
no_inherit = yes
show_timestamp = no
show_arg_names = no
args_alignment = 40
show_prefix = yes

[annotate]

hide_src_code = false
[root@quaco ~]#

clang/llvm 9:

[root@quaco perf]# eu-readelf -winfo /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o | grep compile_unit
[ b] compile_unit abbrev: 1
[root@quaco perf]# eu-readelf -winfo /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.o | grep compile_unit -B1 -A10
Version: 4, Abbreviation section offset: 0, Address size: 8, Offset size: 4

[     b]  compile_unit         abbrev: 1
          producer             (strp) "clang version 9.0.0 (https://urldefense.proofpoint.com/v2/url?u=https-3A__git.llvm.org_git_clang.git_&d=DwIDaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=dR8692q0_uaizy0jkrBJQM5k2hfm4CiFxYT8KaysFrg&m=8ymLhVNE6vfRn0KCyz7xlPkm7i1H4ttMrMYmeHEP1Cg&s=3_k_sPaZo7mwxQMoYhgd4hBUmCoS3TboKrw15yws6mA&e= 7906282d3afec5dfdc2b27943fd6c0309086c507) (https://urldefense.proofpoint.com/v2/url?u=https-3A__git.llvm.org_git_llvm.git_&d=DwIDaQ&c=5VD0RTtNlTh3ycd41b3MUw&r=dR8692q0_uaizy0jkrBJQM5k2hfm4CiFxYT8KaysFrg&m=8ymLhVNE6vfRn0KCyz7xlPkm7i1H4ttMrMYmeHEP1Cg&s=jutQ4xaAa5FePXthz5gHAgdx6kVlrPI64pnpqWWt59Q&e= a1b5de1ff8ae8bc79dc8e86e1f82565229bd0500)"
          language             (data2) C99 (12)
          name                 (strp) "/home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.c"
          stmt_list            (sec_offset) 0
          comp_dir             (strp) "/root"
          low_pc               (addr) raw_syscalls:sys_enter+000000000000000000 <sys_enter>
          ranges               (sec_offset) range list [     0]
[    2a]    variable             abbrev: 2
            name                 (strp) "__augmented_syscalls__"
            type                 (ref4) [    3f]

[root@quaco perf]#

I then leave this running doing system wide syscall tracing using that augmented_raw_syscalls.c eBPF program hooked into the syscall enter and exit tracepoints, so that I have something to profile and further test the BPF support in perf top/annotate/report (slides for LSFMM anyone? :-)) then I get:

Quoted 3 lines

Quoted 1 line

# perf trace -a sleep 100h

wow, I never tried to run sleep with "100h". ;-)

This is me dreaming of the long night sleeps I don't have for about 3.3 years by now ;-)

Quoted 148 lines

Quoted 144 lines

<SNIP>
tmux: server/11597 ioctl(8</dev/ptmx>, TIOCLINUX, 0x7ffe1b49abf8) = 0
tmux: server/11597 readv(8, 0x7ffe1b49ac00, 1) = 101
tmux: server/11597 ioctl(8</dev/ptmx>, TIOCSPGRP, 0x7ffe1b49a9f4) = 0
tmux: server/11597 openat(AT_FDCWD, "/proc/30339/cmdline", O_RDONLY) = 5
tmux: server/11597 fstat(5, 0x7ffe1b49a8e0) = 0
tmux: server/11597 read(5, 0x5571aaeb2c10, 1024) = 10
tmux: server/11597 close(5) = 0
gnome-shell/19195 ... [continued]: ioctl()) = 0
tmux: server/11597 poll(0x5571aad38e50, 6, 11997) ...
gnome-shell/19195 ioctl(11</dev/dri/card0>, DRM_MODE_RMFB, 0x7ffc2129c25c) = 0
gnome-shell/19195 recvmsg(39<socket:[18671390]>, 0x7ffc2129c440, NONE) = -1 EAGAIN (Resource temporarily unavailable) <SNIP>

With that running, I do:

[root@quaco perf]# perf record -a sleep 2s
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.647 MB perf.data (3698 samples) ] [root@quaco perf]#

I.e. collect 2 seconds worth of CPU cycles samples, system wide.

[root@quaco perf]# perf record -a sleep 2s
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 2.328 MB perf.data (17764 samples) ] [root@quaco perf]# perf report --header-only perf.data | grep -i b[pt]f

# event : name = cycles, , id = { 266608, 266609, 266610, 266611, 266612, 266613, 266614, 266615 }, size = 112, { sample_period, sample_freq } = 4000, sample_type = IP|TID|TIME|CPU|PERIOD, read_format = ID, disabled = 1, inherit = 1, mmap = 1, comm = 1, freq = 1, task = 1, precise_ip = 3, sample_id_all = 1, exclude_guest = 1, mmap2 = 1, comm_exec = 1, ksymbol = 1, bpf_event = 1
# bpf_prog_info 13: bpf_prog_7be49e3934a125ba addr 0xffffffffc0437f01 size 229
# bpf_prog_info 14: bpf_prog_2a142ef67aaad174 addr 0xffffffffc04393cd size 229
# bpf_prog_info 17: bpf_prog_7be49e3934a125ba addr 0xffffffffc052ca3c size 229
# bpf_prog_info 18: bpf_prog_2a142ef67aaad174 addr 0xffffffffc0531218 size 229
# bpf_prog_info 21: bpf_prog_7be49e3934a125ba addr 0xffffffffc0cb8010 size 229
# bpf_prog_info 22: bpf_prog_2a142ef67aaad174 addr 0xffffffffc0cba8be size 229
# bpf_prog_info 65: bpf_prog_7be49e3934a125ba addr 0xffffffffc03f6bc2 size 229
# bpf_prog_info 66: bpf_prog_2a142ef67aaad174 addr 0xffffffffc03f87f6 size 229
# bpf_prog_info 125: bpf_prog_819967866022f1e1_sys_enter addr 0xffffffffc0c6e5a1 size 381
# bpf_prog_info 126: bpf_prog_c1bd85c092d6e4aa_sys_exit addr 0xffffffffc0c953a8 size 191
[root@quaco perf]#

So everything seems in order, but then:

[root@quaco perf]# perf report | grep bpf_prog

    0.14%  perf             bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.08%  gnome-terminal-  bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.06%  perf             bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.04%  gnome-terminal-  bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.01%  alsa-sink-ALC25  bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.01%  Web Content      bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.01%  lvmetad          bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.00%  alsa-sink-ALC25  bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.00%  sssd_kcm         bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.00%  gnome-shell      bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.00%  firefox          bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.00%  weechat          bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.00%  WebExtensions    bpf_prog_c1bd85c092d6e4aa_sys_exit   [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
    0.00%  Timer            bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter
    0.00%  Web Content      bpf_prog_819967866022f1e1_sys_enter  [k] bpf_prog_819967866022f1e1_sys_enter

[root@quaco perf]#

Ok, lets check that bpf_prog_819967866022f1e1_sys_enter symbol, 38% of the samples at just at that %rbp, more in a previous run...

[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 25 of event 'cycles', 4000 Hz, Event count (approx.): 7248318, [percent: local period] bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
38.00 push %rbp

 2.72         mov    %rsp,%rbp
              sub    $0x170,%rsp
13.19         sub    $0x28,%rbp
 3.30         mov    %rbx,0x0(%rbp)
20.33         mov    %r13,0x8(%rbp)
              mov    %r14,0x10(%rbp)
              mov    %r15,0x18(%rbp)
              xor    %eax,%eax
              mov    %rax,0x20(%rbp)
              mov    %rdi,%rbx
13.34       → callq  *ffffffffd359487f
              mov    %eax,-0x148(%rbp)

So I ended up trying with a event group to check what could be that:

[root@quaco perf]# perf record -a -e '{cycles,instructions,cache-misses}' sleep 2s
[ perf record: Woken up 18 times to write data ]
[ perf record: Captured and wrote 6.619 MB perf.data (91964 samples) ]
[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 314 of events 'anon group { cycles, instructions, cache-misses }', 4000 Hz, Event count (approx.): 118106063, [percent: local period] bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
20.88 24.58 49.11 push %rbp

47.37  31.62  26.71         mov    %rsp,%rbp
 1.16   0.00   0.00         sub    $0x170,%rsp
                            sub    $0x28,%rbp
 0.58   2.48   0.00         mov    %rbx,0x0(%rbp)
 7.10   5.92   0.00         mov    %r13,0x8(%rbp)
 0.51   0.96   7.96         mov    %r14,0x10(%rbp)
 0.00   1.10   0.00         mov    %r15,0x18(%rbp)
 0.58   0.00   0.00         xor    %eax,%eax
                            mov    %rax,0x20(%rbp)
 2.39   0.85   0.00         mov    %rdi,%rbx
 0.58   1.96   0.00       → callq  *ffffffffd359487f
                            mov    %eax,-0x148(%rbp)
 2.88   0.89   3.50         mov    %rbp,%rsi
                            add    $0xfffffffffffffeb8,%rsi

So seems ok? I.e. that big cost at right the start of the BPF program is just cache pressure, probably, right?

[root@quaco perf]# perf record -a -e '{L1-icache-load-misses,L1-dcache-load-misses}' sleep 2s
[ perf record: Woken up 14 times to write data ]
[ perf record: Captured and wrote 5.557 MB perf.data (72026 samples) ]
[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 376 of events 'anon group { L1-icache-load-misses, L1-dcache-load-misses }', 4000 Hz, Event count (approx.): 3715276, [percent: local p> bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
1.54 63.01 push %rbp

53.09  28.13         mov    %rsp,%rbp
 0.58   0.00         sub    $0x170,%rsp
 0.00   0.55         sub    $0x28,%rbp
 6.96   0.00         mov    %rbx,0x0(%rbp)
10.25   0.00         mov    %r13,0x8(%rbp)
 0.73   0.00         mov    %r14,0x10(%rbp)
 3.04   0.00         mov    %r15,0x18(%rbp)

Looks like. furthermore:

[root@quaco perf]# perf record -a -e '{L1-icache-load-misses,L1-dcache-load-misses,dTLB-load-misses,iTLB-load-misses}' sleep 2s [ perf record: Woken up 21 times to write data ]
[ perf record: Captured and wrote 7.708 MB perf.data (112323 samples) ]
[root@quaco perf]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 391 of events 'anon group { L1-icache-load-misses, L1-dcache-load-misses, dTLB-load-misses, iTLB-load-misses }', 4000 Hz, Event count (> bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
1.98 64.42 100.00 13.66 push %rbp

50.79  23.91   0.00  82.23         mov    %rsp,%rbp
                                   sub    $0x170,%rsp
 0.24   0.00   0.00   0.00         sub    $0x28,%rbp
 7.73   0.00   0.00   0.00         mov    %rbx,0x0(%rbp)
11.13   0.44   0.00   0.00         mov    %r13,0x8(%rbp)
                                   mov    %r14,0x10(%rbp)
 1.64   0.46   0.00   0.00         mov    %r15,0x18(%rbp)

Quoted 1 line

Do these numbers look sane to you guys?

From my experiments, mov is often the top time consumer. But

Quoted 8 lines

Quoted 6 lines

Quoted 3 lines

mov %rsp,%rbp

is a little weird. It does not access cache, right?

Right, but its like the code for bpf_prog_819967866022f1e1_sys_enter is being sucked into L1 icache at that point, no?

do you need to enable pebs (precise event-based sampling)?

So, when you don't specify a event, 'perf record' will use cycles:P, which is the highest level of (PEBS, on x86) precision available. But then that has some limitations, I'll try to check this later, to see if cache events can be counted that way, how many events, etc.

But I think that knowing that is on the first or second instruction is enough, i.e. it seems that somehow the eBPF program is not staying in the CPU cache all the time, which ends up making transferring control to them cause cache misses?

That was the reason for my message, to validate if this is the case or if the BPF perf annotation or sample address resolution are buggy.

Quoted 24 lines

Quoted 24 lines

Quoted 9 lines

Quoted 7 lines

Song, I also noticed that source code is not being intermixed for the --stdio annotation, while it works, to some degree, for '--tui', i.e. when you do 'perf top', press '/bpf' to show just symbols with that substring and then press enter or 'A' to annotate, we can see the original C source code for the BPF program, but it is mangling the screen sometimes, I need to try and fix, please take a look if you have the time.

I will take a look at this, most likely after LSFMM.

mmkay

Quoted 7 lines

Quoted 4 lines

Also things like the callq targets need some work to tell what function is that, which as I said isn't appearing on the --stdio2 output, but appears on the --tui, i.e. we need to resolve that symbol to check how to map back to a BPF helper or any othe callq target.

I am aware of missing callq symbol. I was thinking they are less critical with source code.

Some people dislikes intermixing C and assembly, Linus is one, IIRC, so if we can augment the assembly resolving those addresses to the helper, that would be best.

Quoted 8 lines

Quoted 4 lines

Quoted 4 lines

Quoted 2 lines

Also, what about those 'je 0', i.e. the target is being misinterpreted or is this some BPF construct I should've know about? :)

I didn't notice the je 0 before. Let me try reproduce it.

Did you see these je 0 when you use bpftool dump jited instructions? With dumping source annotated jited/xlated instructions, you can get rough idea where this je 0 is coming from. Want to give a try?

So, here is a fresh record:

[root@quaco ~]# perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
Samples: 40 of event 'cycles', 4000 Hz, Event count (approx.): 12152834, [percent: local period] bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
69.13 push %rbp

              mov    %rsp,%rbp
              sub    $0x170,%rsp
              sub    $0x28,%rbp
19.07         mov    %rbx,0x0(%rbp)
 2.08         mov    %r13,0x8(%rbp)
              mov    %r14,0x10(%rbp)
              mov    %r15,0x18(%rbp)
              xor    %eax,%eax
              mov    %rax,0x20(%rbp)
              mov    %rdi,%rbx
            → callq  *ffffffffd356dda0
 3.03         mov    %eax,-0x148(%rbp)
              mov    %rbp,%rsi
              add    $0xfffffffffffffeb8,%rsi
              movabs $0xffff9d5b7133a400,%rdi

1.17 → callq *ffffffffd356f050

              cmp    $0x0,%rax
            → je     0
              add    $0x38,%rax
              xor    %r13d,%r13d
              cmp    $0x0,%rax
            → jne    0
              mov    %rbp,%rdi
              add    $0xfffffffffffffeb8,%rdi
              mov    $0x40,%esi
              mov    %rbx,%rdx
            → callq  *ffffffffd354e490
              mov    %rbp,%rsi
              add    $0xfffffffffffffec0,%rsi
              movabs $0xffff9d5b6fe1e000,%rdi

[root@quaco ~]#

Plus the bpf prog dump jit, we're probably just parsing 32-bits, the zeroed part...

[root@quaco ~]# bpftool prog | tail -6
129: tracepoint name sys_enter tag 819967866022f1e1 gpl

	loaded_at 2019-04-26T19:31:10-0300  uid 0
	xlated 528B  jited 381B  memlock 4096B  map_ids 119,118,117
130: tracepoint  name sys_exit  tag c1bd85c092d6e4aa  gpl
	loaded_at 2019-04-26T19:31:10-0300  uid 0
	xlated 256B  jited 191B  memlock 4096B  map_ids 119,118
[root@quaco ~]# bpftool prog dump jit id 129
0xffffffffc0c95080:
  0:	push   %rbp
  1:	mov    %rsp,%rbp
  4:	sub    $0x170,%rsp
  b:	sub    $0x28,%rbp
  f:	mov    %rbx,0x0(%rbp)
 13:	mov    %r13,0x8(%rbp)
 17:	mov    %r14,0x10(%rbp)
 1b:	mov    %r15,0x18(%rbp)
 1f:	xor    %eax,%eax
 21:	mov    %rax,0x20(%rbp)
 25:	mov    %rdi,%rbx
 28:	callq  0xffffffffd356dda0
 2d:	mov    %eax,-0x148(%rbp)
 33:	mov    %rbp,%rsi
 36:	add    $0xfffffffffffffeb8,%rsi
 3d:	movabs $0xffff9d5b7133a400,%rdi
 47:	callq  0xffffffffd356f050
 4c:	cmp    $0x0,%rax
 50:	je     0x0000000000000056
 52:	add    $0x38,%rax
 56:	xor    %r13d,%r13d
 59:	cmp    $0x0,%rax
 5d:	jne    0x0000000000000164
 63:	mov    %rbp,%rdi
 66:	add    $0xfffffffffffffeb8,%rdi
 6d:	mov    $0x40,%esi
 72:	mov    %rbx,%rdx
 75:	callq  0xffffffffd354e490
 7a:	mov    %rbp,%rsi
 7d:	add    $0xfffffffffffffec0,%rsi
 84:	movabs $0xffff9d5b6fe1e000,%rdi
 8e:	add    $0xd0,%rdi
 95:	mov    0x0(%rsi),%eax
 98:	cmp    $0x200,%rax
 9f:	jae    0x00000000000000aa
 a1:	shl    $0x3,%rax
 a5:	add    %rdi,%rax
 a8:	jmp    0x00000000000000ac
 aa:	xor    %eax,%eax
 ac:	cmp    $0x0,%rax
 b0:	je     0x0000000000000164
 b6:	movzbq 0x0(%rax),%rdi
 bb:	cmp    $0x0,%rdi
 bf:	je     0x0000000000000164
 c5:	mov    $0x40,%r8d
 cb:	mov    -0x140(%rbp),%rdi
 d2:	cmp    $0x2,%rdi
 d6:	je     0x00000000000000e7
 d8:	cmp    $0x101,%rdi
 df:	je     0x00000000000000ed
 e1:	cmp    $0x15,%rdi
 e5:	jne    0x0000000000000140
 e7:	mov    0x10(%rbx),%rdx
 eb:	jmp    0x00000000000000f1
 ed:	mov    0x18(%rbx),%rdx
 f1:	cmp    $0x0,%rdx
 f5:	je     0x0000000000000140
 f7:	xor    %edi,%edi
 f9:	mov    %edi,-0x104(%rbp)
 ff:	mov    %rbp,%rdi
102:	add    $0xffffffffffffff00,%rdi
109:	mov    $0x100,%esi
10e:	callq  0xffffffffd354e520
113:	mov    $0x148,%r8d
119:	mov    %eax,-0x108(%rbp)
11f:	mov    %rax,%rdi
122:	shl    $0x20,%rdi
126:	shr    $0x20,%rdi
12a:	cmp    $0xff,%rdi
131:	ja     0x0000000000000140
133:	add    $0x48,%rax
137:	and    $0xff,%rax
13d:	mov    %rax,%r8
140:	mov    %rbp,%rcx
143:	add    $0xfffffffffffffeb8,%rcx
14a:	mov    %rbx,%rdi
14d:	movabs $0xffff9d58126aac00,%rsi
157:	mov    $0xffffffff,%edx
15c:	callq  0xffffffffd354eb60
161:	mov    %rax,%r13
164:	mov    %r13,%rax
167:	mov    0x0(%rbp),%rbx
16b:	mov    0x8(%rbp),%r13
16f:	mov    0x10(%rbp),%r14
173:	mov    0x18(%rbp),%r15
177:	add    $0x28,%rbp

17b: leaveq
17c: retq

[root@quaco ~]#

Quoted 28 lines

Quoted 28 lines

Ok!

Quoted 23 lines

Thanks,
Song

Quoted 19 lines

2.68 0.00 0.00 0.00 mov %rdi,%rbx
→ callq *ffffffffd359487f
mov %eax,-0x148(%rbp)
9.61 0.00 0.00 0.00 mov %rbp,%rsi

                                   add    $0xfffffffffffffeb8,%rsi
                                   movabs $0xffff9d556c776c00,%rdi

                                 → callq  *ffffffffd3595b2f
                                   cmp    $0x0,%rax
                                 → je     0
 0.00   1.25   0.00   0.00         add    $0x38,%rax
 0.80   0.21   0.00   0.00         xor    %r13d,%r13d
                                   cmp    $0x0,%rax

→ jne 0
mov %rbp,%rdi
add $0xfffffffffffffeb8,%rdi

- Arnaldo

Signature · 1 line

- Arnaldo

Song, I also noticed that source code is not being intermixed for the --stdio annotation, while it works, to some degree, for '--tui', i.e.

when you do 'perf top', press '/bpf' to show just symbols with that substring and then press enter or 'A' to annotate, we can see the original C source code for the BPF program, but it is mangling the screen sometimes, I need to try and fix, please take a look if you have the time.

Also things like the callq targets need some work to tell what function is that, which as I said isn't appearing on the --stdio2 output, but appears on the --tui, i.e. we need to resolve that symbol to check how to map back to a BPF helper or any othe callq target.

Also, what about those 'je 0', i.e. the target is being misinterpreted or is this some BPF construct I should've know about? :)

2.68 0.00 0.00 0.00 mov %rdi,%rbx
→ callq *ffffffffd359487f
mov %eax,-0x148(%rbp)
9.61 0.00 0.00 0.00 mov %rbp,%rsi

                                   add    $0xfffffffffffffeb8,%rsi     
                                   movabs $0xffff9d556c776c00,%rdi

                                 → callq  *ffffffffd3595b2f            
                                   cmp    $0x0,%rax                    
                                 → je     0                            
 0.00   1.25   0.00   0.00         add    $0x38,%rax                   
 0.80   0.21   0.00   0.00         xor    %r13d,%r13d                  
                                   cmp    $0x0,%rax                    

→ jne 0
mov %rbp,%rdi
add $0xfffffffffffffeb8,%rdi