Re: fstests generic/465 failures on NFS

[Trond Myklebust <trondmy@hammerspace.com>]

On Wed, 2024-01-10 at 09:30 -0500, Jeff Layton wrote:
> I've been seeing some failures of generic/465 across all NFS versions
> for a long time. I finally had some time to track down the cause, but
> I'm not quite sure whether it's fixable.
> 
> The test failures usually look like this (though often at a random
> offset):
> 
> SECTION       -- default
> FSTYP         -- nfs
> PLATFORM      -- Linux/x86_64 kdevops-nfs-default 6.7.0-g2f76af849100
> #80 SMP PREEMPT_DYNAMIC Wed Jan 10 06:33:59 EST 2024
> MKFS_OPTIONS  -- kdevops-nfsd:/export/kdevops-nfs-default-fstests-s
> MOUNT_OPTIONS -- -o context=system_u:object_r:root_t:s0 kdevops-
> nfsd:/export/kdevops-nfs-default-fstests-s /media/scratch
> 
> generic/465 8s ... - output mismatch (see /data/fstests-
> install/xfstests/results/kdevops-nfs-default/6.7.0-
> g2f76af849100/default/generic/465.out.bad)
>     --- tests/generic/465.out	2024-01-10 06:39:53.500389434 -0500
>     +++ /data/fstests-install/xfstests/results/kdevops-nfs-
> default/6.7.0-g2f76af849100/default/generic/465.out.bad	2024-01-10
> 08:57:00.536146701 -0500
>     @@ -1,3 +1,4 @@
>      QA output created by 465
>      non-aio dio test
>     +encounter an error: block 117 offset 0, content 0
>      aio-dio test
>     ...
>     (Run 'diff -u /data/fstests-
> install/xfstests/tests/generic/465.out /data/fstests-
> install/xfstests/results/kdevops-nfs-default/6.7.0-
> g2f76af849100/default/generic/465.out.bad'  to see the entire diff)
> Ran: generic/465
> Failures: generic/465
> Failed 1 of 1 tests
> 
> The test kicks off a thread that tries to read the file using DIO
> while
> the parent task writes 1M blocks of 'a' to it sequentially using DIO.
> It
> expects that the reader will always see 'a' in the read result, or a
> short read. In the above case, it got back a read with '\0' in it.
> 
> The blocks in this test are 1M, so this block starts at offset
> 122683392. Looking at a capture, I caught this:
> 
> 65161  40.392338 192.168.122.173 → 192.168.122.227 NFS 3702 V4 Call
> WRITE StateID: 0x9e68 Offset: 123207680 Len: 524288 ; V4 Call
> READ_PLUS StateID: 0x9e68 Offset: 122683392 Len: 524288  ; V4 Call
> READ_PLUS StateID: 0x9e68 Offset: 123207680 Len: 524288
> 65171  40.393230 192.168.122.173 → 192.168.122.227 NFS 3286 V4 Call
> WRITE StateID: 0x9e68 Offset: 122683392 Len: 524288
> 65172  40.393401 192.168.122.227 → 192.168.122.173 NFS 182 V4 Reply
> (Call In 65161) WRITE
> 65181  40.394844 192.168.122.227 → 192.168.122.173 NFS 6794 V4 Reply
> (Call In 65161) READ_PLUS
> 65195  40.395506 192.168.122.227 → 192.168.122.173 NFS 6794 V4 Reply
> (Call In 65161) READ_PLUS
> 
> It looks like the DIO writes got reordered here so the size of the
> file
> probably increased briefly before the second write got processed, and
> the read_plus got processed in between the two.
> 
> While we might be able to force the client to send the WRITEs in
> order
> of increasing offset in this situation, the server is under no
> obligation to process concurrent RPCs in any particular order. I
> don't
> think this is fundamentally fixable due to that.
> 
> Am I wrong? If not, then I'll plan to send an fstests patch to skip
> this
> test on NFS.

This is an issue that we've known about for a while now. I regularly
see this test failing, and it is indeed because we do not serialise
reads vs writes in O_DIRECT. Until someone describes an application
that relies on that behaviour to, I'd prefer to avoid having to call
inode_dio_wait(inode) on the off chance that someone is doing an
O_DIRECT read from the same set of data that they are doing an O_DIRECT
write to.

IOW: I'd be happy to see us just skip that test.

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