* Re: 9P change breaks bpftrace running in qemu+9p?
[not found] ` <CAHzjS_vrVJrphZqBMxVE4UEfOqgP8XPq6dRuBh9DdWL-SYtO2w@mail.gmail.com>
@ 2025-10-21 16:56 ` Alexei Starovoitov
2025-10-21 22:12 ` Dominique Martinet
0 siblings, 1 reply; 2+ messages in thread
From: Alexei Starovoitov @ 2025-10-21 16:56 UTC (permalink / raw)
To: Song Liu, Linux-Fsdevel, Christian Brauner
Cc: Tingmao Wang, Dominique Martinet, v9fs, Eric Van Hensbergen,
Latchesar Ionkov, Christian Schoenebeck, Mickaël Salaün,
bpf
On Mon, Oct 20, 2025 at 11:49 PM Song Liu <song@kernel.org> wrote:
>
> Hi Tingmao,
>
> On Mon, Oct 20, 2025 at 5:54 PM Tingmao Wang <m@maowtm.org> wrote:
> >
> > On 10/20/25 22:52, Song Liu wrote:
> > > Hi Dominique,
> > >
> > > On Mon, Oct 20, 2025 at 2:32 PM Dominique Martinet
> > > <asmadeus@codewreck.org> wrote:
> > >>
> > >> Song Liu wrote on Mon, Oct 20, 2025 at 12:40:23PM -0700:
> > >>> I am running qemu 9.2.0 and bpftrace v0.24.0. I don't think anything is
> > >>> very special here.
> > >>
> > >> I don't reproduce either (qemu 9.2.4 and bpftrace v0.24.1, I even went
> > >> and installed vmtest to make sure), trying both my branch and a pristine
> > >> v6.18-rc2 kernel -- what's the exact commit you're testing and could you
> > >> attach your .config ?
> > >
> > > Attached, please find the config file.
> > >
> > > I tried to debug this, and found that the issue disappears when I remove
> > > v9fs_lookup_revalidate from v9fs_dentry_operations. But I couldn't figure
> > > out why d_revalidate() is causing such an issue.
> >
> > I've compiled qemu 9.2.0 and download the binary build of bpftrace v0.24.0
> > from GitHub [1], and compiled kernel with your config, but unfortunately I
> > still can't reproduce it...
>
> Thanks for running these tests.
>
> > I do now get this message sometimes (probably unrelated?):
> > bpftrace (148) used greatest stack depth: 11624 bytes left
> >
> > I don't really know how to proceed right now but I will have it run in a
> > loop and see if I can hit it by chance.
> >
> > If you can reproduce it frequently and can debug exactly what is returning
> > -EIO in v9fs_lookup_revalidate that would probably be very helpful, or if
> > you can enable 9p debug outputs and see what's happening around the time
> > of error (CONFIG_NET_9P_DEBUG=y and also debug=5 mount options - I'm not
> > sure how to get vmtest to use a custom mount option but if it's
> > reproducible in plain QEMU that's also an option) that might also be
> > informative I think? I'm happy to take a deeper look (although I'm of
> > course less of an expert than Dominique so hopefully he can also give some
> > opinion).
> >
> > I'm also curious if this can happen with just a usual `stat` or other
> > operations (not necessarily caused by dentry revalidation, and thus not
> > necessarily to do with my patch)
>
> I used strace to compare the behavior before and after the change.
> It appears to me that bpftrace didn't get -EIO in the error case. Instead,
> it got 0 bytes for a read that was supposed to return data.
>
> Success case:
> ...
> openat(AT_FDCWD, "/tmp/bpftrace.Rl1Vkg",
> O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0600) = 3
> write(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\1\0\367\0\1\0\0\0\0\0\0\0\0\0\0\0"...,
> 4352) = 4352
> openat(AT_FDCWD, "/tmp/bpftrace.Rl1Vkg", O_RDONLY|O_CLOEXEC) = 4
> newfstatat(4, "", {st_mode=S_IFREG|0600, st_size=4352, ...}, AT_EMPTY_PATH) = 0
> read(4, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\1\0\367\0\1\0\0\0\0\0\0\0\0\0\0\0"...,
> 8192) = 4352
> close(4) = 0
> ...
>
> Failure case:
> ...
> openat(AT_FDCWD, "/tmp/bpftrace.LbbDxk",
> O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0600) = 3
> write(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\1\0\367\0\1\0\0\0\0\0\0\0\0\0\0\0"...,
> 4352) = 4352
> openat(AT_FDCWD, "/tmp/bpftrace.LbbDxk", O_RDONLY|O_CLOEXEC) = 4
> newfstatat(4, "", {st_mode=S_IFREG|0600, st_size=0, ...}, AT_EMPTY_PATH) = 0
> read(4, "", 8192) = 0
> ...
>
> So the failure case is basically:
> 1) open a file for write, and write something;
> 2) open the same file for read, and read() returns 0.
>
> I created a small program to reproduce this issue (attached below).
>
> Before [1], the program can read the data on the first read():
> [root@(none) ]# ./main xxx
> i: 0, read returns 4096
> i: 1, read returns 0
> i: 2, read returns 0
> i: 3, read returns 0
> i: 4, read returns 0
> i: 5, read returns 0
> i: 6, read returns 0
> i: 7, read returns 0
> i: 8, read returns 0
> i: 9, read returns 0
>
> After [1], the program cannot read the data, even after retry:
> [root@(none) ]# ./main yyy
> i: 0, read returns 0
> i: 1, read returns 0
> i: 2, read returns 0
> i: 3, read returns 0
> i: 4, read returns 0
> i: 5, read returns 0
> i: 6, read returns 0
> i: 7, read returns 0
> i: 8, read returns 0
> i: 9, read returns 0
>
> I am not sure what is the "right" behavior in this case. But this is
> clearly a change of behavior.
>
> Thanks,
> Song
>
> [1] https://lore.kernel.org/v9fs/cover.1743956147.git.m@maowtm.org/
>
>
>
> ================ reproducer ==================
>
> #include <fcntl.h>
> #include <stdio.h>
> #include <stdlib.h>
> #include <unistd.h>
>
> char buf[4096];
>
> int main(int argc, char *argv[])
> {
> int ret, i;
> int fdw, fdr;
>
> if (argc < 2)
> return 1;
>
> fdw = openat(AT_FDCWD, argv[1], O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0600);
> if (fdw < 0) {
> fprintf(stderr, "cannot open fdw\n");
> return 1;
> }
> write(fdw, buf, sizeof(buf));
>
> fdr = openat(AT_FDCWD, argv[1], O_RDONLY|O_CLOEXEC);
>
> if (fdr < 0) {
> fprintf(stderr, "cannot open fdr\n");
> close(fdw);
> return 1;
> }
>
> for (i = 0; i < 10; i++) {
> ret = read(fdr, buf, sizeof(buf));
> fprintf(stderr, "i: %d, read returns %d\n", i, ret);
> }
>
> close(fdr);
> close(fdw);
> unlink(argv[1]);
> return 0;
> }
Andrii reported the issue as well:
https://lore.kernel.org/bpf/CAEf4BzZbCE4tLoDZyUf_aASpgAGFj75QMfSXX4a4dLYixnOiLg@mail.gmail.com/
selftests/bpf was relying on the above behavior too
which we adjusted already, but
this looks to be a regression either in 9p or in vfs.
^ permalink raw reply [flat|nested] 2+ messages in thread