Message-ID: <9bfdc5a0-ed1d-40f6-8a72-6129e1587ca7@linaro.org>
Date: Tue, 12 Nov 2024 14:12:52 +0000
From: James Clark <james.clark@...aro.org>
To: Ian Rogers <irogers@...gle.com>, Leo Yan <leo.yan@....com>
Cc: Atish Patra <atishp@...osinc.com>, Namhyung Kim <namhyung@...nel.org>,
 Arnaldo Carvalho de Melo <acme@...nel.org>, linux-riscv@...ts.infradead.org,
 beeman@...osinc.com, Peter Zijlstra <peterz@...radead.org>,
 Ingo Molnar <mingo@...hat.com>, Mark Rutland <mark.rutland@....com>,
 Alexander Shishkin <alexander.shishkin@...ux.intel.com>,
 Jiri Olsa <jolsa@...nel.org>, Adrian Hunter <adrian.hunter@...el.com>,
 Kan Liang <kan.liang@...ux.intel.com>, Ze Gao <zegao2021@...il.com>,
 Weilin Wang <weilin.wang@...el.com>, Ben Gainey <ben.gainey@....com>,
 Dominique Martinet <asmadeus@...ewreck.org>, Junhao He
 <hejunhao3@...wei.com>, linux-perf-users@...r.kernel.org,
 linux-kernel@...r.kernel.org
Subject: Re: [PATCH v1 3/4] perf record: Skip don't fail for events that don't
 open



