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;
