* perf report warnings on tracepoint events hidden by ui
@ 2017-04-28 0:31 David Carrillo-Cisneros
2017-04-28 1:41 ` Steven Rostedt
2017-04-28 3:07 ` Namhyung Kim
0 siblings, 2 replies; 9+ messages in thread
From: David Carrillo-Cisneros @ 2017-04-28 0:31 UTC (permalink / raw)
To: Jiri Olsa, Namhyung Kim, Arnaldo Carvalho de Melo, Andi Kleen,
David Ahern, Frederic Weisbecker, Peter Zijlstra, Steven Rostedt,
Wang Nan, linux-kernel, Stephane Eranian
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
^ permalink raw reply [flat|nested] 9+ messages in thread* Re: perf report warnings on tracepoint events hidden by ui 2017-04-28 0:31 perf report warnings on tracepoint events hidden by ui David Carrillo-Cisneros @ 2017-04-28 1:41 ` Steven Rostedt 2017-04-28 2:13 ` David Ahern 2017-04-30 17:34 ` David Carrillo-Cisneros 2017-04-28 3:07 ` Namhyung Kim 1 sibling, 2 replies; 9+ messages in thread From: Steven Rostedt @ 2017-04-28 1:41 UTC (permalink / raw) To: David Carrillo-Cisneros Cc: Jiri Olsa, Namhyung Kim, Arnaldo Carvalho de Melo, Andi Kleen, David Ahern, Frederic Weisbecker, Peter Zijlstra, Wang Nan, linux-kernel, Stephane Eranian 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: perf report warnings on tracepoint events hidden by ui 2017-04-28 1:41 ` Steven Rostedt @ 2017-04-28 2:13 ` David Ahern 2017-04-28 2:49 ` Steven Rostedt 2017-04-30 17:34 ` David Carrillo-Cisneros 1 sibling, 1 reply; 9+ messages in thread From: David Ahern @ 2017-04-28 2:13 UTC (permalink / raw) To: Steven Rostedt, David Carrillo-Cisneros Cc: Jiri Olsa, Namhyung Kim, Arnaldo Carvalho de Melo, Andi Kleen, Frederic Weisbecker, Peter Zijlstra, Wang Nan, linux-kernel, Stephane Eranian 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? ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: perf report warnings on tracepoint events hidden by ui 2017-04-28 2:13 ` David Ahern @ 2017-04-28 2:49 ` Steven Rostedt 2017-04-28 2:51 ` David Ahern 0 siblings, 1 reply; 9+ messages in thread From: Steven Rostedt @ 2017-04-28 2:49 UTC (permalink / raw) To: David Ahern Cc: David Carrillo-Cisneros, Jiri Olsa, Namhyung Kim, Arnaldo Carvalho de Melo, Andi Kleen, Frederic Weisbecker, Peter Zijlstra, Wang Nan, linux-kernel, Stephane Eranian 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? ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: perf report warnings on tracepoint events hidden by ui 2017-04-28 2:49 ` Steven Rostedt @ 2017-04-28 2:51 ` David Ahern 2017-04-28 2:54 ` Steven Rostedt 0 siblings, 1 reply; 9+ messages in thread From: David Ahern @ 2017-04-28 2:51 UTC (permalink / raw) To: Steven Rostedt Cc: David Carrillo-Cisneros, Jiri Olsa, Namhyung Kim, Arnaldo Carvalho de Melo, Andi Kleen, Frederic Weisbecker, Peter Zijlstra, Wang Nan, linux-kernel, Stephane Eranian 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? ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: perf report warnings on tracepoint events hidden by ui 2017-04-28 2:51 ` David Ahern @ 2017-04-28 2:54 ` Steven Rostedt 0 siblings, 0 replies; 9+ messages in thread From: Steven Rostedt @ 2017-04-28 2:54 UTC (permalink / raw) To: David Ahern Cc: David Carrillo-Cisneros, Jiri Olsa, Namhyung Kim, Arnaldo Carvalho de Melo, Andi Kleen, Frederic Weisbecker, Peter Zijlstra, Wang Nan, linux-kernel, Stephane Eranian 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: perf report warnings on tracepoint events hidden by ui 2017-04-28 1:41 ` Steven Rostedt 2017-04-28 2:13 ` David Ahern @ 2017-04-30 17:34 ` David Carrillo-Cisneros 1 sibling, 0 replies; 9+ messages in thread From: David Carrillo-Cisneros @ 2017-04-30 17:34 UTC (permalink / raw) To: Steven Rostedt Cc: Jiri Olsa, Namhyung Kim, Arnaldo Carvalho de Melo, Andi Kleen, David Ahern, Frederic Weisbecker, Peter Zijlstra, Wang Nan, linux-kernel, Stephane Eranian >> >> 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: perf report warnings on tracepoint events hidden by ui 2017-04-28 0:31 perf report warnings on tracepoint events hidden by ui David Carrillo-Cisneros 2017-04-28 1:41 ` Steven Rostedt @ 2017-04-28 3:07 ` Namhyung Kim 2017-04-30 17:32 ` David Carrillo-Cisneros 1 sibling, 1 reply; 9+ messages in thread From: Namhyung Kim @ 2017-04-28 3:07 UTC (permalink / raw) To: David Carrillo-Cisneros Cc: Jiri Olsa, Arnaldo Carvalho de Melo, Andi Kleen, David Ahern, Frederic Weisbecker, Peter Zijlstra, Steven Rostedt, Wang Nan, linux-kernel, Stephane Eranian 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: perf report warnings on tracepoint events hidden by ui 2017-04-28 3:07 ` Namhyung Kim @ 2017-04-30 17:32 ` David Carrillo-Cisneros 0 siblings, 0 replies; 9+ messages in thread From: David Carrillo-Cisneros @ 2017-04-30 17:32 UTC (permalink / raw) To: Namhyung Kim Cc: Jiri Olsa, Arnaldo Carvalho de Melo, Andi Kleen, David Ahern, Frederic Weisbecker, Peter Zijlstra, Steven Rostedt, Wang Nan, linux-kernel, Stephane Eranian > > 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 ^ permalink raw reply [flat|nested] 9+ messages in thread
end of thread, other threads:[~2017-04-30 17:35 UTC | newest] Thread overview: 9+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2017-04-28 0:31 perf report warnings on tracepoint events hidden by ui David Carrillo-Cisneros 2017-04-28 1:41 ` Steven Rostedt 2017-04-28 2:13 ` David Ahern 2017-04-28 2:49 ` Steven Rostedt 2017-04-28 2:51 ` David Ahern 2017-04-28 2:54 ` Steven Rostedt 2017-04-30 17:34 ` David Carrillo-Cisneros 2017-04-28 3:07 ` Namhyung Kim 2017-04-30 17:32 ` David Carrillo-Cisneros
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).