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

Em Tue, Jan 22, 2019 at 12:31:17PM -0200, Arnaldo Carvalho de Melo escreveu:

Em Tue, Jan 22, 2019 at 12:13:20PM -0200, Arnaldo Carvalho de Melo escreveu:

quoted

Em Fri, Jan 18, 2019 at 11:46:55AM -0300, Arnaldo Carvalho de Melo escreveu:

quoted

Em Thu, Jan 17, 2019 at 08:15:19AM -0800, Song Liu escreveu:

quoted

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.

So it fails for tracepoints with plain 'perf record':

[root@quaco tmp]# perf record -e sched:sched* sleep 1
[ perf record: Woken up 29 times to write data ]
0x6658 [0x138]: failed to process type: 17
[ perf record: Captured and wrote 0.029 MB perf.data ]
[root@quaco tmp]# perf script
0x6658 [0x138]: failed to process type: 17
[root@quaco tmp]#

[ perf record: Woken up 1 times to write data ]

Breakpoint 1, reader__process_events (rd=0x7ffffffe4160, session=0xab66a0, prog=0x7ffffffe4180) at util/session.c:1911
1911			pr_err("%#" PRIx64 " [%#x]: failed to process type: %d\n",
Missing separate debuginfos, use: dnf debuginfo-install bzip2-libs-1.0.6-28.fc29.x86_64 elfutils-libelf-0.174-5.fc29.x86_64 elfutils-libs-0.174-5.fc29.x86_64 glib2-2.58.2-1.fc29.x86_64 libbabeltrace-1.5.6-1.fc29.x86_64 libunwind-1.2.1-6.fc29.x86_64 libuuid-2.32.1-1.fc29.x86_64 libxcrypt-4.4.2-3.fc29.x86_64 numactl-libs-2.0.12-1.fc29.x86_64 openssl-libs-1.1.1a-1.fc29.x86_64 pcre-8.42-6.fc29.x86_64 perl-libs-5.28.1-427.fc29.x86_64 popt-1.16-15.fc29.x86_64 python2-libs-2.7.15-11.fc29.x86_64 slang-2.3.2-4.fc29.x86_64 xz-libs-5.2.4-3.fc29.x86_64
(gdb) bt
#0  reader__process_events (rd=0x7ffffffe4160, session=0xab66a0, prog=0x7ffffffe4180) at util/session.c:1911
#1  0x0000000000540deb in __perf_session__process_events (session=0xab66a0) at util/session.c:1955
#2  0x0000000000540f1c in perf_session__process_events (session=0xab66a0) at util/session.c:1988
#3  0x0000000000445feb in process_buildids (rec=0x9202a0 <record>) at builtin-record.c:689
#4  0x0000000000446597 in record__finish_output (rec=0x9202a0 <record>) at builtin-record.c:846
#5  0x0000000000447b8c in __cmd_record (rec=0x9202a0 <record>, argc=2, argv=0xab4720) at builtin-record.c:1429
#6  0x0000000000448d64 in cmd_record (argc=2, argv=0xab4720) at builtin-record.c:2153
#7  0x00000000004406dd in __cmd_record (argc=3, argv=0x7fffffffdb30) at builtin-sched.c:3339
#8  0x00000000004411ff in cmd_sched (argc=3, argv=0x7fffffffdb30) at builtin-sched.c:3486
#9  0x00000000004d46e3 in run_builtin (p=0x932c50 <commands+432>, argc=4, argv=0x7fffffffdb30) at perf.c:302
#10 0x00000000004d4950 in handle_internal_command (argc=4, argv=0x7fffffffdb30) at perf.c:354
#11 0x00000000004d4a9f in run_argv (argcp=0x7fffffffd98c, argv=0x7fffffffd980) at perf.c:398
#12 0x00000000004d4e0b in main (argc=4, argv=0x7fffffffdb30) at perf.c:520
(gdb)

[root@quaco tmp]# perf c2c record
^C[ perf record: Woken up 1 times to write data ]
0x5698 [0x138]: failed to process type: 17
[ perf record: Captured and wrote 7.110 MB perf.data ]

[root@quaco tmp]# perf kmem record
^C[ perf record: Woken up 1 times to write data ]
0x5998 [0x138]: failed to process type: 17
[ perf record: Captured and wrote 1.470 MB perf.data ]

[root@quaco tmp]#