On 11/11/2024 5:00 pm, Ian Rogers wrote:
> On Mon, Nov 11, 2024 at 7:49 AM James Clark <james.clark@...aro.org> wrote:
>>
>>
>>
>> On 26/10/2024 1:17 pm, Ian Rogers wrote:
>>> Whilst for many tools it is an expected behavior that failure to open
>>> a perf event is a failure, ARM decided to name PMU events the same as
>>> legacy events and then failed to rename such events on a server uncore
>>> SLC PMU. As perf's default behavior when no PMU is specified is to
>>> open the event on all PMUs that advertise/"have" the event, this
>>> yielded failures when trying to make the priority of legacy and
>>> sysfs/json events uniform - something requested by RISC-V and ARM. A
>>> legacy event user on ARM hardware may find their event opened on an
>>> uncore PMU which for perf record will fail. Arnaldo suggested skipping
>>> such events which this patch implements. Rather than have the skipping
>>> conditional on running on ARM, the skipping is done on all
>>> architectures as such a fundamental behavioral difference could lead
>>> to problems with tools built/depending on perf.
>>>
>>> An example of perf record failing to open events on x86 is:
>>> ```
>>> $ perf record -e data_read,cycles,LLC-prefetch-read -a sleep 0.1
>>> Error:
>>> Failure to open event 'data_read' on PMU 'uncore_imc_free_running_0' which will be removed.
>>> The sys_perf_event_open() syscall returned with 22 (Invalid argument) for event (data_read).
>>> "dmesg | grep -i perf" may provide additional information.
>>>
>>> Error:
>>> Failure to open event 'data_read' on PMU 'uncore_imc_free_running_1' which will be removed.
>>> The sys_perf_event_open() syscall returned with 22 (Invalid argument) for event (data_read).
>>> "dmesg | grep -i perf" may provide additional information.
>>>
>>
>> This makes me wonder if this message was overly wordy to begin with.
>> This line is fine:
>>
>>    Failure to open event 'data_read' on PMU 'uncore_imc_free_running_0'
>>    which will be removed.
>>
>> The next bit about the syscall just repeats. The exit code could be
>> included on the previous line. And the dmesg bit is general advice that
>> could possibly be printed once at the end.
> 
> Thanks for the time spent investigating this!
> 
> I agree on this. I wonder if we should have short and long messages,
> or message+help like we do for parse events. One patch series like
> this is improving EBUSY:
> https://lore.kernel.org/lkml/20241106003007.2112584-1-ctshao@google.com/
> The issue with printing at the end is knowing where/when the end is.
> Printing once is easy enough.
> 
>>> Error:
>>> Failure to open event 'LLC-prefetch-read' on PMU 'cpu' which will be removed.
>>> The LLC-prefetch-read event is not supported.
>>> [ perf record: Woken up 1 times to write data ]
>>> [ perf record: Captured and wrote 2.188 MB perf.data (87 samples) ]
>>>
>>> $ perf report --stats
>>> Aggregated stats:
>>>                  TOTAL events:      17255
>>>                   MMAP events:        284  ( 1.6%)
>>>                   COMM events:       1961  (11.4%)
>>>                   EXIT events:          1  ( 0.0%)
>>>                   FORK events:       1960  (11.4%)
>>>                 SAMPLE events:         87  ( 0.5%)
>>>                  MMAP2 events:      12836  (74.4%)
>>>                KSYMBOL events:         83  ( 0.5%)
>>>              BPF_EVENT events:         36  ( 0.2%)
>>>         FINISHED_ROUND events:          2  ( 0.0%)
>>>               ID_INDEX events:          1  ( 0.0%)
>>>             THREAD_MAP events:          1  ( 0.0%)
>>>                CPU_MAP events:          1  ( 0.0%)
>>>              TIME_CONV events:          1  ( 0.0%)
>>>          FINISHED_INIT events:          1  ( 0.0%)
>>> cycles stats:
>>>                 SAMPLE events:         87
>>> ```
>>>
>>> Note, if all events fail to open then the data file will contain no
>>> samples. This is deliberate as at the point the events are opened
>>> there are other events, such as the dummy event for sideband data, and
>>> these events will succeed in opening even if the user specified ones
>>
>> Is a file with only sideband events useful? Is it possible to fail the
>> record command if the event doesn't open anywhere?
>>
>> I noticed this leads to some different behavior and a libperf warning
>> when you have paranoid=3:
>>
>>     $ perf record -e cycles -C 0 -- true
>>
>>     Error:
>>     Failure to open event 'cpu_atom/cycles/u' on PMU 'cpu_atom' which will
>>     be removed.
>>     ...
>>     Consider adjusting /proc/sys/kernel/perf_event_paranoid setting
>>     ...
>>     libperf: Miscounted nr_mmaps 0 vs 28
>>     WARNING: No sample_id_all support, falling back to unordered
>>     processing
>>     [ perf record: Woken up 1 times to write data ]
>>     [ perf record: Captured and wrote 0.021 MB perf.data ]
> 
> So paranoid=3 is a Debian extension that Peter Z doesn't agree with
> and so isn't enabled in regular kernels. So we're dealing with cycles,
> which we'd expect to open or fall-back to a software event like
> task-clock. It feels like things could happen better here but that's
> not necessarily the fault of this patch.
> 

paranoid=3 is a bit of a red-herring. I actually meant any paranoid 
value other than -1. The important part is "-C 0" because only root is 
allowed to open on a CPU. Or "-a" also causes the issue.

Previously you got the command failure and the hint about the paranoid 
value, but now you get the libperf error too and it still makes the file.

I still don't think a file with only sideband events is useful, I don't 
think there's even a commandline that you can run currently that results 
in that? You always need at least one event to open for it to succeed 
and I'm thinking we could keep that.

It would be nice to fix the libperf warning too because it's warning 
about something that was already warned about.

>>> don't. Having a mix of open and broken events leads to a problem of
>>> identifying different sources of events.
>>   >
>>
>> In my basic test I saw that the opened event was identified correctly in
>> perf report, unless you have an example that you encountered that we
>> should fix?
> 
> I didn't find any but we also don't tend to test failing to open
> events. I could imagine things failing in `perf test` on neoverse
> testing given the l3 advertising the cycles event.
> 
>> One place I saw an issue was with auxtrace events. If there's an event
>> name clash then you're likely to not be able to open the file afterwards
>> because the auxtrace code can't handle an event that didn't open. But I
>> don't know of any name clashes there (I just faked one for testing), and
>> maybe that could be fixed up later in the auxtrace code if there is ever
>> a real one.
>>
>> Other than the above it does seem to work ok.
> 
> Cool, can this be taken as a Tested-by?
> 

