On Tue, 2025-08-12 at 09:58 -0700, Trond Myklebust wrote:
> On Tue, 2025-08-12 at 07:58 -0400, Jeff Layton wrote:
> > On Thu, 2025-07-31 at 17:56 -0400, Trond Myklebust wrote:
> > > On Wed, 2025-07-30 at 10:52 -0400, Jeff Layton wrote:
> > > > We've been seeing a rather nasty bit of data corruption with NFS
> > > > in
> > > > our
> > > > environment. The clients in this env run a patched v6.9 kernel
> > > > (mostly
> > > > due to GPU driver requirements). Most of the patches are NFS
> > > > containerization fixes.
> > > >
> > > > The workload is python scripts writing JSONL files sequentially
> > > > using
> > > > bog-standard buffered write() calls. We're fairly certain that
> > > > userland
> > > > is not seeking so there should be no gaps in the data written.
> > > >
> > > > The problem is that we see ranges of written files being replaced
> > > > by
> > > > NULs. The length of the file seemingly doesn't change from what
> > > > it
> > > > should be, but a chunk of it will be zeroed-out. Looking at the
> > > > offsets
> > > > of the zeroed out ranges, the front part of one page is fine, but
> > > > the
> > > > data from some random offset in the page to the end of the page
> > > > is
> > > > zeroes.
> > > >
> > > > We have a reproducer but we have to run it in a heavily parallel
> > > > configuration to make it happen, so it's evidently a tight race
> > > > of
> > > > some
> > > > sort.
> > > >
> > > > We've turned up some tracepoints and reproduced this twice. What
> > > > we
> > > > see
> > > > in both cases is that the client just doesn't write some section
> > > > of
> > > > the
> > > > file.
> > > >
> > > > In the first trace, there was is a gap of 2201 bytes between
> > > > these
> > > > two
> > > > writes on the wire:
> > > >
> > > > kworker/u1038:1-2597138 [106] ..... 46138.516795:
> > > > nfs_initiate_write: fileid=00:aa:10056165185 fhandle=0x6bd94d55
> > > > offset=53248 count=1895 stable=UNSTABLE
> > > > oil-localfs-252-2605046 [163] ..... 46138.551459:
> > > > nfs_initiate_write: fileid=00:aa:10056165185 fhandle=0x6bd94d55
> > > > offset=57344 count=443956 stable=FILE_SYNC
> > > >
> > > > The zeroed-out range is from 55143-57344. At the same time that
> > > > the
> > > > file is growing from 53248 to 55143 (due to sequential write()
> > > > activity), the client is kicking off writeback for the range up
> > > > to
> > > > 55143. It's issuing 2 writes, one for 0-53248 and one for 53248-
> > > > 55143
> > > > (note that I've filtered out all but one of the DS filehandles
> > > > for
> > > > brevity):
> > > >
> > > > oil-localfs-252-2605046 [162] ..... 46138.516414: nfs_size_grow:
> > > > fileid=00:aa:10056165185 fhandle=0x8bfc64c9
> > > > version=1753485366409158129 cursize=49152 newsize=50130
> > > > oil-localfs-252-2605046 [162] ..... 46138.516593: nfs_size_grow:
> > > > fileid=00:aa:10056165185 fhandle=0x8bfc64c9
> > > > version=1753485366409158129 cursize=50130 newsize=53248
> > > > kworker/u1038:1-2597138 [106] ..... 46138.516740:
> > > > nfs_initiate_write: fileid=00:aa:10056165185 fhandle=0x6bd94d55
> > > > offset=0 count=53248 stable=UNSTABLE
> > > > oil-localfs-252-2605046 [162] ..... 46138.516753: nfs_size_grow:
> > > > fileid=00:aa:10056165185 fhandle=0x8bfc64c9
> > > > version=1753485366409158129 cursize=53248 newsize=55143
> > > > kworker/u1038:1-2597138 [106] ..... 46138.516795:
> > > > nfs_initiate_write: fileid=00:aa:10056165185 fhandle=0x6bd94d55
> > > > offset=53248 count=1895 stable=UNSTABLE
> > > > kworker/u1037:2-2871862 [097] ..... 46138.517659:
> > > > nfs4_pnfs_write:
> > > > error=0 (OK) fileid=00:aa:10056165185 fhandle=0x6bd94d55 offset=0
> > > > count=53248 res=53248 stateid=1:0x79a9c471
> > > > layoutstateid=1:0xcbd8aaad
> > > > kworker/u1037:2-2871862 [097] ..... 46138.517662:
> > > > nfs_writeback_done: error=53248 fileid=00:aa:10056165185
> > > > fhandle=0x6bd94d55 offset=0 count=53248 res=53248 stable=UNSTABLE
> > > > verifier=5199cdae2816c899
> > > > kworker/u1037:5-2593935 [226] ..... 46138.517669:
> > > > nfs4_pnfs_write:
> > > > error=0 (OK) fileid=00:aa:10056165185 fhandle=0x6bd94d55
> > > > offset=53248
> > > > count=1895 res=1895 stateid=1:0x79a9c471
> > > > layoutstateid=1:0xcbd8aaad
> > > > kworker/u1037:5-2593935 [226] ..... 46138.517672:
> > > > nfs_writeback_done: error=1895 fileid=00:aa:10056165185
> > > > fhandle=0x6bd94d55 offset=53248 count=1895 res=1895
> > > > stable=UNSTABLE
> > > > verifier=5199cdae2816c899
> > > > oil-localfs-252-2605046 [162] ..... 46138.518360: nfs_size_grow:
> > > > fileid=00:aa:10056165185 fhandle=0x8bfc64c9
> > > > version=1753485366409158129 cursize=55143 newsize=57344
> > > > oil-localfs-252-2605046 [162] ..... 46138.518556: nfs_size_grow:
> > > > fileid=00:aa:10056165185 fhandle=0x8bfc64c9
> > > > version=1753485366409158129 cursize=57344 newsize=60156
> > > >
> > > > ...and just after writeback completes, we see the file size grow
> > > > from
> > > > 55143 to the end of the page (57344).
> > > >
> > > > The second trace has similar symptoms. There is a lot more
> > > > (smaller)
> > > > write activity (due to memory pressure?). There is a gap of 3791
> > > > bytes
> > > > between these on-the-wire writes, however:
> > > >
> > > > kworker/u1036:0-2339252 [217] ..... 479572.054622:
> > > > nfs_initiate_write: fileid=00:96:10067193438 fhandle=0xc9992232
> > > > offset=221184 count=4401 stable=UNSTABLE
> > > > kworker/u1030:1-2297876 [042] ..... 479572.074194:
> > > > nfs_initiate_write: fileid=00:96:10067193438 fhandle=0xc9992232
> > > > offset=229376 count=261898 stable=UNSTABLE
> > > >
> > > > Same situation -- the at page at offset 53248 has 305 bytes on
> > > > it,
> > > > and
> > > > the remaining is zeroed. This trace shows similar racing write()
> > > > and
> > > > writeback activity as in Friday's trace. At around the same time
> > > > as
> > > > the
> > > > client was growing the file over the affected range, writeback
> > > > was
> > > > kicking off for everything up to the affected range (this has
> > > > some
> > > > other wb related calls filtered for brevity):
> > > >
> > > > oil-localfs-86-727850 [215] ..... 479572.053987:
> > > > nfs_size_grow:
> > > > fileid=00:96:10067193438 fhandle=0x14c40498
> > > > version=1753823598774309300 cursize=217088
> > > > newsize=220572
> > > >
> > > >
> > > > kworker/u1036:8-2339326 [088] ..... 479572.054008:
> > > > nfs_initiate_write: fileid=00:96:10067193438 fhandle=0xc9992232
> > > > offset=217088 count=3484
> > > > stable=UNSTABLE
> > > >
> > > >
> > > > oil-localfs-86-727850 [215] ..... 479572.054405:
> > > > nfs_size_grow:
> > > > fileid=00:96:10067193438 fhandle=0x14c40498
> > > > version=1753823598774309300 cursize=220572
> > > > newsize=221184
> > > >
> > > >
> > > > kworker/u1036:1-2297875 [217] ..... 479572.054418:
> > > > nfs_initiate_write: fileid=00:96:10067193438 fhandle=0xc9992232
> > > > offset=220572 count=612
> > > > stable=UNSTABLE
> > > >
> > > >
> > > > oil-localfs-86-727850 [215] ..... 479572.054581:
> > > > nfs_size_grow:
> > > > fileid=00:96:10067193438 fhandle=0x14c40498
> > > > version=1753823598774309300 cursize=221184
> > > > newsize=225280
> > > >
> > > >
> > > > oil-localfs-86-727850 [215] ..... 479572.054584:
> > > > nfs_size_grow:
> > > > fileid=00:96:10067193438 fhandle=0x14c40498
> > > > version=1753823598774309300 cursize=225280
> > > > newsize=225585
> > > >
> > > >
> > > > kworker/u1036:0-2339252 [217] ..... 479572.054622:
> > > > nfs_initiate_write: fileid=00:96:10067193438 fhandle=0xc9992232
> > > > offset=221184 count=4401
> > > > stable=UNSTABLE
> > > >
> > > >
> > > > oil-localfs-86-727850 [215] ..... 479572.054997:
> > > > nfs_size_grow:
> > > > fileid=00:96:10067193438 fhandle=0x14c40498
> > > > version=1753823598774309300 cursize=225585
> > > > newsize=229376
> > > >
> > > >
> > > > oil-localfs-86-727850 [215] ..... 479572.055190:
> > > > nfs_size_grow:
> > > > fileid=00:96:10067193438 fhandle=0x14c40498
> > > > version=1753823598774309300 cursize=229376
> > > > newsize=230598
> > > >
> > > >
> > > >
> > > > Could this be a race between extending an existing dirty page,
> > > > and
> > > > writeback kicking off for the pre-extension range on the page?
> > > > Maybe
> > > > the client is clearing the dirty bit, thinking that the write
> > > > covers
> > > > the dirty range, but it has an outdated idea about what that
> > > > range is
> > > > or doesn't properly check?
> > > >
> > > > Traces for both events, filtered on the relevant fileid are
> > > > attached.
> > > > I've rolled patches for some new tracepoints that I'm going to
> > > > attempt
> > > > to turn up next, but I thought that this was a good point to
> > > > solicit
> > > > ideas.
> > > >
> > > > Happy to entertain other thoughts or patches!
> > >
> > > So... The fact that we are seeing a nfs_size_grow() for the hole at
> > > offset 55143 means that either an existing request was updated, or
> > > a
> > > new one was created in order to cover that hole, and it must have
> > > been
> > > marked as dirty.
> > >
> > > I'm not seeing anything in the NFS code that can lose that request
> > > without triggering either the nfs_write_error tracepoint, the
> > > nfs_commit_error tracepoint, the nfs_invalidate_folio tracepoint or
> > > else completing the write.
> > >
> > > The only other way I can see this data being lost is if something
> > > is
> > > corrupting folio->private, or if the page cache is somehow managing
> > > to
> > > throw away a dirty folio.
> > > Of the two, there was for a while a netfs bug which would corrupt
> > > folio->private, but I assume you're not using cachefs?
> >
> > After staring at this code a lot, I have a theory. But, it seems like
> > we'd be seeing this a lot more if it were correct, so I must be
> > overlooking something.
> >
> > Here's the scenario:
> >
> > --------------8<--------------
> >
> > Userland has written some of a file and the last folio is not full.
> >
> > Writeback has kicked off for the inode and is successful.
> > nfs_write_completion() calls nfs_page_end_writeback(). That will
> > unlock
> > the nfs_page (clear PG_BUSY) and leave it attached to the folio, and
> > on
> > the commit list.
> >
> > Next a write from userland comes in to extend the file to the end of
> > the page (and beyond). nfs_try_to_update_request() merges the write
> > into the original request and re-marks the page dirty.
> >
> > Later the commit runs successfully and the write verifier matches.
> > nfs_commit_release_pages() runs and nfs_inode_remove_request() is
> > called which detaches the nfs_page from the folio.
> >
> > Eventually, writeback starts up again and the folio is picked up and
> > submitted by nfs_writepages(), but folio->private is now NULL, and
> > it's
> > ignored.
> >
> > But...like I said I feel like we'd hit this all the time if it were
> > possible, even though I don't see what prevents it. If this is a
> > possibility, then the patch may be as simple as something like this?
> >
> > diff --git a/fs/nfs/write.c b/fs/nfs/write.c
> > index bb0e78644ffb..72402208fa33 100644
> > --- a/fs/nfs/write.c
> > +++ b/fs/nfs/write.c
> > @@ -1867,7 +1867,7 @@ static void nfs_commit_release_pages(struct
> > nfs_commit_data *data)
> > * returned by the server against all stored verfs.
> > */
> > if (nfs_write_match_verf(verf, req)) {
> > /* We have a match */
> > - if (folio)
> > + if (folio && !folio_test_dirty(folio))
> > nfs_inode_remove_request(req);
> > dprintk_cont(" OK\n");
> > goto next;
>
> The call to nfs_clear_request_commit() in nfs_join_page_group() should
> be taking care of removing the page before a COMMIT is sent.
>
Got it, thanks. Yeah, that should prevent the commit callback from
touching the page.
> During both the writeback and the commit, the nfs_page is locked, so
> won't be available to be updated by nfs_try_to_update_request().
Yes. I was thinking of the window between the two, but I think you're
right that nfs_clear_request_commit() should prevent the commit from
touching the page after it gets merged in.
Still, the timing of the trace messages suggests that there is race of
some sort:
oil-localfs-161-1326370 [135] ..... 42066.128429: nfs_write_end: fileid=00:82:10087279963 fhandle=0xa6491ad0 version=1754454982197296994 offset=10026 count=2262
oil-localfs-161-1326370 [135] ..... 42066.128429: nfs_update_folio: fileid=00:82:10087279963 fhandle=0xa6491ad0 version=1754454982197296994 offset=1834 count=2262
oil-localfs-161-1326370 [135] ..... 42066.128429: nfs_try_to_update_request: fileid=00:82:10087279963 fhandle=0xa6491ad0 version=1754454982197296994 offset=1834 count=2262
Here it ends up blocked in nfs_lock_request() while the commit runs.
kworker/u1028:3-3432139 [031] ..... 42066.128431: nfs_initiate_commit: fileid=00:82:10087279963 fhandle=0x483d45e0 offset=0 count=0
kworker/u1028:3-3432139 [031] ..... 42066.128435: nfs_initiate_commit: fileid=00:82:10087279963 fhandle=0x7619eec9 offset=0 count=0
kworker/u1028:3-3432139 [031] ..... 42066.128437: nfs_initiate_commit: fileid=00:82:10087279963 fhandle=0xd0cc79e6 offset=0 count=0
kworker/u1037:1-3477598 [226] ..... 42066.129140: nfs_commit_done: error=0 fileid=00:82:10087279963 fhandle=0x7619eec9 offset=0 stable=FILE_SYNC verifier=615487ab86b79ab3
kworker/u1035:0-3302696 [209] ..... 42066.129158: nfs_commit_done: error=0 fileid=00:82:10087279963 fhandle=0x483d45e0 offset=0 stable=FILE_SYNC verifier=a376459679d60091
kworker/u1028:3-3432139 [031] ..... 42066.129163: nfs_commit_done: error=0 fileid=00:82:10087279963 fhandle=0xd0cc79e6 offset=0 stable=FILE_SYNC verifier=ff1ddeecd9737f82
kworker drops the lock, nfs_try_to_update_request() runs to completion and eventually the nfs_size_grow() runs.
oil-localfs-161-1326370 [135] ..... 42066.129179: nfs_size_grow: fileid=00:82:10087279963 fhandle=0xa6491ad0 version=1754454982197296994 cursize=10026 newsize=12288
FWIW, I have a bpftrace script that I'm hoping might give us a bit more
info about why the page didn't get written back when this happens. Just
waiting for some time to run it in our test env.
I'll keep looking!
--
Jeff Layton <jlayton@xxxxxxxxxx>
