| 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: <Z7ZIqpwffQbibwL2@google.com>
Date: Wed, 19 Feb 2025 13:10:02 -0800
From: Namhyung Kim <namhyung@...nel.org>
To: Arnaldo Carvalho de Melo <acme@...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 Wed, Feb 19, 2025 at 03:47:44PM +0100, Arnaldo Carvalho de Melo wrote:
> On Wed, Feb 19, 2025 at 03:37:10PM +0100, Arnaldo Carvalho de Melo wrote:
> > 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:
>
> Nope, __maps__insert() should notice that the ends are broken and set
> it:
>
> if (nr_maps == 1) {
> /* If there's just 1 entry then maps are sorted. */
> maps__set_maps_by_address_sorted(maps, true);
> maps__set_maps_by_name_sorted(maps, maps_by_name != NULL);
> } else {
> /* Sorted if maps were already sorted and this map starts after the last one. */
> maps__set_maps_by_address_sorted(maps,
> maps__maps_by_address_sorted(maps) &&
> map__end(maps_by_address[nr_maps - 2]) <= map__start(new));
> maps__set_maps_by_name_sorted(maps, false);
> }
> if (map__end(new) < map__start(new))
> RC_CHK_ACCESS(maps)->ends_broken = true;
>
>
> humm, RC_CHK_ACCESS(maps)->ends_broken should be set for the case we
> have and I think it isn't being... Then the bpf trampoline map that is
> the last entry to be added is before the last entry and thus
> maps_by_address_sorted is set to false, ends_broken continues false and
> at the end maps_by_address_sorted is set to true and the last
> check_invariants triggerrs the asserts...
Right, probably it needs to set the ends_broken when the end address of
the new map is smaller than the previous (but the start address is
bigger) and fixup the end address when it sorts the maps by address.
Thanks,
Namhyung
>
> > > > > > #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