Re: perf report warnings on tracepoint events hidden by ui

From: Steven Rostedt
Date: Thu Apr 27 2017 - 21:42:06 EST


On Thu, 27 Apr 2017 19:31:12 -0500
David Carrillo-Cisneros <davidcc@xxxxxxxxxx> 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