Message-ID: <Z0caqvFFmkL9I6lk@x1>
Date: Wed, 27 Nov 2024 10:12:10 -0300
From: Arnaldo Carvalho de Melo <acme@...nel.org>
To: Namhyung Kim <namhyung@...nel.org>
Cc: Linus Torvalds <torvalds@...ux-foundation.org>,
	Ian Rogers <irogers@...gle.com>,
	Kan Liang <kan.liang@...ux.intel.com>,
	Peter Zijlstra <peterz@...radead.org>,
	Ingo Molnar <mingo@...nel.org>, LKML <linux-kernel@...r.kernel.org>,
	linux-perf-users@...r.kernel.org
Subject: Re: [GIT PULL] perf-tools changes for v6.13

On Tue, Nov 26, 2024 at 07:25:08PM -0800, Namhyung Kim wrote:
> On Tue, Nov 26, 2024 at 09:59:44PM -0300, Arnaldo Carvalho de Melo wrote:
> > On Tue, Nov 26, 2024 at 04:00:12PM -0800, Namhyung Kim wrote:
> > > On Tue, Nov 26, 2024 at 03:33:10PM -0800, Linus Torvalds wrote:
> > > > Hmm. Has the default search path for the vmlinux image changed?

> > > I don't think so.

> > > > Doing profiling with this, I get

> > > >     openat(AT_FDCWD, "vmlinux", O_RDONLY)   = 5

> > > > which is very very wrong for my kernel build - it basically picks up
> > > > the vmlinux image from the build directory, which has absolutely
> > > > *nothign* to do with the image that is being run at the moment.

> > > Sure, at least it should match the build-id before use.

> > I tried it here and at first I reproduced Linus results, which I found

I understand it now, first, when I tried to reproduce Linus case I did a
'perf record' with the most recent code, the one failing for Linus, but
then when I tried to test it with v6.1, trying to bisect it, perf v6.1
couldn't process the perf.data file generated "in the future", by
v6.12-rc6 + perf-tools:

# perf report -v
file uses a more recent and unsupported ABI (8 bytes extra)
incompatible file format (rerun with -v to learn more)
#

So I did another 'perf record' and used that perf.data, that had no
problems all the way to v6.12-rc6, it works, the bug was introduced
recently making it not able to checking the build-id in the vmlinux
file, as there is nothing to compare it with, no build-id in the
perf.data file.

root@...ber:/home/acme/git/perf-tools# perf -v
perf version 6.12.gb50ecc5aca4d
root@...ber:/home/acme/git/perf-tools# perf record -a sleep 2s
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 2.442 MB perf.data (8953 samples) ]
root@...ber:/home/acme/git/perf-tools# perf -v ; strace -e openat -o /tmp/strace.output perf report -vv |& grep -A5 "^Looking at the vmlinux_path" ; grep '"vmlinux"' -B1 -A10 /tmp/strace.output 
perf version 6.12.gb50ecc5aca4d
Looking at the vmlinux_path (8 entries long)
Using vmlinux for symbols
<SNIP>
root@...ber:/home/acme/git/perf-tools#

So I redid the bisection, this time doing a fresh perf record at each
step and got to:

⬢ [acme@...lbox linux]$ git bisect bad
ae39ba16554eb4a2d97f752847e93aa428438912 is the first bad commit
commit ae39ba16554eb4a2d97f752847e93aa428438912 (HEAD)
Author: Ian Rogers <irogers@...gle.com>
Date:   Mon Sep 9 13:37:37 2024 -0700

    perf inject: Fix build ID injection
    
    Build ID injection wasn't inserting a sample ID and aligning events to
    64 bytes rather than 8. No sample ID means events are unordered and two
    different build_id events for the same path, as happens when a file is
    replaced, can't be differentiated.
    
    Add in sample ID insertion for the build_id events alongside some
    refactoring. The refactoring better aligns the function arguments for
    different use cases, such as synthesizing build_id events without
    needing to have a dso. The misc bits are explicitly passed as with
    callchains the maps/dsos may span user and kernel land, so using
    sample->cpumode isn't good enough.
    
    Signed-off-by: Ian Rogers <irogers@...gle.com>
    Acked-by: Namhyung Kim <namhyung@...nel.org>
    Cc: Adrian Hunter <adrian.hunter@...el.com>
    Cc: Alexander Shishkin <alexander.shishkin@...ux.intel.com>
    Cc: Anne Macedo <retpolanne@...teo.net>
    Cc: Casey Chen <cachen@...estorage.com>
    Cc: Colin Ian King <colin.i.king@...il.com>
    Cc: Ingo Molnar <mingo@...hat.com>
    Cc: Jiri Olsa <jolsa@...nel.org>
    Cc: Kan Liang <kan.liang@...ux.intel.com>
    Cc: Mark Rutland <mark.rutland@....com>
    Cc: Peter Zijlstra <peterz@...radead.org>
    Cc: Sun Haiyong <sunhaiyong@...ngson.cn>
    Link: https://lore.kernel.org/r/20240909203740.143492-2-irogers@google.com
    Signed-off-by: Arnaldo Carvalho de Melo <acme@...hat.com>

