Re: parts of pages on NFS being replaced by swaths of NULs

[Trond Myklebust <trondmy@kernel.org>]

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.

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().

-- 
Trond Myklebust
Linux NFS client maintainer, Hammerspace
trondmy@kernel.org, trond.myklebust@hammerspace.com