| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <Z7XsltyqUWrdKma0@x1>
Date: Wed, 19 Feb 2025 15:37:10 +0100
From: Arnaldo Carvalho de Melo <acme@...nel.org>
To: Namhyung Kim <namhyung@...nel.org>
Cc: Ian Rogers <irogers@...gle.com>, Kan Liang <kan.liang@...ux.intel.com>,
Jiri Olsa <jolsa@...nel.org>,
Adrian Hunter <adrian.hunter@...el.com>,
Peter Zijlstra <peterz@...radead.org>,
Ingo Molnar <mingo@...nel.org>, LKML <linux-kernel@...r.kernel.org>,
linux-perf-users@...r.kernel.org,
Stephane Eranian <eranian@...gle.com>
Subject: Re: [PATCH] perf report: Add 'tgid' sort key
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@...ber:~# perf probe -l
> > probe_perf:maps_fixup_end (on maps__fixup_end:1@...l/maps.c in /home/acme/bin/perf with maps)
> > probe_perf:maps_insert (on maps__insert:1@...l/maps.c in /home/acme/bin/perf with maps name start end)
> > root@...ber:~#
> >
> > root@...ber:~# 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@...ber:~#
> >
> > 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@...ry=0x7bef08 "map__end(prev) <= map__end(map)",
> > > > file=file@...ry=0x7bedf8 "util/maps.c", line=line@...ry=95, function=function@...ry=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@...ber:~# 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@...l/maps.c in /home/acme/bin/perf with maps maps_by_address_sorted)
probe_perf:maps_fixup_end (on maps__fixup_end:1@...l/maps.c in /home/acme/bin/perf with maps)
probe_perf:maps_insert (on maps__insert:1@...l/maps.c in /home/acme/bin/perf with maps name start end)
root@...ber:~#
And then:
root@...ber:~# 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@...ber:~#
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);
> > }
> >
> >
Powered by blists - more mailing lists