by Nix

[permalink] [raw]

Subject: Re: steam-associated reproducible hard NFSv4.2 client hang (5.9, 5.10)

On 2 Apr 2021, [email protected] said:
> Sorry, did you say whether nfsd threads or rpc.mountd are blocked?

... just about to switch into debugging this, but it does seem to me
that if nfsd threads or (especially) mountd on the server side were
blocked, I'd see misbehaviour with mounts from every client, not just a
few of them. This doesn't happen.

While this is going on, my firewall and other clients not engaging in
the problematic Steam-related activity can talk NFSv4 to the server
perfectly happily: indeed this is actually a problem when debugging
because I have to quiesce the bloody things as much as I can to stop
their RPC traffic flooding the log with irrelevant junk :)

Recovery from this consists only of rebooting the stuck client: the
server and all other clients don't need touching (indeed, I'm typing
this in an emacs on that server, and since it was last rebooted it's
been hit by a client experiencing this hang at least five times: the
mailserver also keeps its mailspool on that server as well, and no
problems there either).

(The server also has fairly silly amounts of RAM compared to the load
it's placed under. I'm not concerned about the possibility of rpc.mountd
getting swapped out. It just doesn't happen. Even things like git gc of
the entire Chromium git repo proceed without swapping.)

btw, the filesystem layout on this machine is, in part:

/dev/main/root xfs 4294993920 738953092 3556040828 18% /
/dev/mapper/main-vms xfs 1073231868 406045460 667186408 38% /vm
/dev/mapper/main-steam ext4 1055852896 85367140 916781564 9% /pkg/non-free/steam
/dev/mapper/main-archive xfs 3219652608 2761922796 457729812 86% /usr/archive
/dev/mapper/main-pete xfs 2468405656 2216785448 251620208 90% /usr/archive/music/Pete
/dev/mapper/main-phones xfs 52411388 4354092 48057296 9% /.nfs/nix/share/phones
/dev/mapper/main-unifi xfs 10491804 1130228 9361576 11% /var/lib/unifi
/dev/mapper/oracrypt-plain 2147510784 144030636 2003480148 7% /home/oranix/oracle/private

... and you'll note that the exported fs I'm seeing hangs on is actually
*not* the $HOME on the root fs: it's /pkg/non-free/steam, which is ext4
purely because so many games on x86 still fail horribly when 64-bit
inodes are used, and ext4 can emit 32-bit inodes on biggish fses without
horrible performance consequences, unlike xfs. The relevant import line:

loom:/pkg/non-free/steam/.steam /home/nix/.steam nfs defaults,_netdev

(so it is imported to *subdirectory* of a directory which is a mounted
NFS export, and *that* one is exported from /). The hang also happens
when using nfusr as the NFS client for the .steam import, so whatever it
is isn't just down to the client...

The primary reason I'm using one big fs for almost everything on this
server build is, uh, NFSv4. My last machine had lots of little
filesystems, and the result somehow confused the NFS pseudoroot
construction process so badly that most of the things I tried to export
never appeared on NFSv4, only on v3: only those exports which *were* on
the root filesystem were ever available for NFSv4 mounting, so I was
stuck with v3 on that machine. At (IIRC) Chuck Lever's suggestion (many
years ago, so he probably won't remember) I varied things when I built a
new server and was happy to find that with a less baroque setup and a
bigger rootfs with more stuff on it, NFSv4 seemed perfectly happy and
the pseudoroot was populated fine.

OK let's collect some logs so we're not reasoning in the absence of data
any more. Back soon! (I hope.)

2021-04-06 05:06:29

by Nix

[permalink] [raw]

Subject: Re: steam-associated reproducible hard NFSv4.2 client hang (5.9, 5.10)

[linux-net added: a stubborn NFS client hang doing uncompression of some
Steam games over NFS now looks like it might be TCP-stack or even
network-device-related rather than NFS-related]

On 24 Feb 2021, [email protected] said:

