Re: recent intermittent fsx-related failures

[Trond Myklebust <trondmy@hammerspace.com>]

On Fri, 2021-09-24 at 15:30 +0000, Chuck Lever III wrote:
> 
> 
> > On Sep 21, 2021, at 3:00 PM, Trond Myklebust
> > <trondmy@hammerspace.com> wrote:
> > 
> > On Sun, 2021-09-19 at 23:03 +0000, Chuck Lever III wrote:
> > > 
> > > 
> > > > On Jul 23, 2021, at 4:24 PM, Trond Myklebust
> > > > <trondmy@hammerspace.com> wrote:
> > > > 
> > > > On Fri, 2021-07-23 at 20:12 +0000, Chuck Lever III wrote:
> > > > > Hi-
> > > > > 
> > > > > I noticed recently that generic/075, generic/112, and
> > > > > generic/127
> > > > > were
> > > > > failing intermittently on NFSv3 mounts. All three of these
> > > > > tests
> > > > > are
> > > > > based on fsx.
> > > > > 
> > > > > "git bisect" landed on this commit:
> > > > > 
> > > > > 7b24dacf0840 ("NFS: Another inode revalidation improvement")
> > > > > 
> > > > > After reverting 7b24dacf0840 on v5.14-rc1, I can no longer
> > > > > reproduce
> > > > > the test failures.
> > > > > 
> > > > > 
> > > > 
> > > > So you are seeing file metadata updates that end up not
> > > > changing
> > > > the
> > > > ctime?
> > > 
> > > As far as I can tell, a WRITE and two SETATTRs are happening in
> > > sequence to the same file during the same jiffy. The WRITE does
> > > not report pre/post attributes, but the SETATTRs do. The reported
> > > pre- and post- mtime and ctime are all the same value for both
> > > SETATTRs, I believe due to timestamp_truncate().
> > > 
> > > My theory is that persistent-storage-backed filesystems seem to
> > > go slow enough that it doesn't become a significant problem. But
> > > with tmpfs, this can happen often enough that the client gets
> > > confused. And I can make the problem unreproducable if I enable
> > > enough debugging paraphernalia on the server to slow it down.
> > > 
> > > I'm not exactly sure how the client becomes confused by this
> > > behavior, but fsx reports a stale size value, or it can hit a
> > > bus error. I'm seeing at least four of the fsx-based xfs tests
> > > fail intermittently.
> > > 
> > 
> > The client no longer relies on post-op attributes in order to
> > update
> > the metadata after a successful SETATTR. If you look at
> > nfs_setattr_update_inode() you'll see that it picks the values that
> > were set directly from the iattr argument.
> > 
> > The post-op attributes are only used to determine the implicit
> > timestamp updates, and to detect any other updates that may have
> > happened.
> 
> I've been able to directly and repeatedly observe the size attribute
> reverting to a previous value.
> 
> The issue stems from the MM driving a background readahead operation
> at the same time the application truncates or extends the file. The
> READ starts before the size-mutating operation and completes after
> it.
> 
> If the server happens to have done the READ before the size-mutating
> operation, the READ result contains the previous size value. When
> the READ completes, the client overwrites the more recent size
> value with the stale one.
> 
> I'm not yet sure how this relates to
> 
> 7b24dacf0840 ("NFS: Another inode revalidation improvement")
> 
> and maybe it doesn't. "git bisect" with an unreliable reproducer
> generates notoriously noisy data. 
> 

Hmm... That makes sense. If so, the issue is the attributes from the
READ end up tricking nfs_inode_finish_partial_attr_update() into OKing
the update because the ctime ends up looking the same, and so the
client tries to opportunistically revalidate the cache that was (for
some reason) already marked as being invalid.

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