lkml.org 
[lkml]   [2019]   [Mar]   [19]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
SubjectRe: [WORKS!] Re: [PATCH v9 perf,bpf 12/15] perf, bpf: enable annotation of bpf program
Date


> On Mar 19, 2019, at 7:52 AM, Arnaldo Carvalho de Melo <arnaldo.melo@gmail.com> wrote:
>
> Em Tue, Mar 19, 2019 at 11:14:35AM -0300, Arnaldo Carvalho de Melo escreveu:
>>
>> Now the test is really being performed, the test-all.bin feature
>> detection fast path is working, proceeding.
>
> Now it all works, really nice!
>
> I added a 'Committer testing' section with all the steps to test this
> and pushed to:
>
> https://git.kernel.org/pub/scm/linux/kernel/git/acme/linux.git/commit/?h=perf/core&id=6530d44e7dc1d41c73fe70b9e6ea1b9cabebb57f

Thanks Arnaldo! This looks great!

I will rebase https://lkml.org/lkml/2019/3/14/681 on top of this branch
and resend.

Song


> Which I repeat here, please go thru it and check if everything is ok, if
> the disassembled + original BPF source code looks ok, etc:
>
> Committer testing:
>
> 1) Have a BPF program running, one that has BTF info, etc, I used
> the tools/perf/examples/bpf/augmented_raw_syscalls.c put in place
> by 'perf trace'.
>
> # grep -B1 augmented_raw ~/.perfconfig
> [trace]
> add_events = /home/acme/git/perf/tools/perf/examples/bpf/augmented_raw_syscalls.c
> #
> # perf trace -e *mmsg
> dnf/6245 sendmmsg(20, 0x7f5485a88030, 2, MSG_NOSIGNAL) = 2
> NetworkManager/10055 sendmmsg(22<socket:[1056822]>, 0x7f8126ad1bb0, 2, MSG_NOSIGNAL) = 2
>
> 2) Then do a 'perf record' system wide for a while:
>
> # perf record -a
> ^C[ perf record: Woken up 68 times to write data ]
> [ perf record: Captured and wrote 19.427 MB perf.data (366891 samples) ]
> #
>
> 3) Check that we captured BPF and BTF info in the perf.data file:
>
> # perf report --header-only | grep 'b[pt]f'
> # event : name = cycles:ppp, , id = { 294789, 294790, 294791, 294792, 294793, 294794, 294795, 294796 }, 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 of id 13
> # bpf_prog_info of id 14
> # bpf_prog_info of id 15
> # bpf_prog_info of id 16
> # bpf_prog_info of id 17
> # bpf_prog_info of id 18
> # bpf_prog_info of id 21
> # bpf_prog_info of id 22
> # bpf_prog_info of id 41
> # bpf_prog_info of id 42
> # btf info of id 2
> #
>
> 4) Check which programs got recorded:
>
> # perf report | grep bpf_prog | head
> 0.16% exe bpf_prog_819967866022f1e1_sys_enter [k] bpf_prog_819967866022f1e1_sys_enter
> 0.14% exe bpf_prog_c1bd85c092d6e4aa_sys_exit [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
> 0.08% fuse-overlayfs bpf_prog_819967866022f1e1_sys_enter [k] bpf_prog_819967866022f1e1_sys_enter
> 0.07% fuse-overlayfs bpf_prog_c1bd85c092d6e4aa_sys_exit [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
> 0.01% clang-4.0 bpf_prog_c1bd85c092d6e4aa_sys_exit [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
> 0.01% clang-4.0 bpf_prog_819967866022f1e1_sys_enter [k] bpf_prog_819967866022f1e1_sys_enter
> 0.00% clang bpf_prog_c1bd85c092d6e4aa_sys_exit [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
> 0.00% runc bpf_prog_819967866022f1e1_sys_enter [k] bpf_prog_819967866022f1e1_sys_enter
> 0.00% clang bpf_prog_819967866022f1e1_sys_enter [k] bpf_prog_819967866022f1e1_sys_enter
> 0.00% sh bpf_prog_c1bd85c092d6e4aa_sys_exit [k] bpf_prog_c1bd85c092d6e4aa_sys_exit
> #
>
> This was with the default --sort order for 'perf report', which is:
>
> --sort comm,dso,symbol
>
> If we just look for the symbol, for instance:
>
> # perf report --sort symbol | grep bpf_prog | head
> 0.26% [k] bpf_prog_819967866022f1e1_sys_enter - -
> 0.24% [k] bpf_prog_c1bd85c092d6e4aa_sys_exit - -
> #
>
> or the DSO:
>
> # perf report --sort dso | grep bpf_prog | head
> 0.26% bpf_prog_819967866022f1e1_sys_enter
> 0.24% bpf_prog_c1bd85c092d6e4aa_sys_exit
> #
>
> We'll see the two BPF programs that augmented_raw_syscalls.o puts in
> place, one attached to the raw_syscalls:sys_enter and another to the
> raw_syscalls:sys_exit tracepoints, as expected.
>
> Now we can finally do, from the command line, annotation for one of
> those two symbols, with the original BPF program source coude intermixed
> with the disassembled JITed code:
>
> # perf annotate --stdio2 bpf_prog_819967866022f1e1_sys_enter
>
> Samples: 950 of event 'cycles:ppp', 4000 Hz, Event count (approx.): 553756947, [percent: local period]
> bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
> Percent int sys_enter(struct syscall_enter_args *args)
> 53.41 push %rbp
>
> 0.63 mov %rsp,%rbp
> 0.31 sub $0x170,%rsp
> 1.93 sub $0x28,%rbp
> 7.02 mov %rbx,0x0(%rbp)
> 3.20 mov %r13,0x8(%rbp)
> 1.07 mov %r14,0x10(%rbp)
> 0.61 mov %r15,0x18(%rbp)
> 0.11 xor %eax,%eax
> 1.29 mov %rax,0x20(%rbp)
> 0.11 mov %rdi,%rbx
> return bpf_get_current_pid_tgid();
> 2.02 → callq *ffffffffda6776d9
> 2.76 mov %eax,-0x148(%rbp)
> mov %rbp,%rsi
> int sys_enter(struct syscall_enter_args *args)
> add $0xfffffffffffffeb8,%rsi
> return bpf_map_lookup_elem(pids, &pid) != NULL;
> movabs $0xffff975ac2607800,%rdi
>
> 1.26 → callq *ffffffffda6789e9
> cmp $0x0,%rax
> 2.43 → je 0
> add $0x38,%rax
> 0.21 xor %r13d,%r13d
> if (pid_filter__has(&pids_filtered, getpid()))
> 0.81 cmp $0x0,%rax
> → jne 0
> mov %rbp,%rdi
> probe_read(&augmented_args.args, sizeof(augmented_args.args), args);
> 2.22 add $0xfffffffffffffeb8,%rdi
> 0.11 mov $0x40,%esi
> 0.32 mov %rbx,%rdx
> 2.74 → callq *ffffffffda658409
> syscall = bpf_map_lookup_elem(&syscalls, &augmented_args.args.syscall_nr);
> 0.22 mov %rbp,%rsi
> 1.69 add $0xfffffffffffffec0,%rsi
> syscall = bpf_map_lookup_elem(&syscalls, &augmented_args.args.syscall_nr);
> movabs $0xffff975bfcd36000,%rdi
>
> add $0xd0,%rdi
> 0.21 mov 0x0(%rsi),%eax
> 0.93 cmp $0x200,%rax
> → jae 0
> 0.10 shl $0x3,%rax
>
> 0.11 add %rdi,%rax
> 0.11 → jmp 0
> xor %eax,%eax
> if (syscall == NULL || !syscall->enabled)
> 1.07 cmp $0x0,%rax
> → je 0
> if (syscall == NULL || !syscall->enabled)
> 6.57 movzbq 0x0(%rax),%rdi
>
> if (syscall == NULL || !syscall->enabled)
> cmp $0x0,%rdi
> 0.95 → je 0
> mov $0x40,%r8d
> switch (augmented_args.args.syscall_nr) {
> mov -0x140(%rbp),%rdi
> switch (augmented_args.args.syscall_nr) {
> cmp $0x2,%rdi
> → je 0
> cmp $0x101,%rdi
> → je 0
> cmp $0x15,%rdi
> → jne 0
> case SYS_OPEN: filename_arg = (const void *)args->args[0];
> mov 0x10(%rbx),%rdx
> → jmp 0
> case SYS_OPENAT: filename_arg = (const void *)args->args[1];
> mov 0x18(%rbx),%rdx
> if (filename_arg != NULL) {
> cmp $0x0,%rdx
> → je 0
> xor %edi,%edi
> augmented_args.filename.reserved = 0;
> mov %edi,-0x104(%rbp)
> augmented_args.filename.size = probe_read_str(&augmented_args.filename.value,
> mov %rbp,%rdi
> add $0xffffffffffffff00,%rdi
> augmented_args.filename.size = probe_read_str(&augmented_args.filename.value,
> mov $0x100,%esi
> → callq *ffffffffda658499
> mov $0x148,%r8d
> augmented_args.filename.size = probe_read_str(&augmented_args.filename.value,
> mov %eax,-0x108(%rbp)
> augmented_args.filename.size = probe_read_str(&augmented_args.filename.value,
> mov %rax,%rdi
> shl $0x20,%rdi
>
> shr $0x20,%rdi
>
> if (augmented_args.filename.size < sizeof(augmented_args.filename.value)) {
> cmp $0xff,%rdi
> → ja 0
> len -= sizeof(augmented_args.filename.value) - augmented_args.filename.size;
> add $0x48,%rax
> len &= sizeof(augmented_args.filename.value) - 1;
> and $0xff,%rax
> mov %rax,%r8
> mov %rbp,%rcx
> return perf_event_output(args, &__augmented_syscalls__, BPF_F_CURRENT_CPU, &augmented_args, len);
> add $0xfffffffffffffeb8,%rcx
> mov %rbx,%rdi
> movabs $0xffff975fbd72d800,%rsi
>
> mov $0xffffffff,%edx
> → callq *ffffffffda658ad9
> mov %rax,%r13
> }
> mov %r13,%rax
> 0.72 mov 0x0(%rbp),%rbx
> mov 0x8(%rbp),%r13
> 1.16 mov 0x10(%rbp),%r14
> 0.10 mov 0x18(%rbp),%r15
> 0.42 add $0x28,%rbp
> 0.54 leaveq
> 0.54 ← retq
> #
>
> Please see 'man perf-config' to see how to control what should be seen,
> via ~/.perfconfig [annotate] section, for instance, one can suppress the
> source code and see just the disassembly, etc.
>
> Alternatively, use the TUI bu just using 'perf annotate', press
> '/bpf_prog' to see the bpf symbols, press enter and do the interactive
> annotation, which allows for dumping to a file after selecting the
> the various output tunables, for instance, the above without source code
> intermixed, plus showing all the instruction offsets:
>
> # perf annotate bpf_prog_819967866022f1e1_sys_enter
>
> Then press: 's' to hide the source code + 'O' twice to show all
> instruction offsets, then 'P' to print to the
> bpf_prog_819967866022f1e1_sys_enter.annotation file, which will have:
>
> # cat bpf_prog_819967866022f1e1_sys_enter.annotation
> bpf_prog_819967866022f1e1_sys_enter() bpf_prog_819967866022f1e1_sys_enter
> Event: cycles:ppp
>
> 53.41 0: push %rbp
>
> 0.63 1: mov %rsp,%rbp
> 0.31 4: sub $0x170,%rsp
> 1.93 b: sub $0x28,%rbp
> 7.02 f: mov %rbx,0x0(%rbp)
> 3.20 13: mov %r13,0x8(%rbp)
> 1.07 17: mov %r14,0x10(%rbp)
> 0.61 1b: mov %r15,0x18(%rbp)
> 0.11 1f: xor %eax,%eax
> 1.29 21: mov %rax,0x20(%rbp)
> 0.11 25: mov %rdi,%rbx
> 2.02 28: → callq *ffffffffda6776d9
> 2.76 2d: mov %eax,-0x148(%rbp)
> 33: mov %rbp,%rsi
> 36: add $0xfffffffffffffeb8,%rsi
> 3d: movabs $0xffff975ac2607800,%rdi
>
> 1.26 47: → callq *ffffffffda6789e9
> 4c: cmp $0x0,%rax
> 2.43 50: → je 0
> 52: add $0x38,%rax
> 0.21 56: xor %r13d,%r13d
> 0.81 59: cmp $0x0,%rax
> 5d: → jne 0
> 63: mov %rbp,%rdi
> 2.22 66: add $0xfffffffffffffeb8,%rdi
> 0.11 6d: mov $0x40,%esi
> 0.32 72: mov %rbx,%rdx
> 2.74 75: → callq *ffffffffda658409
> 0.22 7a: mov %rbp,%rsi
> 1.69 7d: add $0xfffffffffffffec0,%rsi
> 84: movabs $0xffff975bfcd36000,%rdi
>
> 8e: add $0xd0,%rdi
> 0.21 95: mov 0x0(%rsi),%eax
> 0.93 98: cmp $0x200,%rax
> 9f: → jae 0
> 0.10 a1: shl $0x3,%rax
>
> 0.11 a5: add %rdi,%rax
> 0.11 a8: → jmp 0
> aa: xor %eax,%eax
> 1.07 ac: cmp $0x0,%rax
> b0: → je 0
> 6.57 b6: movzbq 0x0(%rax),%rdi
>
> bb: cmp $0x0,%rdi
> 0.95 bf: → je 0
> c5: mov $0x40,%r8d
> cb: mov -0x140(%rbp),%rdi
> d2: cmp $0x2,%rdi
> d6: → je 0
> d8: cmp $0x101,%rdi
> df: → je 0
> e1: cmp $0x15,%rdi
> e5: → jne 0
> e7: mov 0x10(%rbx),%rdx
> eb: → jmp 0
> ed: mov 0x18(%rbx),%rdx
> f1: cmp $0x0,%rdx
> f5: → je 0
> f7: xor %edi,%edi
> f9: mov %edi,-0x104(%rbp)
> ff: mov %rbp,%rdi
> 102: add $0xffffffffffffff00,%rdi
> 109: mov $0x100,%esi
> 10e: → callq *ffffffffda658499
> 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 0
> 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 $0xffff975fbd72d800,%rsi
>
> 157: mov $0xffffffff,%edx
> 15c: → callq *ffffffffda658ad9
> 161: mov %rax,%r13
> 164: mov %r13,%rax
> 0.72 167: mov 0x0(%rbp),%rbx
> 16b: mov 0x8(%rbp),%r13
> 1.16 16f: mov 0x10(%rbp),%r14
> 0.10 173: mov 0x18(%rbp),%r15
> 0.42 177: add $0x28,%rbp
> 0.54 17b: leaveq
> 0.54 17c: ← retq
>
> Another cool way to test all this is to symple use 'perf top' look for
> those symbols, go there and press enter, annotate it live :-)
>
> Signed-off-by: Song Liu <songliubraving@fb.com>
> Reviewed-by: Jiri Olsa <jolsa@kernel.org>
> Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> Cc: Alexei Starovoitov <ast@kernel.org>
> Cc: Daniel Borkmann <daniel@iogearbox.net>
> Cc: Namhyung Kim <namhyung@kernel.org>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Stanislav Fomichev <sdf@google.com>
> Link: http://lkml.kernel.org/r/20190312053051.2690567-13-songliubraving@fb.com
> Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

\
 
 \ /
  Last update: 2019-03-19 17:52    [W:0.507 / U:0.092 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site