Yep, although with a caveat that I faked the second cycles PMU that 
wouldn't open, but I don't think that should make a difference:

Tested-by: James Clark <james.clark@...aro.org>

I can also test with the real thing if you like but would take a bit 
longer as I have to borrow it off Leo.

> Thanks,
> Ian
> 
>>> The issue with legacy events is that on RISC-V they want the driver to
>>> not have mappings from legacy to non-legacy config encodings for each
>>> vendor/model due to size, complexity and difficulty to update. It was
>>> reported that on ARM Apple-M? CPUs the legacy mapping in the driver
>>> was broken and the sysfs/json events should always take precedent,
>>> however, it isn't clear this is still the case. It is the case that
>>> without working around this issue a legacy event like cycles without a
>>> PMU can encode differently than when specified with a PMU - the
>>> non-PMU version favoring legacy encodings, the PMU one avoiding legacy
>>> encodings.
>>>
>>> The patch removes events and then adjusts the idx value for each
>>> evsel. This is done so that the dense xyarrays used for file
>>> descriptors, etc. don't contain broken entries. As event opening
>>> happens relatively late in the record process, use of the idx value
>>> before the open will have become corrupted, so it is expected there
>>> are latent bugs hidden behind this change - the change is best
>>> effort. As the only vendor that has broken event names is ARM, this
>>> will principally effect ARM users. They will also experience warning
>>> messages like those above because of the uncore PMU advertising legacy
>>> event names.
>>
>>
>>
>>>
>>> Suggested-by: Arnaldo Carvalho de Melo <acme@...nel.org>
>>> Signed-off-by: Ian Rogers <irogers@...gle.com>
>>> ---
>>>    tools/perf/builtin-record.c | 22 +++++++++++++++++-----
>>>    1 file changed, 17 insertions(+), 5 deletions(-)
>>>
>>> diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
>>> index f83252472921..7e99743f7e42 100644
>>> --- a/tools/perf/builtin-record.c
>>> +++ b/tools/perf/builtin-record.c
>>> @@ -1364,6 +1364,7 @@ static int record__open(struct record *rec)
>>>        struct perf_session *session = rec->session;
>>>        struct record_opts *opts = &rec->opts;
>>>        int rc = 0;
>>> +     bool skipped = false;
>>>
>>>        evlist__for_each_entry(evlist, pos) {
>>>    try_again:
>>> @@ -1379,15 +1380,26 @@ static int record__open(struct record *rec)
>>>                                pos = evlist__reset_weak_group(evlist, pos, true);
>>>                                goto try_again;
>>>                        }
>>> -                     rc = -errno;
>>>                        evsel__open_strerror(pos, &opts->target, errno, msg, sizeof(msg));
>>> -                     ui__error("%s\n", msg);
>>> -                     goto out;
>>> +                     ui__error("Failure to open event '%s' on PMU '%s' which will be removed.\n%s\n",
>>> +                               evsel__name(pos), evsel__pmu_name(pos), msg);
>>> +                     pos->skippable = true;
>>> +                     skipped = true;
>>> +             } else {
>>> +                     pos->supported = true;
>>>                }
>>> -
>>> -             pos->supported = true;
>>>        }
>>>
>>> +     if (skipped) {
>>> +             struct evsel *tmp;
>>> +             int idx = 0;
>>> +
>>> +             evlist__for_each_entry_safe(evlist, tmp, pos) {
>>> +                     if (pos->skippable)
>>> +                             evlist__remove(evlist, pos);
>>> +                     pos->core.idx = idx++;
>>> +             }
>>> +     }
>>>        if (symbol_conf.kptr_restrict && !evlist__exclude_kernel(evlist)) {
>>>                pr_warning(
>>>    "WARNING: Kernel address maps (/proc/{kallsyms,modules}) are restricted,\n"
>>

Powered by blists - more mailing lists