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

[Jeff Layton <jlayton@kernel.org>]

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

I've been looking for a couple of days too and haven't spotted any
obvious bugs yet.

> 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?

No, no fscache. Mount options are:

    proto=tcp6,port=20492,vers=4.2,nosharecache,timeo=30,nconnect=16,noresvport

-- 
Jeff Layton <jlayton@kernel.org>