From: Arnaldo Carvalho de Melo <acme@kernel.org>
To: Namhyung Kim <namhyung@kernel.org>
Cc: Ian Rogers <irogers@google.com>,
Kan Liang <kan.liang@linux.intel.com>,
Jiri Olsa <jolsa@kernel.org>,
Adrian Hunter <adrian.hunter@intel.com>,
Peter Zijlstra <peterz@infradead.org>,
Ingo Molnar <mingo@kernel.org>,
LKML <linux-kernel@vger.kernel.org>,
linux-perf-users@vger.kernel.org,
Stephane Eranian <eranian@google.com>
Subject: Re: [PATCH] perf report: Add 'tgid' sort key
Date: Wed, 19 Feb 2025 15:37:10 +0100 [thread overview]
Message-ID: <Z7XsltyqUWrdKma0@x1> (raw)
In-Reply-To: <Z7UDlZKnqXRqNqQa@google.com>
On Tue, Feb 18, 2025 at 02:03:01PM -0800, Namhyung Kim wrote:
> On Tue, Feb 18, 2025 at 10:01:33PM +0100, Arnaldo Carvalho de Melo wrote:
> > On Tue, Feb 18, 2025 at 09:36:52PM +0100, Arnaldo Carvalho de Melo wrote:
> > > So the call to maps_fixup_end() will set maps->end_broken to false,
> > > since it fixed up the map ends, etc, but then we insert more maps with
> > > broken ends:
> >
> > > #6 0x0000000000633d52 in check_invariants (maps=0xf967c0) at util/maps.c:95
> > > 95 assert(map__end(prev) <= map__end(map));
> > > (gdb) p prev->dso->name
> > > $1 = 0xfc47ab "bpf_trampoline_6442522522"
> >
> > So the above map is created overlapping a previously existing map:
> >
> > root@number:~# perf probe -l
> > probe_perf:maps_fixup_end (on maps__fixup_end:1@util/maps.c in /home/acme/bin/perf with maps)
> > probe_perf:maps_insert (on maps__insert:1@util/maps.c in /home/acme/bin/perf with maps name start end)
> > root@number:~#
> >
> > root@number:~# perf trace --lib -e probe_perf:maps* perf record sleep
> > <SNIP>
> > 319.791 perf/1732173 probe_perf:maps_insert((634e5e) maps=0x2d9715d0 name="bpf_prog_6deef7357e7b4530_sd_fw_egress" start=0xffffffffc0160788 end=0xffffffffc01607c8)
> > 319.810 perf/1732173 probe_perf:maps_insert((634e5e) maps=0x2d9715d0 name="bpf_prog_6deef7357e7b4530_sd_fw_ingress" start=0xffffffffc01647b8 end=0xffffffffc01647f8)
> > 319.822 perf/1732173 probe_perf:maps_insert((634e5e) maps=0x2d9715d0 name="bpf_prog_6deef7357e7b4530_sd_fw_egress" start=0xffffffffc016482c end=0xffffffffc016486c)
> > 319.834 perf/1732173 probe_perf:maps_insert((634e5e) maps=0x2d9715d0 name="bpf_prog_6deef7357e7b4530_sd_fw_ingress" start=0xffffffffc01648ac end=0xffffffffc01648ec)
> > 319.845 perf/1732173 probe_perf:maps_insert((634e5e) maps=0x2d9715d0 name="bpf_prog_be31ae23198a0378_sd_devices" start=0xffffffffc0186388 end=0xffffffffc01864b2)
> > 319.857 perf/1732173 probe_perf:maps_insert((634e5e) maps=0x2d9715d0 name="bpf_trampoline_6442522522" start=0xffffffffc0147640 end=0xffffffffc0148640)
> > [ perf record: Captured and wrote 0.035 MB perf.data (7 samples) ]
> > perf: util/maps.c:95: check_invariants: Assertion `map__end(prev) <= map__end(map)' failed.
> > root@number:~#
> >
> > So a PERF_RECORD_KSYMBOL processing will add a map for
> > "bpf_trampoline_6442522522" that has its start after before the
> > "bpf_prog_40ddf486530245f5_sd_devices" start, ok, but ends after
> > "bpf_prog_40ddf486530245f5_sd_devices", overlapping it.
> >
> > machine__process_ksymbol_register() does:
> >
> > 713 map__set_start(map, event->ksymbol.addr);
> > 714 map__set_end(map, map__start(map) + event->ksymbol.len);
> > 715 err = maps__insert(machine__kernel_maps(machine), map);
> >
> > And:
> >
> > (gdb) p /x event->ksymbol.addr
> > $2 = 0xffffffffc0147a2c
> > (gdb) p event->ksymbol.len
> > $3 = 306
>
> Hmm.. so I think the situation is like below.
>
> (bpf_trampoline_6442522522)
> +---------------------------------------+
> | |
> | +------------------------+ |
> | | (bpf_prog_40ddf486...) | <----+---- adding this
> | | | |
> | | | |
> | c0147a2c |
> | |
> c0147640 c0148640
>
> And it failed to add bpf_prog_40ddf486... in check_invariants() because
> the end address is smaller than the previous map.
No, it didn't fail to add, it managed to do it which left the kernel
maps in a broken state, with overlappings while it had a cleared
ends_broken, then, later, when the checks_invariant is finally called at
perf record exit time:
> > > > #4 0x00007ffff6e3681e in __assert_fail_base (fmt=0x7ffff6fc3bb8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x7bef08 "map__end(prev) <= map__end(map)",
> > > > file=file@entry=0x7bedf8 "util/maps.c", line=line@entry=95, function=function@entry=0x7bf1c0 <__PRETTY_FUNCTION__.6> "check_invariants") at assert.c:96
> > > > #5 0x00007ffff6e47047 in __assert_fail (assertion=0x7bef08 "map__end(prev) <= map__end(map)", file=0x7bedf8 "util/maps.c", line=95,
> > > > function=0x7bf1c0 <__PRETTY_FUNCTION__.6> "check_invariants") at assert.c:105
> > > > #6 0x00000000006347a1 in check_invariants (maps=0xf987e0) at util/maps.c:95
> > > > #7 0x0000000000635ae2 in maps__remove (maps=0xf987e0, map=0xf98a80) at util/maps.c:538
> > > > #8 0x000000000062afd2 in machine__destroy_kernel_maps (machine=0xf98178) at util/machine.c:1176
> > > > #9 0x000000000062b32b in machines__destroy_kernel_maps (machines=0xf98178) at util/machine.c:1238
> > > > #10 0x00000000006388af in perf_session__destroy_kernel_maps (session=0xf97f60) at util/session.c:105
> > > > #11 0x0000000000638df0 in perf_session__delete (session=0xf97f60) at util/session.c:248
> > > > #12 0x0000000000431f18 in __cmd_record (rec=0xecace0 <record>, argc=4, argv=0x7fffffffde60) at builtin-record.c:2888
is when we detect the problem, but I see what you mean, I'm trying to
figure out why this isn't caught here:
machine__process_ksymbol_register() ->
int maps__insert(struct maps *maps, struct map *map)
{
int ret;
down_write(maps__lock(maps));
ret = __maps__insert(maps, map);
check_invariants(maps);
up_write(maps__lock(maps));
return ret;
}
Some more tracing:
root@number:~# perf probe -d probe_perf:* ; perf probe -qx ~/bin/perf check_invariants maps 'maps->maps_by_address_sorted' ; perf probe -qx ~/bin/perf maps__insert maps 'map->dso->name:string' 'map->start' 'map->end' ; perf probe -qx ~/bin/perf maps__fixup_end maps ; perf probe -l
Removed event: probe_perf:check_invariants
Removed event: probe_perf:maps_fixup_end
Removed event: probe_perf:maps_insert
probe_perf:check_invariants (on check_invariants:1@util/maps.c in /home/acme/bin/perf with maps maps_by_address_sorted)
probe_perf:maps_fixup_end (on maps__fixup_end:1@util/maps.c in /home/acme/bin/perf with maps)
probe_perf:maps_insert (on maps__insert:1@util/maps.c in /home/acme/bin/perf with maps name start end)
root@number:~#
And then:
root@number:~# perf trace --lib -e probe_perf:maps_*,probe_perf:check_invariants/max-stack=32/ perf record sleep
<SNIP>
316.283 perf/1882053 probe_perf:maps_insert((634e64) maps=0x342785d0 name="bpf_prog_6deef7357e7b4530_sd_fw_ingress" start=0xffffffffc01648ac end=0xffffffffc01648ec)
316.284 perf/1882053 probe_perf:check_invariants((633b0f) maps=0x342785d0 maps_by_address_sorted=0x0)
check_invariants (/home/acme/bin/perf)
maps__insert (/home/acme/bin/perf)
machine__process_ksymbol_register (/home/acme/bin/perf)
machine__process_ksymbol (/home/acme/bin/perf)
perf_event__process_ksymbol (/home/acme/bin/perf)
machines__deliver_event (/home/acme/bin/perf)
perf_session__deliver_event (/home/acme/bin/perf)
perf_session__process_event (/home/acme/bin/perf)
process_simple (/home/acme/bin/perf)
reader__read_event (/home/acme/bin/perf)
reader__process_events (/home/acme/bin/perf)
__perf_session__process_events (/home/acme/bin/perf)
perf_session__process_events (/home/acme/bin/perf)
process_buildids (/home/acme/bin/perf)
record__finish_output (/home/acme/bin/perf)
__cmd_record (/home/acme/bin/perf)
cmd_record (/home/acme/bin/perf)
run_builtin (/home/acme/bin/perf)
handle_internal_command (/home/acme/bin/perf)
run_argv (/home/acme/bin/perf)
main (/home/acme/bin/perf)
__libc_start_call_main (/usr/lib64/libc.so.6)
__libc_start_main@@GLIBC_2.34 (/usr/lib64/libc.so.6)
_start (/home/acme/bin/perf)
316.296 perf/1882053 probe_perf:maps_insert((634e64) maps=0x342785d0 name="bpf_prog_be31ae23198a0378_sd_devices" start=0xffffffffc0186388 end=0xffffffffc01864b2)
316.298 perf/1882053 probe_perf:check_invariants((633b0f) maps=0x342785d0 maps_by_address_sorted=0x0)
check_invariants (/home/acme/bin/perf)
maps__insert (/home/acme/bin/perf)
machine__process_ksymbol_register (/home/acme/bin/perf)
machine__process_ksymbol (/home/acme/bin/perf)
perf_event__process_ksymbol (/home/acme/bin/perf)
machines__deliver_event (/home/acme/bin/perf)
perf_session__deliver_event (/home/acme/bin/perf)
perf_session__process_event (/home/acme/bin/perf)
process_simple (/home/acme/bin/perf)
reader__read_event (/home/acme/bin/perf)
reader__process_events (/home/acme/bin/perf)
__perf_session__process_events (/home/acme/bin/perf)
perf_session__process_events (/home/acme/bin/perf)
process_buildids (/home/acme/bin/perf)
record__finish_output (/home/acme/bin/perf)
__cmd_record (/home/acme/bin/perf)
cmd_record (/home/acme/bin/perf)
run_builtin (/home/acme/bin/perf)
handle_internal_command (/home/acme/bin/perf)
run_argv (/home/acme/bin/perf)
main (/home/acme/bin/perf)
__libc_start_call_main (/usr/lib64/libc.so.6)
__libc_start_main@@GLIBC_2.34 (/usr/lib64/libc.so.6)
_start (/home/acme/bin/perf)
316.310 perf/1882053 probe_perf:maps_insert((634e64) maps=0x342785d0 name="bpf_trampoline_6442522522" start=0xffffffffc0147640 end=0xffffffffc0148640)
316.311 perf/1882053 probe_perf:check_invariants((633b0f) maps=0x342785d0 maps_by_address_sorted=0x0)
check_invariants (/home/acme/bin/perf)
maps__insert (/home/acme/bin/perf)
machine__process_ksymbol_register (/home/acme/bin/perf)
machine__process_ksymbol (/home/acme/bin/perf)
perf_event__process_ksymbol (/home/acme/bin/perf)
machines__deliver_event (/home/acme/bin/perf)
perf_session__deliver_event (/home/acme/bin/perf)
perf_session__process_event (/home/acme/bin/perf)
process_simple (/home/acme/bin/perf)
reader__read_event (/home/acme/bin/perf)
reader__process_events (/home/acme/bin/perf)
__perf_session__process_events (/home/acme/bin/perf)
perf_session__process_events (/home/acme/bin/perf)
process_buildids (/home/acme/bin/perf)
record__finish_output (/home/acme/bin/perf)
__cmd_record (/home/acme/bin/perf)
cmd_record (/home/acme/bin/perf)
run_builtin (/home/acme/bin/perf)
handle_internal_command (/home/acme/bin/perf)
run_argv (/home/acme/bin/perf)
main (/home/acme/bin/perf)
__libc_start_call_main (/usr/lib64/libc.so.6)
__libc_start_main@@GLIBC_2.34 (/usr/lib64/libc.so.6)
_start (/home/acme/bin/perf)
316.369 perf/1882053 probe_perf:check_invariants((633b0f) maps=0x342a6950 maps_by_address_sorted=0x1)
check_invariants (/home/acme/bin/perf)
__maps__insert_sorted (/home/acme/bin/perf)
__maps__fixup_overlap_and_insert (/home/acme/bin/perf)
maps__fixup_overlap_and_insert (/home/acme/bin/perf)
thread__insert_map (/home/acme/bin/perf)
machine__process_mmap2_event (/home/acme/bin/perf)
perf_event__process_mmap2 (/home/acme/bin/perf)
build_id__process_mmap2 (/home/acme/bin/perf)
machines__deliver_event (/home/acme/bin/perf)
perf_session__deliver_event (/home/acme/bin/perf)
ordered_events__deliver_event (/home/acme/bin/perf)
do_flush (/home/acme/bin/perf)
__ordered_events__flush (/home/acme/bin/perf)
ordered_events__flush (/home/acme/bin/perf)
__perf_session__process_events (/home/acme/bin/perf)
perf_session__process_events (/home/acme/bin/perf)
process_buildids (/home/acme/bin/perf)
record__finish_output (/home/acme/bin/perf)
__cmd_record (/home/acme/bin/perf)
cmd_record (/home/acme/bin/perf)
run_builtin (/home/acme/bin/perf)
handle_internal_command (/home/acme/bin/perf)
run_argv (/home/acme/bin/perf)
main (/home/acme/bin/perf)
__libc_start_call_main (/usr/lib64/libc.so.6)
__libc_start_main@@GLIBC_2.34 (/usr/lib64/libc.so.6)
_start (/home/acme/bin/perf)
<SNIP>
[ perf record: Captured and wrote 0.035 MB perf.data (7 samples) ]
1195.433 perf/1882053 probe_perf:check_invariants((633b0f) maps=0x342785d0 maps_by_address_sorted=0x1)
check_invariants (/home/acme/bin/perf)
maps__remove (/home/acme/bin/perf)
machine__destroy_kernel_maps (/home/acme/bin/perfperf: util/maps.c:95: check_invariants: Assertion `map__end(prev) <= map__end(map)' failed.
)
machines__destroy_kernel_maps (/home/acme/bin/perf)
perf_session__destroy_kernel_maps (/home/acme/bin/perf)
perf_session__delete (/home/acme/bin/perf)
__cmd_record (/home/acme/bin/perf)
cmd_record (/home/acme/bin/perf)
run_builtin (/home/acme/bin/perf)
handle_internal_command (/home/acme/bin/perf)
run_argv (/home/acme/bin/perf)
main (/home/acme/bin/perf)
__libc_start_call_main (/usr/lib64/libc.so.6)
__libc_start_main@@GLIBC_2.34 (/usr/lib64/libc.so.6)
_start (/home/acme/bin/perf)
root@number:~#
check_invariants() doesn't check the ends because the
maps_byh_address_sorted is not set, I'll soon disappear into a call, but
the above should help as a checkpoint, I'll be back.
- Arnaldo
> > Thread 1 "perf" hit Breakpoint 1, machine__process_ksymbol_register (machine=0xf96158, event=0x7ffff7fb9aa0, sample=0x7fffffffa860) at util/machine.c:688
> > 688 {
> > (gdb) bt
> > #0 machine__process_ksymbol_register (machine=0xf96158, event=0x7ffff7fb9aa0, sample=0x7fffffffa860) at util/machine.c:688
> > #1 0x00000000006294ca in machine__process_ksymbol (machine=0xf96158, event=0x7ffff7fb9aa0, sample=0x7fffffffa860) at util/machine.c:779
> > #2 0x00000000005ce2fd in perf_event__process_ksymbol (tool=0xec8ce0 <record>, event=0x7ffff7fb9aa0, sample=0x7fffffffa860, machine=0xf96158) at util/event.c:296
> > #3 0x000000000063b6e4 in machines__deliver_event (machines=0xf96158, evlist=0xf521f0, event=0x7ffff7fb9aa0, sample=0x7fffffffa860, tool=0xec8ce0 <record>, file_offset=31392,
> > file_path=0xf96850 "perf.data") at util/session.c:1334
> > #4 0x000000000063b8c9 in perf_session__deliver_event (session=0xf95f40, event=0x7ffff7fb9aa0, tool=0xec8ce0 <record>, file_offset=31392, file_path=0xf96850 "perf.data")
> > at util/session.c:1367
> > #5 0x000000000063c6bd in perf_session__process_event (session=0xf95f40, event=0x7ffff7fb9aa0, file_offset=31392, file_path=0xf96850 "perf.data") at util/session.c:1626
> > #6 0x000000000063de3d in process_simple (session=0xf95f40, event=0x7ffff7fb9aa0, file_offset=31392, file_path=0xf96850 "perf.data") at util/session.c:2203
> > #7 0x000000000063daf4 in reader__read_event (rd=0x7fffffffafa0, session=0xf95f40, prog=0x7fffffffaf70) at util/session.c:2132
> > #8 0x000000000063dcee in reader__process_events (rd=0x7fffffffafa0, session=0xf95f40, prog=0x7fffffffaf70) at util/session.c:2181
> > #9 0x000000000063df8b in __perf_session__process_events (session=0xf95f40) at util/session.c:2226
> > #10 0x000000000063e988 in perf_session__process_events (session=0xf95f40) at util/session.c:2390
> > #11 0x000000000042d98b in process_buildids (rec=0xec8ce0 <record>) at builtin-record.c:1475
> > #12 0x000000000042e963 in record__finish_output (rec=0xec8ce0 <record>) at builtin-record.c:1798
> > #13 0x0000000000431c46 in __cmd_record (rec=0xec8ce0 <record>, argc=2, argv=0x7fffffffde80) at builtin-record.c:2841
> > #14 0x000000000043513f in cmd_record (argc=2, argv=0x7fffffffde80) at builtin-record.c:4260
> > #15 0x00000000004bcf65 in run_builtin (p=0xecbd60 <commands+288>, argc=3, argv=0x7fffffffde80) at perf.c:351
> > #16 0x00000000004bd20c in handle_internal_command (argc=3, argv=0x7fffffffde80) at perf.c:404
> > #17 0x00000000004bd365 in run_argv (argcp=0x7fffffffdc6c, argv=0x7fffffffdc60) at perf.c:448
> > #18 0x00000000004bd6ae in main (argc=3, argv=0x7fffffffde80) at perf.c:556
> > (gdb)
>
> > So, this one liner "refixes" the "modules" ends when processing the
> > records to find the build ids, unsure if it is the best solution tho:
> I think it "fixes" the problem by not clearing maps->ends_broken during
> the sample processing. So check_invariants() will not check the end
> addresses of overlapping bpf_trampoline and bpf_prog.
You mean my one-liner?
I meant "refixes" as in maps__fixup_end() will fixup the overlapping of
the bpf_trampoline and bpf_prog and will re-clear maps->ends_broken
(needlessly, it was already cleared by the first call to
maps__fixup_end() after loading modules, at the start of the session).
Then check_invariants() _will_, check again, because maps->ends_broken
is cleared (was cleared twice even), the end addresses and there will
not be any overlapping, no?
- Arnaldo
> I'm curious how other commands (like perf report) are affected. I think
> the original concern was the output of `perf buildid-list -m`.
>
> Thanks,
> Namhyung
>
> >
> > diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
> > index 5db1aedf48df92d2..5c4603d08ab5f2cb 100644
> > --- a/tools/perf/builtin-record.c
> > +++ b/tools/perf/builtin-record.c
> > @@ -1797,6 +1797,8 @@ record__finish_output(struct record *rec)
> > if (!rec->no_buildid) {
> > process_buildids(rec);
> >
> > + maps__fixup_end(machine__kernel_maps(&rec->session->machines.host));
> > +
> > if (rec->buildid_all)
> > perf_session__dsos_hit_all(rec->session);
> > }
> >
> >
next prev parent reply other threads:[~2025-02-19 14:37 UTC|newest]
Thread overview: 30+ messages / expand[flat|nested] mbox.gz Atom feed top
2025-02-06 0:01 [PATCH] perf report: Add 'tgid' sort key Namhyung Kim
2025-02-11 22:43 ` Ian Rogers
2025-02-12 21:05 ` Arnaldo Carvalho de Melo
2025-02-12 21:07 ` Arnaldo Carvalho de Melo
2025-02-12 21:59 ` Ian Rogers
2025-02-12 22:10 ` Ian Rogers
2025-02-13 1:52 ` Namhyung Kim
2025-02-14 22:22 ` Arnaldo Carvalho de Melo
2025-02-18 20:36 ` Arnaldo Carvalho de Melo
2025-02-18 21:01 ` Arnaldo Carvalho de Melo
2025-02-18 22:03 ` Namhyung Kim
2025-02-19 14:37 ` Arnaldo Carvalho de Melo [this message]
2025-02-19 14:47 ` Arnaldo Carvalho de Melo
2025-02-19 21:10 ` Namhyung Kim
2025-02-20 17:12 ` Ian Rogers
2025-02-21 7:04 ` Namhyung Kim
2025-02-24 18:18 ` Ian Rogers
2025-02-25 2:51 ` Namhyung Kim
2025-02-25 4:40 ` Ian Rogers
2025-02-25 7:51 ` Namhyung Kim
2025-02-25 19:07 ` Arnaldo Carvalho de Melo
2025-02-25 19:11 ` Arnaldo Carvalho de Melo
2025-02-25 19:25 ` Arnaldo Carvalho de Melo
2025-02-25 19:48 ` Arnaldo Carvalho de Melo
2025-02-26 19:34 ` Namhyung Kim
2025-02-26 21:37 ` Arnaldo Carvalho de Melo
2025-02-26 21:38 ` Arnaldo Carvalho de Melo
2025-02-26 21:40 ` Arnaldo Carvalho de Melo
2025-02-26 21:49 ` Arnaldo Carvalho de Melo
2025-02-26 22:17 ` Namhyung Kim
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=Z7XsltyqUWrdKma0@x1 \
--to=acme@kernel.org \
--cc=adrian.hunter@intel.com \
--cc=eranian@google.com \
--cc=irogers@google.com \
--cc=jolsa@kernel.org \
--cc=kan.liang@linux.intel.com \
--cc=linux-kernel@vger.kernel.org \
--cc=linux-perf-users@vger.kernel.org \
--cc=mingo@kernel.org \
--cc=namhyung@kernel.org \
--cc=peterz@infradead.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.