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

[Arnaldo Carvalho de Melo <acme@kernel.org>]

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.

- Arnaldo