Re: [PATCH v11 perf, bpf-next 7/9] perf tools: synthesize PERF_RECORD_* for loaded BPF programs

[Jiri Olsa <jolsa@redhat.com>]

On Tue, Jan 22, 2019 at 12:58:05PM -0200, Arnaldo Carvalho de Melo wrote:
> Em Tue, Jan 22, 2019 at 03:51:19PM +0100, Jiri Olsa escreveu:
> > On Tue, Jan 22, 2019 at 12:31:17PM -0200, Arnaldo Carvalho de Melo wrote:
> > > Em Tue, Jan 22, 2019 at 12:13:20PM -0200, Arnaldo Carvalho de Melo escreveu:
> > > > Em Fri, Jan 18, 2019 at 11:46:55AM -0300, Arnaldo Carvalho de Melo escreveu:
> > > > > Em Thu, Jan 17, 2019 at 08:15:19AM -0800, Song Liu escreveu:
> > > > > > This patch synthesize PERF_RECORD_KSYMBOL and PERF_RECORD_BPF_EVENT for
> > > > > > BPF programs loaded before perf-record. This is achieved by gathering
> > > > > > information about all BPF programs via sys_bpf.
> > > > > 
> > > > > Ditto
> > > > 
> > > > This is breaking 'perf sched', see below, the fix seems trivial:
> > > > 
> > > > [root@quaco ~]# perf sched record -a sleep 2
> > > > [ perf record: Woken up 1 times to write data ]
> > > > 0x5b60 [0x138]: failed to process type: 17
> > > > [ perf record: Captured and wrote 1.539 MB perf.data ]
> > > > [root@quaco ~]# perf sched lat
> > > > 0x5b60 [0x138]: failed to process type: 17
> > > > Failed to process events, error -22
> > > > [root@quaco ~]#
> > > 
> > > So:
> > > 
> > >    perf_session__process_event (event->header.type = 17 (PERF_RECORD_KSYMBOL)
> > >      if (tool->ordered_events)
> > >        ret = perf_evlist__parse_sample_timestamp(evlist, event, &timestamp);
> > >        if (ret && ret != -1)
> > >             return ret;
> > > 
> > > So it returns here with -EFAULT, i.e. this is failing:
> > > 
> > > int perf_evlist__parse_sample_timestamp(struct perf_evlist *evlist,
> > >                                         union perf_event *event,
> > >                                         u64 *timestamp)
> > > {
> > >         struct perf_evsel *evsel = perf_evlist__event2evsel(evlist, event);
> > > 
> > >         if (!evsel)
> > >                 return -EFAULT;
> > >         return perf_evsel__parse_sample_timestamp(evsel, event, timestamp);
> > > }
> > > 
> > > It isn't mapping the event ID it finds back to an evsel.. Jiri, ideas?
> > > 
> > > This is happening so far only for 'perf sched', perf record with two
> > > events works.
> > 
> > I saw also perf mem failing because of this.. will check
> 
> Right, seems something with the synthesizing of existing bpf progs,
> which always there are some nowadays, for instance, on this fedora29
> system:
> 
> [root@quaco tmp]# bpftool prog
> 13: cgroup_skb  tag 7be49e3934a125ba  gpl
> 	loaded_at 2019-01-21T13:30:27-0200  uid 0
> 	xlated 296B  jited 229B  memlock 4096B  map_ids 13,14
> 14: cgroup_skb  tag 2a142ef67aaad174  gpl
> 	loaded_at 2019-01-21T13:30:27-0200  uid 0
> 	xlated 296B  jited 229B  memlock 4096B  map_ids 13,14
> 15: cgroup_skb  tag 7be49e3934a125ba  gpl
> 	loaded_at 2019-01-21T13:30:27-0200  uid 0
> 	xlated 296B  jited 229B  memlock 4096B  map_ids 15,16
> 16: cgroup_skb  tag 2a142ef67aaad174  gpl
> 	loaded_at 2019-01-21T13:30:27-0200  uid 0
> 	xlated 296B  jited 229B  memlock 4096B  map_ids 15,16
> 17: cgroup_skb  tag 7be49e3934a125ba  gpl
> 	loaded_at 2019-01-21T13:30:29-0200  uid 0
> 	xlated 296B  jited 229B  memlock 4096B  map_ids 17,18
> 18: cgroup_skb  tag 2a142ef67aaad174  gpl
> 	loaded_at 2019-01-21T13:30:29-0200  uid 0
> 	xlated 296B  jited 229B  memlock 4096B  map_ids 17,18
> 21: cgroup_skb  tag 7be49e3934a125ba  gpl
> 	loaded_at 2019-01-21T13:30:29-0200  uid 0
> 	xlated 296B  jited 229B  memlock 4096B  map_ids 21,22
> 22: cgroup_skb  tag 2a142ef67aaad174  gpl
> 	loaded_at 2019-01-21T13:30:29-0200  uid 0
> 	xlated 296B  jited 229B  memlock 4096B  map_ids 21,22
> [root@quaco tmp]#
> 
> When with a bunch of tracepoints, that is what 'perf mem', 'perf kmem',
> 'perf sched', etc does, it ends up failing here:
> 
>                     ret = perf_evlist__parse_sample_timestamp(evlist, event, &timestamp);
> 
> So it is not passed to 
> 
>                    ret = perf_session__queue_event(session, event, timestamp, file_offset);
> 
> in perf_session__process_event, this happens right when processing
> buildids in 'perf record', and also in 'perf report', so that is
> something badly synthesized that hits perf.data for PERF_RECORD_KSYMBOL.

it's reproducible with simple:
  perf record -e cycles,instructions ls

as you said on irc, it's the machine->id_hdr_size size missing
there's one more glitch, attached patch fixes that for me
you can't use sizeof(struct ksymbol_event), because it includes
the name as well.. which screws the size

but I don't know that code that much.. might be still something
missing

jirka


---
diff --git a/tools/perf/util/bpf-event.c b/tools/perf/util/bpf-event.c
index 01e1dc1bb7fb..d86b61cc635f 100644
--- a/tools/perf/util/bpf-event.c
+++ b/tools/perf/util/bpf-event.c
@@ -7,6 +7,7 @@
 #include "bpf-event.h"
 #include "debug.h"
 #include "symbol.h"
+#include "machine.h"
 
 #define ptr_to_u64(ptr)    ((__u64)(unsigned long)(ptr))
 
@@ -149,7 +150,7 @@ static int perf_event__synthesize_one_bpf_prog(struct perf_tool *tool,
 		*ksymbol_event = (struct ksymbol_event){
 			.header = {
 				.type = PERF_RECORD_KSYMBOL,
-				.size = sizeof(struct ksymbol_event),
+				.size = offsetof(struct ksymbol_event, name) + machine->id_hdr_size,
 			},
 			.addr = prog_addrs[i],
 			.len = prog_lens[i],