⬢ [acme@...lbox linux]$ git tag --contains ae39ba16554eb4a2d97f752847e93aa428438912 | grep ^v6.
v6.12
v6.12-rc1
v6.12-rc2
v6.12-rc3
v6.12-rc4
v6.12-rc5
v6.12-rc6
v6.12-rc7
⬢ [acme@...lbox linux]$

Which matches what Namhyung found. A plain revert doesn't work,
Namhyung's patch below fixes it for me, with it:

# perf -v ; perf record -a sleep 2s ; perf buildid-list | grep 'vmlinux\|kallsyms' ; perf report -vv |& grep -A2 "^Looking at the vmlinux_path"
perf version 6.12.g25425b03a8d7
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 2.095 MB perf.data (3738 samples) ]
55152ddca5da77ca62deb3dd0db105e82b3711e0 [kernel.kallsyms]
Looking at the vmlinux_path (8 entries long)
symsrc__init: build id mismatch for vmlinux.
symsrc__init: cannot get elf header.
#

It refuses that bogus "vmlinux" in the current directory, and since my
machine has no matching vmlinux, it fallbacks to recording the running
kernel build id as "[kernel.kallsyms]" and will use it for resolving
symbols.

If I install the matching vmlinux using 'dnf debuginfo-install kernel':

# perf -v ; perf record -a sleep 2s ; perf report -vv |& grep -A2 "^Looking at the vmlinux_path"
perf version 6.12.g25425b03a8d7
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 2.116 MB perf.data (4278 samples) ]
Looking at the vmlinux_path (8 entries long)
symsrc__init: build id mismatch for vmlinux.
Using /usr/lib/debug/lib/modules/6.11.8-200.fc40.x86_64/vmlinux for symbols
# file /usr/lib/debug/lib/modules/6.11.8-200.fc40.x86_64/vmlinux
/usr/lib/debug/lib/modules/6.11.8-200.fc40.x86_64/vmlinux: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), statically linked, BuildID[sha1]=55152ddca5da77ca62deb3dd0db105e82b3711e0, with debug_info, not stripped
# perf buildid-list -h -k

 Usage: perf buildid-list [<options>]

    -k, --kernel          Show current kernel build id

root@...ber:/home/acme/git/perf-tools# perf buildid-list -k
55152ddca5da77ca62deb3dd0db105e82b3711e0
root@...ber:/home/acme/git/perf-tools#

It will find the right file and use it.

So, for Namhyung's patch below:

Tested-by: Arnaldo Carvalho de Melo <acme@...hat.com>

Now to write another 'perf test' to cover this...

- Arnaldo

