Hello,
A bug in perf v5.19 and newer completely breaks monitoring multithreaded
processes using "perf top -p". The tool fails to start with "Failed to mmap
with 22 (Invalid argument)". It still seems to work fine on single-threaded
processes. "perf record" is also unaffected.
I have bisected the issue to the following commit:
commit ae4f8ae16a07896403c90305d4b9be27f657c1fc
Author: Adrian Hunter <[email protected]>
Date: Tue May 24 10:54:31 2022 +0300
libperf evlist: Allow mixing per-thread and per-cpu mmaps
mmap_per_evsel() will skip events that do not match the CPU, so all CPUs
can be iterated in any case.
The issue can be easily reproduced using the following test:
$ python - <<EOF
import time
import threading
th = threading.Thread(target=time.sleep, args=(3600,))
th.start()
th.join()
EOF
stracing "perf top -p $(pgrep python)" yields this:
145184 perf_event_open({type=PERF_TYPE_HARDWARE, size=PERF_ATTR_SIZE_VER7, config=PERF_COUNT_HW_CPU_CYCLES, sample_freq=4000, sample_type=PERF_SAMPLE_IP|PERF_SAMPLE_TID|PERF_SAMPLE_TIME|PERF_SAMPLE_PERIOD, read_format=PERF_FORMAT_ID, disabled=1, exclude_kernel=1, mmap=1, comm=1, freq=1, task=1, precise_ip=0 /* arbitrary skid */, sample_id_all=1, mmap2=1, comm_exec=1, ksymbol=1, ...}, 92061, -1, -1, PERF_FLAG_FD_CLOEXEC) = 3
> tools/perf/perf(evsel__open_cpu+0x287) [0x4c8ad7]
> tools/perf/perf(cmd_top+0x1996) [0x439b26]
> tools/perf/perf(run_builtin+0x68) [0x4a91f8]
> tools/perf/perf(main+0x645) [0x40cad5]
145184 perf_event_open({type=PERF_TYPE_HARDWARE, size=PERF_ATTR_SIZE_VER7, config=PERF_COUNT_HW_CPU_CYCLES, sample_freq=4000, sample_type=PERF_SAMPLE_IP|PERF_SAMPLE_TID|PERF_SAMPLE_TIME|PERF_SAMPLE_PERIOD, read_format=PERF_FORMAT_ID, disabled=1, exclude_kernel=1, mmap=1, comm=1, freq=1, task=1, precise_ip=0 /* arbitrary skid */, sample_id_all=1, mmap2=1, comm_exec=1, ksymbol=1, ...}, 104619, -1, -1, PERF_FLAG_FD_CLOEXEC) = 5
> tools/perf/perf(evsel__open_cpu+0x287) [0x4c8ad7]
> tools/perf/perf(cmd_top+0x1996) [0x439b26]
> tools/perf/perf(run_builtin+0x68) [0x4a91f8]
> tools/perf/perf(main+0x645) [0x40cad5]
…(snip)…
145184 ioctl(5, PERF_EVENT_IOC_SET_OUTPUT, 3) = -1 EINVAL (Invalid argument)
> tools/perf/perf(perf_evlist__mmap_ops+0x2cf) [0x5d497f]
> tools/perf/perf(evlist__mmap+0xa7) [0x4c09b7]
> perf/perf(cmd_top+0x1ccd) [0x439e5d]
> tools/perf/perf(run_builtin+0x68) [0x4a91f8]
> tools/perf/perf(main+0x645) [0x40cad5]
Best regards,
Tomáš
--
Tomáš Trnka
Software for Chemistry & Materials B.V.
TWIMC: this mail is primarily send for documentation purposes and for
regzbot, my Linux kernel regression tracking bot. These mails usually
contain '#forregzbot' in the subject, to make them easy to spot and filter.
[TLDR: I'm adding this regression report to the list of tracked
regressions; all text from me you find below is based on a few templates
paragraphs you might have encountered already already in similar form.]
Hi, this is your Linux kernel regression tracker. CCing the regression
mailing list, as it should be in the loop for all regressions, as
explained here:
https://www.kernel.org/doc/html/latest/admin-guide/reporting-issues.html
On 02.09.22 16:46, Tomáš Trnka wrote:
> Hello,
>
> A bug in perf v5.19 and newer completely breaks monitoring multithreaded
> processes using "perf top -p". The tool fails to start with "Failed to mmap
> with 22 (Invalid argument)". It still seems to work fine on single-threaded
> processes. "perf record" is also unaffected.
>
> I have bisected the issue to the following commit:
>
> commit ae4f8ae16a07896403c90305d4b9be27f657c1fc
> Author: Adrian Hunter <[email protected]>
> Date: Tue May 24 10:54:31 2022 +0300
>
> libperf evlist: Allow mixing per-thread and per-cpu mmaps
>
> mmap_per_evsel() will skip events that do not match the CPU, so all CPUs
> can be iterated in any case.
>
> The issue can be easily reproduced using the following test:
>
> $ python - <<EOF
> import time
> import threading
> th = threading.Thread(target=time.sleep, args=(3600,))
> th.start()
> th.join()
> EOF
>
> stracing "perf top -p $(pgrep python)" yields this:
>
> 145184 perf_event_open({type=PERF_TYPE_HARDWARE, size=PERF_ATTR_SIZE_VER7, config=PERF_COUNT_HW_CPU_CYCLES, sample_freq=4000, sample_type=PERF_SAMPLE_IP|PERF_SAMPLE_TID|PERF_SAMPLE_TIME|PERF_SAMPLE_PERIOD, read_format=PERF_FORMAT_ID, disabled=1, exclude_kernel=1, mmap=1, comm=1, freq=1, task=1, precise_ip=0 /* arbitrary skid */, sample_id_all=1, mmap2=1, comm_exec=1, ksymbol=1, ...}, 92061, -1, -1, PERF_FLAG_FD_CLOEXEC) = 3
> > tools/perf/perf(evsel__open_cpu+0x287) [0x4c8ad7]
> > tools/perf/perf(cmd_top+0x1996) [0x439b26]
> > tools/perf/perf(run_builtin+0x68) [0x4a91f8]
> > tools/perf/perf(main+0x645) [0x40cad5]
> 145184 perf_event_open({type=PERF_TYPE_HARDWARE, size=PERF_ATTR_SIZE_VER7, config=PERF_COUNT_HW_CPU_CYCLES, sample_freq=4000, sample_type=PERF_SAMPLE_IP|PERF_SAMPLE_TID|PERF_SAMPLE_TIME|PERF_SAMPLE_PERIOD, read_format=PERF_FORMAT_ID, disabled=1, exclude_kernel=1, mmap=1, comm=1, freq=1, task=1, precise_ip=0 /* arbitrary skid */, sample_id_all=1, mmap2=1, comm_exec=1, ksymbol=1, ...}, 104619, -1, -1, PERF_FLAG_FD_CLOEXEC) = 5
> > tools/perf/perf(evsel__open_cpu+0x287) [0x4c8ad7]
> > tools/perf/perf(cmd_top+0x1996) [0x439b26]
> > tools/perf/perf(run_builtin+0x68) [0x4a91f8]
> > tools/perf/perf(main+0x645) [0x40cad5]
> …(snip)…
> 145184 ioctl(5, PERF_EVENT_IOC_SET_OUTPUT, 3) = -1 EINVAL (Invalid argument)
> > tools/perf/perf(perf_evlist__mmap_ops+0x2cf) [0x5d497f]
> > tools/perf/perf(evlist__mmap+0xa7) [0x4c09b7]
> > perf/perf(cmd_top+0x1ccd) [0x439e5d]
> > tools/perf/perf(run_builtin+0x68) [0x4a91f8]
> > tools/perf/perf(main+0x645) [0x40cad5]
>
> Best regards,
>
> Tomáš
> --
> Tomáš Trnka
> Software for Chemistry & Materials B.V.
Thanks for the report. To be sure below issue doesn't fall through the
cracks unnoticed, I'm adding it to regzbot, my Linux kernel regression
tracking bot:
#regzbot introduced ae4f8ae16a07896 ^
https://bugzilla.kernel.org/show_bug.cgi?id=216441
#regzbot title perf: perf top -p broken for multithreaded processes
since 5.19
#regzbot ignore-activity
This isn't a regression? This issue or a fix for it are already
discussed somewhere else? It was fixed already? You want to clarify when
the regression started to happen? Or point out I got the title or
something else totally wrong? Then just reply -- ideally with also
telling regzbot about it, as explained here:
https://linux-regtracking.leemhuis.info/tracked-regression/
Reminder for developers: When fixing the issue, add 'Link:' tags
pointing to the report (the mail this one replies to), as explained for
in the Linux kernel's documentation; above webpage explains why this is
important for tracked regressions.
Ciao, Thorsten (wearing his 'the Linux kernel's regression tracker' hat)
P.S.: As the Linux kernel's regression tracker I deal with a lot of
reports and sometimes miss something important when writing mails like
this. If that's the case here, don't hesitate to tell me in a public
reply, it's in everyone's interest to set the public record straight.
On 3/09/22 21:42, Arnaldo Carvalho de Melo wrote:
>
>
> On September 3, 2022 2:35:09 PM GMT-03:00, Adrian Hunter <[email protected] <mailto:[email protected]>> wrote:
>>On 3/09/22 17:08, Arnaldo Carvalho de Melo wrote:
>>> Em Sat, Sep 03, 2022 at 10:14:25AM +0300, Adrian Hunter escreveu:
>>>> On 2/09/22 22:17, Arnaldo Carvalho de Melo wrote:
>>>>> Em Fri, Sep 02, 2022 at 05:50:22PM +0300, Adrian Hunter escreveu:
>>>>>> On 2/09/22 17:46, Tomáš Trnka wrote:
>>>>>>> Hello,
>>>>>>>
>>>>>>> A bug in perf v5.19 and newer completely breaks monitoring multithreaded
>>>>>>> processes using "perf top -p". The tool fails to start with "Failed to mmap
>>>>>>> with 22 (Invalid argument)". It still seems to work fine on single-threaded
>>>>>>> processes. "perf record" is also unaffected.
>>>>>>
>>>>>> It has been reported here:
>>>>>>
>>>>>> https://bugzilla.kernel.org/show_bug.cgi?id=216441 <https://bugzilla.kernel.org/show_bug.cgi?id=216441>
>>>>>
>>>>> If I do:
>>>>>
>>>>> ⬢[acme@toolbox perf-urgent]$ git log -2
>>>>> commit dfeb0bc60782471c293938e71b1a1117cfac2cb3 (HEAD -> perf/urgent)
>>>>> Author: Arnaldo Carvalho de Melo <[email protected] <mailto:[email protected]>>
>>>>> Date: Fri Sep 2 16:15:39 2022 -0300
>>>>>
>>>>> Revert "libperf evlist: Check nr_mmaps is correct"
>>>>>
>>>>> This reverts commit 4ce47d842d4c16c07b135b8a7975b8f0672bcc0e.
>>>>>
>>>>> Signed-off-by: Arnaldo Carvalho de Melo <[email protected] <mailto:[email protected]>>
>>>>>
>>>>> commit 78cd283f6b8ab701cb35eafd5af8140560a88f16
>>>>> Author: Arnaldo Carvalho de Melo <[email protected] <mailto:[email protected]>>
>>>>> Date: Fri Sep 2 16:13:41 2022 -0300
>>>>>
>>>>> Revert "libperf evlist: Allow mixing per-thread and per-cpu mmaps"
>>>>>
>>>>> This reverts commit ae4f8ae16a07896403c90305d4b9be27f657c1fc.
>>>>>
>>>>> Signed-off-by: Arnaldo Carvalho de Melo <[email protected] <mailto:[email protected]>>
>>>>> ⬢[acme@toolbox perf-urgent]$
>>>>>
>>>>> It works again, Tomáš can you please try doing this to see if this works
>>>>> for you?
>>>>>
>>>>
>>>> This is the fix I have so far. I would like to test it some more though.
>>>
>>> Ok, so I'll leave it for the next pull req, possibly after Linux
>>> Plumbers.
>>>
>>> What do you think about reverting those two patches for v6.0 and then
>>> add this for v6.1?
>>
>>That would break sideband collection with selected CPUs, so I would
>>prefer to avoid that.
>>
>>The fix is a effectively a partial revert of "libperf evlist: Allow
>>mixing per-thread and per-cpu mmaps" anyway. I just need a few days
>>to do more testing.
>
> Ok, please add any insight or clarification you find while testing to the end result patch, like this sideband collection with selected CPUs.
>
> This is all complex, so even comments being prone to drift from code, having them added in the commit log message, associated with the codebase at that time may help us in the future when fixing problems, using 'git blame'.
I finished the testing I wanted to do, and sent V2 of the patch with an expanded commit message:
https://lore.kernel.org/lkml/[email protected]/T/#u
On 04.09.22 12:15, Thorsten Leemhuis wrote:
> TWIMC: this mail is primarily send for documentation purposes and for
> regzbot, my Linux kernel regression tracking bot. These mails usually
> contain '#forregzbot' in the subject, to make them easy to spot and filter.
>
> [...]
> On 02.09.22 16:46, Tomáš Trnka wrote:
>>
>> A bug in perf v5.19 and newer completely breaks monitoring multithreaded
>> processes using "perf top -p". The tool fails to start with "Failed to mmap
>> with 22 (Invalid argument)". It still seems to work fine on single-threaded
>> processes. "perf record" is also unaffected.
>>
>> I have bisected the issue to the following commit:
>>
>> commit ae4f8ae16a07896403c90305d4b9be27f657c1fc
>> Author: Adrian Hunter <[email protected]>
>> Date: Tue May 24 10:54:31 2022 +0300
>>
>> libperf evlist: Allow mixing per-thread and per-cpu mmaps
>>
>> mmap_per_evsel() will skip events that do not match the CPU, so all CPUs
>> can be iterated in any case.
>>
>> The issue can be easily reproduced using the following test:
>>
>> $ python - <<EOF
>> import time
>> import threading
>> th = threading.Thread(target=time.sleep, args=(3600,))
>> th.start()
>> th.join()
>> EOF
>>
>> stracing "perf top -p $(pgrep python)" yields this:
>>
>> 145184 perf_event_open({type=PERF_TYPE_HARDWARE, size=PERF_ATTR_SIZE_VER7, config=PERF_COUNT_HW_CPU_CYCLES, sample_freq=4000, sample_type=PERF_SAMPLE_IP|PERF_SAMPLE_TID|PERF_SAMPLE_TIME|PERF_SAMPLE_PERIOD, read_format=PERF_FORMAT_ID, disabled=1, exclude_kernel=1, mmap=1, comm=1, freq=1, task=1, precise_ip=0 /* arbitrary skid */, sample_id_all=1, mmap2=1, comm_exec=1, ksymbol=1, ...}, 92061, -1, -1, PERF_FLAG_FD_CLOEXEC) = 3
>> > tools/perf/perf(evsel__open_cpu+0x287) [0x4c8ad7]
>> > tools/perf/perf(cmd_top+0x1996) [0x439b26]
>> > tools/perf/perf(run_builtin+0x68) [0x4a91f8]
>> > tools/perf/perf(main+0x645) [0x40cad5]
>> 145184 perf_event_open({type=PERF_TYPE_HARDWARE, size=PERF_ATTR_SIZE_VER7, config=PERF_COUNT_HW_CPU_CYCLES, sample_freq=4000, sample_type=PERF_SAMPLE_IP|PERF_SAMPLE_TID|PERF_SAMPLE_TIME|PERF_SAMPLE_PERIOD, read_format=PERF_FORMAT_ID, disabled=1, exclude_kernel=1, mmap=1, comm=1, freq=1, task=1, precise_ip=0 /* arbitrary skid */, sample_id_all=1, mmap2=1, comm_exec=1, ksymbol=1, ...}, 104619, -1, -1, PERF_FLAG_FD_CLOEXEC) = 5
>> > tools/perf/perf(evsel__open_cpu+0x287) [0x4c8ad7]
>> > tools/perf/perf(cmd_top+0x1996) [0x439b26]
>> > tools/perf/perf(run_builtin+0x68) [0x4a91f8]
>> > tools/perf/perf(main+0x645) [0x40cad5]
>> …(snip)…
>> 145184 ioctl(5, PERF_EVENT_IOC_SET_OUTPUT, 3) = -1 EINVAL (Invalid argument)
>> > tools/perf/perf(perf_evlist__mmap_ops+0x2cf) [0x5d497f]
>> > tools/perf/perf(evlist__mmap+0xa7) [0x4c09b7]
>> > perf/perf(cmd_top+0x1ccd) [0x439e5d]
>> > tools/perf/perf(run_builtin+0x68) [0x4a91f8]
>> > tools/perf/perf(main+0x645) [0x40cad5]
>>
>> Best regards,
>>
>> Tomáš
>> --
>> Tomáš Trnka
>> Software for Chemistry & Materials B.V.
>
> Thanks for the report. To be sure below issue doesn't fall through the
> cracks unnoticed, I'm adding it to regzbot, my Linux kernel regression
> tracking bot:
>
> #regzbot introduced ae4f8ae16a07896 ^
> https://bugzilla.kernel.org/show_bug.cgi?id=216441
> #regzbot title perf: perf top -p broken for multithreaded processes
> since 5.19
> #regzbot ignore-activity
#regzbot fixed-by: 7864d8f7c088aad988c44c631f1ceed9179cf2cf