perf report warnings on tracepoint events hidden by ui

perf report warnings on tracepoint events hidden by ui

[David Carrillo-Cisneros]

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

  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?

Thanks,
David

Re: perf report warnings on tracepoint events hidden by ui

[Steven Rostedt]

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

Re: perf report warnings on tracepoint events hidden by ui

[David Ahern]

On 4/27/17 7:41 PM, Steven Rostedt wrote:
> 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

'-e syscalls' vs raw_syscalls suggests an older kernel -- like RHEL6.


See the note I put into tools/perf/builtin-trace.c:

static struct perf_evsel *perf_evsel__syscall_newtp(const char
*direction, void *handler)
{
        struct perf_evsel *evsel = perf_evsel__newtp("raw_syscalls",
direction);

        /* older kernel (e.g., RHEL6) use syscalls:{enter,exit} */
        if (IS_ERR(evsel))
                evsel = perf_evsel__newtp("syscalls", direction);


Are you running top of tree perf on RHEL6?

Re: perf report warnings on tracepoint events hidden by ui

[Steven Rostedt]

On Thu, 27 Apr 2017 20:13:43 -0600
David Ahern <dsahern@gmail.com> wrote:

> On 4/27/17 7:41 PM, Steven Rostedt wrote:
> > 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  
> 
> '-e syscalls' vs raw_syscalls suggests an older kernel -- like RHEL6.

New kernels have both syscalls and raw_syscalls. The raw_syscalls are
the true tracepoints that the syscalls use. His option works on
4.11-rc8.

-- Steve


> 
> 
> See the note I put into tools/perf/builtin-trace.c:
> 
> static struct perf_evsel *perf_evsel__syscall_newtp(const char
> *direction, void *handler)
> {
>         struct perf_evsel *evsel = perf_evsel__newtp("raw_syscalls",
> direction);
> 
>         /* older kernel (e.g., RHEL6) use syscalls:{enter,exit} */
>         if (IS_ERR(evsel))
>                 evsel = perf_evsel__newtp("syscalls", direction);
> 
> 
> Are you running top of tree perf on RHEL6?

Re: perf report warnings on tracepoint events hidden by ui

[David Ahern]

On 4/27/17 8:49 PM, Steven Rostedt wrote:
> On Thu, 27 Apr 2017 20:13:43 -0600
> David Ahern <dsahern@gmail.com> wrote:
> 
>> On 4/27/17 7:41 PM, Steven Rostedt wrote:
>>> 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  
>>
>> '-e syscalls' vs raw_syscalls suggests an older kernel -- like RHEL6.
> 
> New kernels have both syscalls and raw_syscalls. The raw_syscalls are
> the true tracepoints that the syscalls use. His option works on
> 4.11-rc8.


What's old is new again?

root@kenny-jessie4:~# uname -a
Linux kenny-jessie4 4.11.0-rc8+ #258 SMP Thu Apr 27 08:36:06 PDT 2017
x86_64 GNU/Linux

root@kenny-jessie4:~# perf list | grep syscalls
  raw_syscalls:sys_enter                             [Tracepoint event]
  raw_syscalls:sys_exit                              [Tracepoint event]


Is an option needed to enable syscalls vs raw_syscalls?

Re: perf report warnings on tracepoint events hidden by ui

[Steven Rostedt]

On Thu, 27 Apr 2017 20:51:28 -0600
David Ahern <dsahern@gmail.com> wrote:

> On 4/27/17 8:49 PM, Steven Rostedt wrote:
> > On Thu, 27 Apr 2017 20:13:43 -0600
> > David Ahern <dsahern@gmail.com> wrote:
> >   
> >> On 4/27/17 7:41 PM, Steven Rostedt wrote:  
> >>> 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    
> >>
> >> '-e syscalls' vs raw_syscalls suggests an older kernel -- like RHEL6.  
> > 
> > New kernels have both syscalls and raw_syscalls. The raw_syscalls are
> > the true tracepoints that the syscalls use. His option works on
> > 4.11-rc8.  
> 
> 
> What's old is new again?
> 
> root@kenny-jessie4:~# uname -a
> Linux kenny-jessie4 4.11.0-rc8+ #258 SMP Thu Apr 27 08:36:06 PDT 2017
> x86_64 GNU/Linux
> 
> root@kenny-jessie4:~# perf list | grep syscalls
>   raw_syscalls:sys_enter                             [Tracepoint event]
>   raw_syscalls:sys_exit                              [Tracepoint event]
> 
> 
> Is an option needed to enable syscalls vs raw_syscalls?

Yep!

CONFIG_FTRACE_SYSCALLS=y

-- Steve

Re: perf report warnings on tracepoint events hidden by ui

[Namhyung Kim]

Hi,

On Fri, Apr 28, 2017 at 9:31 AM, 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.

Yep, currently perf report TUI hides warnings since there's no space
to show them.

>
>   $ 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
>
>   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?

But I don't see any warning when I run it with --stdio.  Could you
show me the format file of sys_enter_mmap?


Thanks,
Namhyung

Re: perf report warnings on tracepoint events hidden by ui

[David Carrillo-Cisneros]

>
> But I don't see any warning when I run it with --stdio.  Could you
> show me the format file of sys_enter_mmap?

I found the problem. The kernel version I was testing on fails to
initialize some fields in the tracepoint structure, so my format
looked like:

# cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_mmap/format
name: sys_enter_mmap
ID: 144
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: "addr: 0x%08lx, len: 0x%08lx, prot: 0x%08lx, flags:
0x%08lx, fd: 0x%08lx, off: 0x%08lx", ((unsigned long)(REC->addr)),
((unsigned long)(REC->len)), ((unsigned long)(REC->prot)), ((unsigned
long)(REC->flags)), ((unsigned long)(REC->fd)), ((unsigned
long)(REC->off))

rather than:

name: sys_enter_mmap
ID: 111
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;

        field:int nr;   offset:8;       size:4; signed:1;
        field:unsigned long addr;       offset:16;      size:8; signed:0;
        field:unsigned long len;        offset:24;      size:8; signed:0;
        field:unsigned long prot;       offset:32;      size:8; signed:0;
        field:unsigned long flags;      offset:40;      size:8; signed:0;
        field:unsigned long fd; offset:48;      size:8; signed:0;
        field:unsigned long off;        offset:56;      size:8; signed:0;

print fmt: "addr: 0x%08lx, len: 0x%08lx, prot: 0x%08lx, flags:
0x%08lx, fd: 0x%08lx, off: 0x%08lx", ((unsigned long)(REC->addr)),
((unsigned long)(REC->len)), ((unsigned long)(REC->prot)), ((unsigned
long)(REC->flags)), ((unsigned long)(REC->fd)), ((unsigned
long)(REC->off))


Upstream is all good. It was my oversight not testing there first.

Thanks,
David

Re: perf report warnings on tracepoint events hidden by ui

[David Carrillo-Cisneros]

>>
>> 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:

I was running an internal version. I found the bug in an internal
commit. It's true that upstream is all good.

Thank you for checking,
David