> On Tue, Feb 23, 2021 at 11:58:51PM +0000, Trond Myklebust wrote:
>> On Tue, 2021-02-23 at 17:57 -0500, J. Bruce Fields wrote:
>> > On Sun, Jan 03, 2021 at 02:27:51PM +0000, Nick Alcock wrote:
>> > > Relevant exports, from /proc/fs/nfs/exports:
>> > >
>> > > / 192.168.16.0/24,silk.wkstn.nix(ro,insecure,no_root_squash,s
>> > > ync,no_wdelay,no_subtree_check,v4root,fsid=0,uuid=0a4a4563:00764033
>> > > :8c827c0e:989cf534,sec=390003:390004:390005:1)
>> > > /home/.loom.srvr.nix *.srvr.nix,fold.srvr.nix(rw,root_squash,syn
>> > > c,wdelay,no_subtree_check,uuid=0a4a4563:00764033:8c827c0e:989cf534,
>> > > sec=1)
>>
>> Isn't that trying to export the same filesystem as '/' on the line
>> above using conflicting export options?
>
> Yes, and exporting something on the root filesystem is generally a bad
> idea for the usual reasons.
>
> I don't see any explanation for the write hang there, though.
>
> Unless maybe if it leaves mountd unable to answer an upcall for some
> reason, hm.
>
> I think that would show up in /proc/net/rpc/nfsd.fh/content. Try
> cat'ing that file after 'rpcdebug -m rpc -s cache' and that should show
> if there's an upcall that's not getting answered.

OK, I got some debugging: this is still happening on 5.11, but it's
starting to look more like a problem below NFS.

There are no unanswered upcalls, and though I did eventually manage to
get a multimegabyte pile of NFS debugging info (after fighting with the
problem that the Steam client has internal timeouts that are silently
exceeded and break things if you just leave debugging on)... I suspect I
don't need to bother you with it, because the packet capture was more
informative.

I have a complete capture of everything on the wire from the moment
Steam started, but it's nearly 150MiB xz'ed and includes a lot of boring
nonsense related to Steam's revalidation of everything because the last
startup crashed: it probably also includes things like my Steam account
password, getdents of my home directory etc so if you want that I can
send you the details privately: but this capture of only the last few
thousand NFS packets is interesting enough:
<http://www.esperi.org.uk/~nix/temporary/nfs-trouble.cap>.

Looking at this in Wireshark, everything goes fine (ignoring the usual
offloading-associated checksum whining) until packet 1644, when we
suddenly start seeing out-of-order packets and retransmissions (on an
otherwise totally idle 10GbE subnet). They get more and more common, and
at packet 1711 the client loses patience and hits the host with a RST.
This is... not likely to do NFS any good at all, and with $HOME served
over the same connection I'm not surprised the client goes fairly
unresponsive after that and the hangcheck timer starts screaming about
processes blocked on I/O to some of the odder filesystems I'm getting
over NFS on that client, like /var/tmp and /var/account/acct (so, yes,
all process termination likely blocks forever on this). So it looks like
NFS is being betrayed by TCP and/or some lower layer. (Also, NFS doesn't
seem to try too hard to recover -- or perhaps, when it does, the new
session goes just as wrong).

The socket statistics on the server report 22 rx drops since boot (out
of 11903K) and no errors of any kind: possibly each of these drops
corresponds to the test runs I've been doing, but there can't be more
than one or two drops per test (I must have crashed the client over ten
times trying to get dumps) which if true seems more fragile than I
expect NFS to be :) so they might well just be coincidental.

I simplified my network for this test run, so the link has literally no
hosts on it right now other than the NFS server and client at issue and
a 10GbE Netgear GS110EMX switch, which reports zero errors and no
packets dropped since it was rebooted months ago. Both ends are the same
Intel X540-AT2 driven by ixgbe. The network cabling has never given me
the least cause for concern, and I've never seen things getting hit by
RSTs when talking to this host before. I've certainly never seen *NFS*
getting a RST. It happens consistently, anyway, which argues strongly
against the cabling :)

Neither client nor server are using any sort of iptables (it's not even
compiled in), and while the server is doing a bit of policy-based
routing and running a couple of bridges for VMs it's not doing anything
that should cause this (and this was replicated when the bridges had
nothing on them other than the host in any case). Syncookies are
compiled out on both hosts (they're still on on the firewall, but that's
not participating in this and isn't even on the same subnet).

Just in case: complete network-related sysctls changed from default on
the client:

net.ipv6.conf.default.keep_addr_on_down = 1

and on the server:

net.ipv4.ip_forward = 1
net.ipv6.conf.all.forwarding = 1
net.ipv6.conf.default.keep_addr_on_down = 1
net.ipv4.ping_group_range = 73 73
net.core.bpf_jit_enable = 1

None of these seem too likely to cause *this*. I wonder how I could
track down where this mess is coming from...