Re: perf report warnings on tracepoint events hidden by ui

[Steven Rostedt <rostedt@goodmis.org>]

On Thu, 27 Apr 2017 19:31:12 -0500
David Carrillo-Cisneros <davidcc@google.com> wrote:

> When processing tracepoint events, perf report outputs warnings about
> field not founds. The warnings are usually hidden by perf report UI
> and appear when using the --stdio option. e.g.
> 
>   $ perf record -e syscalls:sys_enter_mmap some_load
> 
>   $ perf report --stdio
> 
>   Warning: [syscalls:sys_enter_mmap] eval_num_arg: field addr not found
>   Warning: [syscalls:sys_enter_mmap] eval_num_arg: field len not found
>   Warning: [syscalls:sys_enter_mmap] eval_num_arg: field prot not found
>   Warning: [syscalls:sys_enter_mmap] eval_num_arg: field flags not found
>   Warning: [syscalls:sys_enter_mmap] eval_num_arg: field fd not found
>   Warning: [syscalls:sys_enter_mmap] eval_num_arg: field off not found
>   Warning: [syscalls:sys_enter_mmap] eval_num_arg: field addr not found
>   Warning: [syscalls:sys_enter_mmap] eval_num_arg: field len not found
>   Warning: [syscalls:sys_enter_mmap] eval_num_arg: field prot not found
>   Warning: [syscalls:sys_enter_mmap] eval_num_arg: field flags not found
>   Warning: [syscalls:sys_enter_mmap] eval_num_arg: field fd not found
>   Warning: [syscalls:sys_enter_mmap] eval_num_arg: field off not found
> 
> I bisected the warnings to:
>   commit d49dadea78624 ("perf tools: Make 'trace' or 'trace_fields'
> sort key default for tracepoint events").
> 
> that introduced sorting by trace. The event's format in my example is:
> 
>   $ cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_socket/format

It's not sys_enter_socket, it's sys_enter_mmap.

> 
>   name: sys_enter_socket
>   ID: 1850
>   format:
>           field:unsigned short common_type;       offset:0;
> size:2; signed:0;
>           field:unsigned char common_flags;       offset:2;
> size:1; signed:0;
>           field:unsigned char common_preempt_count;       offset:3;
>    size:1; signed:0;
>           field:int common_pid;   offset:4;       size:4; signed:1;
> 
>   print fmt: "family: 0x%08lx, type: 0x%08lx, protocol: 0x%08lx",
> ((unsigned long)(REC->family)), ((unsigned long)(REC->type)),
> ((unsigned long)(REC->protocol))
> 
> 
> An appears to be correctly parsed by event_read_print in
> tools/lib/tracevent/event-parse.c . Has anyone seen this before?

What kernel are you running?

I just built and booted v4.11-rc8 with a v4.11-rc8 perf:

+------------------+

[root@bxtest ~]# perf record -e syscalls:sys_enter_mmap /work/c/hackbench 10
Time: 4.896
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.049 MB perf.data (6 samples) ]
[root@bxtest ~]# perf report --stdio
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 6  of event 'syscalls:sys_enter_mmap'
# Event count (approx.): 6
#
# Overhead  Trace output                                                                                                       
# ........  ...................................................................................................................
#
    33.33%  addr: 0x00000000, len: 0x00002000, prot: 0x00000003, flags: 0x00000022, fd: 0xffffffffffffffff, off: 0x00000000
    16.67%  addr: 0x00000000, len: 0x00023bec, prot: 0x00000001, flags: 0x00000002, fd: 0x00000004, off: 0x00000000
    16.67%  addr: 0x00000000, len: 0x003c5960, prot: 0x00000005, flags: 0x00000802, fd: 0x00000004, off: 0x00000000
    16.67%  addr: 0x7f9db5be2000, len: 0x00006000, prot: 0x00000003, flags: 0x00000812, fd: 0x00000004, off: 0x001bc000
    16.67%  addr: 0x7f9db5be8000, len: 0x00003960, prot: 0x00000003, flags: 0x00000032, fd: 0xffffffffffffffff, off: 0x00000000


#
# (Tip: If you have debuginfo enabled, try: perf report -s sym,srcline)
#
[root@bxtest ~]# perf --version
perf version 4.11.rc8.g5a7ad11


+------------------+

Seems fine to me.

-- Steve