linux-perf-users.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* Bug with 'perf script --symfs'?
@ 2024-07-08  7:50 Ze Xia
  2024-07-12 20:13 ` Namhyung Kim
  0 siblings, 1 reply; 2+ messages in thread
From: Ze Xia @ 2024-07-08  7:50 UTC (permalink / raw)
  To: Peter Zijlstra, Ingo Molnar, Arnaldo Carvalho de Melo,
	Namhyung Kim
  Cc: linux-perf-users

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`.

Kind regards
Ze Xia

^ permalink raw reply	[flat|nested] 2+ messages in thread
end of thread, other threads:[~2024-07-12 20:14 UTC | newest]

Thread overview: 2+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2024-07-08  7:50 Bug with 'perf script --symfs'? Ze Xia
2024-07-12 20:13 ` Namhyung Kim

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).