> > very strange, then I tried to bisect it, and all the previous versions
> > were producing this:
> > 
> > root@...ber:/home/acme/git/perf-tools# perf -v ; perf report -vv |& grep -A5 "^Looking at the vmlinux_path"
> > perf version 6.12.gb50ecc5aca4d
> > Looking at the vmlinux_path (8 entries long)
> > symsrc__init: build id mismatch for vmlinux.
> > symsrc__init: cannot get elf header.
> > overlapping maps:
> >  ffffffffc034b75c-ffffffffc034b89b 0 bpf_prog_40ddf486530245f5_sd_devices
> >  ffffffffc0000000-ffffffffff000000 7fffc0004000 vmlinux
> > root@...ber:/home/acme/git/perf-tools#
> > 
> > Which is what I got from the perf-tools branch you asked him to pull.
> > 
> > The algorithm in perf is similar to the one in pahole (that stole it
> > from perf):
> > 
> > root@...ber:/home/acme/git/perf-tools# strace -e openat pahole --running_kernel_vmlinux |& tail -12
> > openat(AT_FDCWD, "/sys/kernel/notes", O_RDONLY) = 3
> > openat(AT_FDCWD, "vmlinux", O_RDONLY)   = 3
> > openat(AT_FDCWD, "/boot/vmlinux", O_RDONLY) = -1 ENOENT (No such file or directory)
> > openat(AT_FDCWD, "/boot/vmlinux-6.11.8-200.fc40.x86_64", O_RDONLY) = -1 ENOENT (No such file or directory)
> > openat(AT_FDCWD, "/usr/lib/debug/boot/vmlinux-6.11.8-200.fc40.x86_64", O_RDONLY) = -1 ENOENT (No such file or directory)
> > openat(AT_FDCWD, "/lib/modules/6.11.8-200.fc40.x86_64/build/vmlinux", O_RDONLY) = -1 ENOENT (No such file or directory)
> > openat(AT_FDCWD, "/usr/lib/debug/lib/modules/6.11.8-200.fc40.x86_64/vmlinux", O_RDONLY) = -1 ENOENT (No such file or directory)
> > openat(AT_FDCWD, "/usr/lib/debug/boot/vmlinux-6.11.8-200.fc40.x86_64.debug", O_RDONLY) = -1 ENOENT (No such file or directory)
> > openat(AT_FDCWD, "/root/.cache/debuginfod_client/55152ddca5da77ca62deb3dd0db105e82b3711e0/debuginfo", O_RDONLY) = -1 ENOENT (No such file or directory)
> > pahole: couldn't find a vmlinux that matches the running kernel
> > HINT: Maybe you're inside a container or missing a debuginfo package?
> > +++ exited with 1 +++
> > root@...ber:/home/acme/git/perf-tools#
> > 
> > The one in perf does very much the same:
> > 
> > root@...ber:/home/acme/git/perf-tools# perf -v ; strace -e openat -o /tmp/strace.output perf report -vv |& grep -A5 "^Looking at the vmlinux_path" ; grep '"vmlinux"' -B1 -A10 /tmp/strace.output 
> > perf version 6.12.gb50ecc5aca4d
> > Looking at the vmlinux_path (8 entries long)
> > symsrc__init: build id mismatch for vmlinux.
> > symsrc__init: cannot get elf header.
> > overlapping maps:
> >  ffffffffc034b75c-ffffffffc034b89b 0 bpf_prog_40ddf486530245f5_sd_devices
> >  ffffffffc0000000-ffffffffff000000 7fffc0004000 vmlinux
> > openat(AT_FDCWD, "/root/.debug/.build-id/55/152ddca5da77ca62deb3dd0db105e82b3711e0/elf", O_RDONLY) = -1 ENOENT (No such file or directory)
> > openat(AT_FDCWD, "vmlinux", O_RDONLY)   = 142
> > openat(AT_FDCWD, "/boot/vmlinux", O_RDONLY) = -1 ENOENT (No such file or directory)
> > openat(AT_FDCWD, "/boot/vmlinux-6.11.8-200.fc40.x86_64", O_RDONLY) = -1 ENOENT (No such file or directory)
> > openat(AT_FDCWD, "/usr/lib/debug/boot/vmlinux-6.11.8-200.fc40.x86_64", O_RDONLY) = -1 ENOENT (No such file or directory)
> > openat(AT_FDCWD, "/lib/modules/6.11.8-200.fc40.x86_64/build/vmlinux", O_RDONLY) = -1 ENOENT (No such file or directory)
> > openat(AT_FDCWD, "/usr/lib/debug/lib/modules/6.11.8-200.fc40.x86_64/vmlinux", O_RDONLY) = -1 ENOENT (No such file or directory)
> > openat(AT_FDCWD, "/usr/lib/debug/boot/vmlinux-6.11.8-200.fc40.x86_64.debug", O_RDONLY) = -1 ENOENT (No such file or directory)
> > openat(AT_FDCWD, "/root/.debug/.build-id/55/152ddca5da77ca62deb3dd0db105e82b3711e0/kallsyms", O_RDONLY) = 142
> > openat(AT_FDCWD, "/sys/kernel/notes", O_RDONLY) = 142
> > openat(AT_FDCWD, "/proc/kcore", O_RDONLY) = 142
> > openat(AT_FDCWD, "/proc/kallsyms", O_RDONLY) = 142
> > root@...ber:/home/acme/git/perf-tools# 
> > root@...ber:/home/acme/git/perf-tools# perf buildid-list -h -k
> > 
> >  Usage: perf buildid-list [<options>]
> > 
> >     -k, --kernel          Show current kernel build id
> > 
> > root@...ber:/home/acme/git/perf-tools# perf buildid-list -k
> > 55152ddca5da77ca62deb3dd0db105e82b3711e0
> > root@...ber:/home/acme/git/perf-tools# file vmlinux 
> > vmlinux: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), statically linked, BuildID[sha1]=e86cad482822bd4b4caabb01e7cd00161fd51a38, with debug_info, not stripped
> > root@...ber:/home/acme/git/perf-tools#
> > 
> > And it ends up using /proc/kallsyms
> > 
> > Today I did some bisects, etc, but even with at first reproducing what
> > Linus described, i.e. it used the non-matching vmlinux in the current
> > directory to resolve symbols, I couldn't reproduce it after trying to
> > bisect it :-\
> >  
> > > > So now I need to point "perf report" at the actual image, which I
> > > > didn't need to do before.
> > > 
> > > Ok, I'll try to reproduce it and take a look.
> > 
> > Hope you root cause this, late in this part of the world, going AFK now.
> 
> I think it's a bug in perf record since v6.12.  I found the build-id
> event in the header area is broken.  Can you verify if this works?
> 
> Thanks,
> Namhyung
> 
> ---8<---
> >From 62ebc7de4c306d99f39af847bee4a2aab05b0f93 Mon Sep 17 00:00:00 2001
> From: Namhyung Kim <namhyung@...nel.org>
> Date: Tue, 26 Nov 2024 19:13:31 -0800
> Subject: [PATCH] perf tools: Fix build-id event recording
> 
> The build-id events written at the end of the record session are broken
> due to unexpected data.  The write_buildid() writes the fixed length
> event first and then variable length filename.
> 
> But a recent change made it write more data in the padding area
> accidentally.  So readers of the event see zero-filled data for the
> next entry and treat it incorrectly.   This resulted in wrong kernel
> symbols because the kernel DSO loaded a random vmlinux image in the
> path as it didn't have a valid build-id.
> 
> Fixes: ae39ba16554e ("perf inject: Fix build ID injection")
> Reported-by: Linus Torvalds <torvalds@...ux-foundation.org>
> Signed-off-by: Namhyung Kim <namhyung@...nel.org>
> ---
>  tools/perf/util/build-id.c | 4 ++--
>  1 file changed, 2 insertions(+), 2 deletions(-)
> 
> diff --git a/tools/perf/util/build-id.c b/tools/perf/util/build-id.c
> index 8982f68e7230cd64..e763e8d99a4367d7 100644
> --- a/tools/perf/util/build-id.c
> +++ b/tools/perf/util/build-id.c
> @@ -277,7 +277,7 @@ static int write_buildid(const char *name, size_t name_len, struct build_id *bid
>  	struct perf_record_header_build_id b;
>  	size_t len;
>  
> -	len = sizeof(b) + name_len + 1;
> +	len = name_len + 1;
>  	len = PERF_ALIGN(len, sizeof(u64));
>  
>  	memset(&b, 0, sizeof(b));
> @@ -286,7 +286,7 @@ static int write_buildid(const char *name, size_t name_len, struct build_id *bid
>  	misc |= PERF_RECORD_MISC_BUILD_ID_SIZE;
>  	b.pid = pid;
>  	b.header.misc = misc;
> -	b.header.size = len;
> +	b.header.size = sizeof(b) + len;
>  
>  	err = do_write(fd, &b, sizeof(b));
>  	if (err < 0)
> -- 
> 2.47.0.338.g60cca15819-goog
> 

Powered by blists - more mailing lists