Re: Bug with 'perf script --symfs'?

[Namhyung Kim <namhyung@kernel.org>]

Hello,

On Mon, Jul 08, 2024 at 03:50:17PM +0800, Ze Xia wrote:
> Hi,
> 
> I think I found that `perf script --symfs` option and automatic namespace attaching seems to conflict.
> 
> Environment: kernel version `6.5.0-41-generic`, distribution `ubuntu22.04`, arch `x86_64`
> 
> Behavior: In `perf script`, if a process is inside another namespace than the default (e.g. inside a docker container), perf script will try to attach to that namespace to read debug info. However, if `--symfs` option is provided, then it will search for debug files with `symfs` prefix *inside the namespace*. Usually the symfs directory isn't present in the namespace, thus I see this behavior as inappropriate.
> 
> To reproduce: I run commands below on a ubuntu machine with docker installed. Any glibc based distro without musl installed should also reproduce the issue, as musl isn't present at host but present in the docker container.
> 
> In one terminal (create the process to be profiled):
> 
>     $ docker run -it --rm --name test-symfs --net=host alpine
>     # now we're inside the container
>     $ apk add musl-dbg
>     $ dd if=/dev/zero of=/dev/null
>     # it stucks here, don't kill it yet
> 
> In another terminal (profiling):
> 
>     $ perf record -a -g sleep 1
>     $ perf script > success.perf
>     $ grep musl success.perf | head -n 10
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
> 
> Thanks to automatic namespace attaching, this works. Problem comes with `--symfs` option:
> 
>     $ docker cp test-symfs:/ ./symfs
>     $ perf script --symfs ./symfs > fail.perf
>     $ grep musl fail.perf | head -n 10
>             75fbf5143992 [unknown] (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 [unknown] (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 [unknown] (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 [unknown] (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 [unknown] (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 [unknown] (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 [unknown] (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 [unknown] (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 [unknown] (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 [unknown] (/lib/ld-musl-x86_64.so.1)
> 
> We can't find the symbol any more.
> 
> Rerun the `perf script` with `strace`:
> 
>     $ strace -o fail.strace perf script --symfs ./symfs > fail.perf
>     $ grep musl fail.strace | grep stat
>     newfstatat(AT_FDCWD, "./symfs//lib/ld-musl-x86_64.so.1", 0x7ffce53b7030, 0) = -1 ENOENT (No such file or directory)
>     newfstatat(AT_FDCWD, "./symfs//lib/ld-musl-x86_64.so.1", 0x7ffce53b2140, 0) = -1 ENOENT (No such file or directory)
>     newfstatat(AT_FDCWD, "./symfs//usr/lib/debug/lib/ld-musl-x86_64.so.1.debug", 0x7ffce53b41a0, 0) = -1 ENOENT (No such file or directory)
>     newfstatat(AT_FDCWD, "./symfs//usr/lib/debug/lib/ld-musl-x86_64.so.1", 0x7ffce53b41a0, 0) = -1 ENOENT (No such file or directory)
>     newfstatat(AT_FDCWD, "./symfs//lib/ld-musl-x86_64.so.1", 0x7ffce53b41a0, 0) = -1 ENOENT (No such file or directory)
>     newfstatat(AT_FDCWD, "./symfs//lib/.debug/ld-musl-x86_64.so.1", 0x7ffce53b41a0, 0) = -1 ENOENT (No such file or directory)
> 
> Note how `./symfs/` is included in all those calls.
> 
> Rerun the success case with strace:
> 
>     $ strace -o success.strace perf script > success.perf
>     $ grep musl success.strace | grep stat
>     newfstatat(AT_FDCWD, "/lib/ld-musl-x86_64.so.1", {st_mode=S_IFREG|0755, st_size=649832, ...}, 0) = 0
>     newfstatat(AT_FDCWD, "ld-musl-x86_64.so.1.debug", 0x7ffe0949a350, 0) = -1 ENOENT (No such file or directory)
>     newfstatat(AT_FDCWD, "/lib/ld-musl-x86_64.so.1.debug", 0x7ffe0949a350, 0) = -1 ENOENT (No such file or directory)
>     newfstatat(AT_FDCWD, "/lib/.debug/ld-musl-x86_64.so.1.debug", 0x7ffe0949a350, 0) = -1 ENOENT (No such file or directory)
>     newfstatat(AT_FDCWD, "/usr/lib/debug/lib/ld-musl-x86_64.so.1.debug", {st_mode=S_IFREG|0755, st_size=2892848, ...}, 0) = 0
>     newfstatat(AT_FDCWD, "/usr/lib/debug/lib/ld-musl-x86_64.so.1.debug", {st_mode=S_IFREG|0755, st_size=2892848, ...}, 0) = 0
> 
> Note that the calls without `./symfs/` worked, because perf is inside the container's namespace.
> 
> To prove that our symfs indeed contains the debug info, we can stop the `dd` command inside docker and rerun `perf script` without `--symfs` option, it also succeeds:
> 
>     $ strace -o success2.strace perf script --symfs ./symfs > success2.perf
>     $ grep musl success2.perf | head -n 10
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>             75fbf5143992 __cp_end+0x0 (/lib/ld-musl-x86_64.so.1)
>     $ grep musl success2.strace | grep stat
>     newfstatat(AT_FDCWD, "./symfs//lib/ld-musl-x86_64.so.1", 0x7ffe14d3d6a0, 0) = -1 ENOENT (No such file or directory)
>     newfstatat(AT_FDCWD, "./symfs//lib/ld-musl-x86_64.so.1", {st_mode=S_IFREG|0755, st_size=649832, ...}, 0) = 0
>     newfstatat(AT_FDCWD, "ld-musl-x86_64.so.1.debug", 0x7ffe14d387a0, 0) = -1 ENOENT (No such file or directory)
>     newfstatat(AT_FDCWD, "./symfs//lib/ld-musl-x86_64.so.1.debug", 0x7ffe14d387a0, 0) = -1 ENOENT (No such file or directory)
>     newfstatat(AT_FDCWD, "./symfs//lib/.debug/ld-musl-x86_64.so.1.debug", 0x7ffe14d387a0, 0) = -1 ENOENT (No such file or directory)
>     newfstatat(AT_FDCWD, "/usr/lib/debug./symfs//lib/ld-musl-x86_64.so.1.debug", 0x7ffe14d387a0, 0) = -1 ENOENT (No such file or directory)
>     newfstatat(AT_FDCWD, "./symfs//usr/lib/debug/lib/ld-musl-x86_64.so.1.debug", {st_mode=S_IFREG|0755, st_size=2892848, ...}, 0) = 0
>     newfstatat(AT_FDCWD, "./symfs//usr/lib/debug/lib/ld-musl-x86_64.so.1", 0x7ffe14d3a810, 0) = -1 ENOENT (No such file or directory)
>     newfstatat(AT_FDCWD, "./symfs//lib/ld-musl-x86_64.so.1", {st_mode=S_IFREG|0755, st_size=649832, ...}, 0) = 0
> 
> As the `dd` process is dead now, `perf script` will not attach to its namespace. It reads debug info from our symfs, and it worked.
> 
> Expected Behavior: `symfs` is prefixed only if no namespace attaching happened. Or, to be conversative, try twice, with or without `--symfs`.

I'm not sure if it's the reasonable expectation.  With --symfs, you can
expect it will prefix the path to all DSO paths.  The namespace makes
things complicated but I think the symfs behaivor is simple.  There's no
guarantee if the symfs is always out of the namespace, right?

Thanks,
Namhyung