* NFS server misbehaving (nfsd eats CPU and returns no data)
@ 2012-05-07 22:44 parafin
2012-08-21 17:43 ` J. Bruce Fields
0 siblings, 1 reply; 6+ messages in thread
From: parafin @ 2012-05-07 22:44 UTC (permalink / raw)
To: linux-nfs
[-- Attachment #1: Type: text/plain, Size: 2267 bytes --]
Hello.
I'm having a problem with my NFS share. It's been present for some time
now, kernel versions got upgraded, setup has been changed, but since I
can't remember for sure when it started, I'll just describe my current
configuration. But first the problem itself.
Periodically (I would say every GB of data or so) reads from NFS share
hang during which nfsd kernel thread on server eats CPU but no data
gets sent to the client. After a minute everything comes to norm again
(no action on my part is required). First thing I did to debug this is
I enabled verbose output in all userspace daemons both on client and
server - it produced no output whatsoever during the problematic period
of time. Next I dumped network traffic on TCP port 2049 both on client
and server - there was no packet drops or any other strange stuff,
except that client restarted the TCP connection to 2049 port after a
minute of silence from server (which resulted in data flowing again).
This was confirmed by kernel debug output from client (echo 65535 | tee
nfs_debug nfsd_debug nlm_debug rpc_debug) - NFS client sent a server
READ request with 60 seconds timeout, timeout was reached and resulted
in dropping and restarting of NFS TCP connection. So this points to NFS
server kernel code. Kernel debug output on server is quite large and
spikes during the hangs - I've attached deduplicated (by hand) version
of it to this email. I couldn't find anything strange in there, but I
don't understand most of it anyway.
My current setup - both server and client are Linux 3.3.3, NFSv4 with
sec=krb5, it runs through local network 192.168.0.0/24 with no
firewalls (client has iptables disabled in kernel, server ACCEPTs
everything from internal interface). Client uses Wi-Fi, server -
Ethernet with VLANs, so traffic goes through AP. But since network dumps
on server and client are the same, network configuration IMHO is
irrelevant, I just added it for fullness of description. Most common
usage (and test case) of this NFS share is watching some videos using
mplayer. Underlying filesystem is XFS (though ext4 is used for other
shares on the same server).
I'm ready to provide additional information or test some patches, since
this problem is quite annoying (and IMHO got worse with time).
[-- Attachment #2: nfs_debug.syslog --]
[-- Type: application/octet-stream, Size: 27548 bytes --]
May 07 19:43:56 [kernel] svc: server c5108000, pool 0, transport f2cf3000, inuse=2
May 07 19:43:56 [kernel] svc: tcp_recv f2cf3000 data 1 conn 0 close 0
May 07 19:43:56 [kernel] svc: socket f2cf3000 recvfrom(f2cf31d8, 0) = 4
May 07 19:43:56 [kernel] svc: TCP record, 176 bytes
May 07 19:43:56 [kernel] svc: socket f2cf3000 recvfrom(c6ca60b0, 3920) = 176
May 07 19:43:56 [kernel] svc: TCP complete record (176 bytes)
May 07 19:43:56 [kernel] svc: got len=176
May 07 19:43:56 [kernel] svc: svc_authenticate (6)
May 07 19:43:56 [kernel] RPC: svcauth_gss: argv->iov_len = 148
May 07 19:43:56 [kernel] RPC: gss_verify_mic_v2
May 07 19:43:56 [kernel] RPC: gss_get_mic_v2
May 07 19:43:56 [kernel] RPC: Want update, refage=120, age=110
May 07 19:43:56 [kernel] svc: calling dispatcher
May 07 19:43:56 [kernel] nfsd_dispatch: vers 4 proc 1
May 07 19:43:56 [kernel] nfsv4 compound op #1/2: 22 (OP_PUTFH)
May 07 19:43:56 [kernel] nfsd: fh_verify(32: 81060001 76ec352c e245ec13 557836b4 784ef9e3 cb8dd809)
May 07 19:43:56 [kernel] nfsv4 compound op c685b050 opcnt 2 #1: 22: status 0
May 07 19:43:56 [kernel] nfsv4 compound op #2/2: 25 (OP_READ)
May 07 19:43:56 [kernel] renewing client (clientid 4fa7ddc0/00000017)
May 07 19:43:56 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=0
- Last output repeated 4 times -
May 07 19:43:56 [kernel] nfsv4 compound op c685b050 opcnt 2 #2: 25: status 0
May 07 19:43:56 [kernel] nfsv4 compound returned 0
May 07 19:43:56 [kernel] svc: socket f2cf3000 sendto([d843d000 92... ], 524380) = 524380 (addr 192.168.0.4, port=944)
May 07 19:43:56 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:43:56 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=0
- Last output repeated 282 times -
everything is fine up to this point
May 07 19:44:19 [kernel] svc: socket f31fdf80 TCP data ready (svsk f2cf3000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 served by daemon c5108000
May 07 19:44:19 [kernel] svc: socket f31fdf80 TCP data ready (svsk f2cf3000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f31fdf80 TCP data ready (svsk f2cf3000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f31fdf80 TCP data ready (svsk f2cf3000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f31fdf80 TCP data ready (svsk f2cf3000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f31fdf80 TCP data ready (svsk f2cf3000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f31fdf80 TCP data ready (svsk f2cf3000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f31fdf80 TCP data ready (svsk f2cf3000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f31fdf80 TCP data ready (svsk f2cf3000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f31fdf80 TCP data ready (svsk f2cf3000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: server c5108000, pool 0, transport f2cf3000, inuse=2
May 07 19:44:19 [kernel] svc: tcp_recv f2cf3000 data 1 conn 0 close 0
May 07 19:44:19 [kernel] svc: socket f2cf3000 recvfrom(f2cf31d8, 0) = 4
May 07 19:44:19 [kernel] svc: TCP record, 176 bytes
May 07 19:44:19 [kernel] svc: socket f2cf3000 recvfrom(c6ca60b0, 3920) = 176
May 07 19:44:19 [kernel] svc: TCP complete record (176 bytes)
May 07 19:44:19 [kernel] svc: got len=176
May 07 19:44:19 [kernel] svc: transport f2cf3000 put into queue
May 07 19:44:19 [kernel] svc: svc_authenticate (6)
May 07 19:44:19 [kernel] RPC: svcauth_gss: argv->iov_len = 148
May 07 19:44:19 [kernel] RPC: gss_verify_mic_v2
May 07 19:44:19 [kernel] RPC: gss_get_mic_v2
May 07 19:44:19 [kernel] RPC: Want update, refage=120, age=0
May 07 19:44:19 [kernel] svc: calling dispatcher
May 07 19:44:19 [kernel] nfsd_dispatch: vers 4 proc 1
May 07 19:44:19 [kernel] nfsv4 compound op #1/2: 22 (OP_PUTFH)
May 07 19:44:19 [kernel] nfsd: fh_verify(32: 81060001 76ec352c e245ec13 557836b4 784ef9e3 cb8dd809)
May 07 19:44:19 [kernel] nfsv4 compound op c685b050 opcnt 2 #1: 22: status 0
May 07 19:44:19 [kernel] nfsv4 compound op #2/2: 25 (OP_READ)
May 07 19:44:19 [kernel] renewing client (clientid 4fa7ddc0/00000017)
May 07 19:44:19 [kernel] nfsv4 compound op c685b050 opcnt 2 #2: 25: status 0
May 07 19:44:19 [kernel] nfsv4 compound returned 0
May 07 19:44:19 [kernel] svc: socket f2cf3000 sendto([c555b000 92... ], 524380) = 524380 (addr 192.168.0.4, port=944)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 dequeued, inuse=1
May 07 19:44:19 [kernel] svc: server c5108000, pool 0, transport f2cf3000, inuse=2
May 07 19:44:19 [kernel] svc: tcp_recv f2cf3000 data 1 conn 0 close 0
May 07 19:44:19 [kernel] svc: socket f2cf3000 recvfrom(f2cf31d8, 0) = 4
May 07 19:44:19 [kernel] svc: TCP record, 176 bytes
May 07 19:44:19 [kernel] svc: socket f2cf3000 recvfrom(c6ca60b0, 3920) = 176
May 07 19:44:19 [kernel] svc: TCP complete record (176 bytes)
May 07 19:44:19 [kernel] svc: got len=176
May 07 19:44:19 [kernel] svc: transport f2cf3000 put into queue
May 07 19:44:19 [kernel] svc: svc_authenticate (6)
May 07 19:44:19 [kernel] RPC: svcauth_gss: argv->iov_len = 148
May 07 19:44:19 [kernel] RPC: gss_verify_mic_v2
May 07 19:44:19 [kernel] RPC: gss_get_mic_v2
May 07 19:44:19 [kernel] svc: calling dispatcher
May 07 19:44:19 [kernel] nfsd_dispatch: vers 4 proc 1
May 07 19:44:19 [kernel] nfsv4 compound op #1/2: 22 (OP_PUTFH)
May 07 19:44:19 [kernel] nfsd: fh_verify(32: 81060001 76ec352c e245ec13 557836b4 784ef9e3 cb8dd809)
May 07 19:44:19 [kernel] nfsv4 compound op c685b050 opcnt 2 #1: 22: status 0
May 07 19:44:19 [kernel] nfsv4 compound op #2/2: 25 (OP_READ)
May 07 19:44:19 [kernel] renewing client (clientid 4fa7ddc0/00000017)
May 07 19:44:19 [kernel] nfsv4 compound op c685b050 opcnt 2 #2: 25: status 0
May 07 19:44:19 [kernel] nfsv4 compound returned 0
May 07 19:44:19 [kernel] svc: socket f2cf3000 sendto([d6eee000 92... ], 524380) = 524380 (addr 192.168.0.4, port=944)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 dequeued, inuse=1
May 07 19:44:19 [kernel] svc: server c5108000, pool 0, transport f2cf3000, inuse=2
May 07 19:44:19 [kernel] svc: tcp_recv f2cf3000 data 1 conn 0 close 0
May 07 19:44:19 [kernel] svc: socket f2cf3000 recvfrom(f2cf31d8, 0) = 4
May 07 19:44:19 [kernel] svc: TCP record, 176 bytes
May 07 19:44:19 [kernel] svc: socket f2cf3000 recvfrom(c6ca60b0, 3920) = 176
May 07 19:44:19 [kernel] svc: TCP complete record (176 bytes)
May 07 19:44:19 [kernel] svc: got len=176
May 07 19:44:19 [kernel] svc: transport f2cf3000 put into queue
May 07 19:44:19 [kernel] svc: svc_authenticate (6)
May 07 19:44:19 [kernel] RPC: svcauth_gss: argv->iov_len = 148
May 07 19:44:19 [kernel] RPC: gss_verify_mic_v2
May 07 19:44:19 [kernel] RPC: gss_get_mic_v2
May 07 19:44:19 [kernel] svc: calling dispatcher
May 07 19:44:19 [kernel] nfsd_dispatch: vers 4 proc 1
May 07 19:44:19 [kernel] nfsv4 compound op #1/2: 22 (OP_PUTFH)
May 07 19:44:19 [kernel] nfsd: fh_verify(32: 81060001 76ec352c e245ec13 557836b4 784ef9e3 cb8dd809)
May 07 19:44:19 [kernel] nfsv4 compound op c685b050 opcnt 2 #1: 22: status 0
May 07 19:44:19 [kernel] nfsv4 compound op #2/2: 25 (OP_READ)
May 07 19:44:19 [kernel] nfsv4 compound op c685b050 opcnt 2 #2: 25: status 0
May 07 19:44:19 [kernel] nfsv4 compound returned 0
May 07 19:44:19 [kernel] svc: socket f2cf3000 sendto([c859e000 92... ], 524380) = 524380 (addr 192.168.0.4, port=944)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 dequeued, inuse=1
May 07 19:44:19 [kernel] svc: server c5108000, pool 0, transport f2cf3000, inuse=2
May 07 19:44:19 [kernel] svc: tcp_recv f2cf3000 data 1 conn 0 close 0
May 07 19:44:19 [kernel] svc: socket f2cf3000 recvfrom(f2cf31d8, 0) = 4
May 07 19:44:19 [kernel] svc: TCP record, 176 bytes
May 07 19:44:19 [kernel] svc: socket f2cf3000 recvfrom(c6ca60b0, 3920) = 176
May 07 19:44:19 [kernel] svc: TCP complete record (176 bytes)
May 07 19:44:19 [kernel] svc: got len=176
May 07 19:44:19 [kernel] svc: transport f2cf3000 put into queue
May 07 19:44:19 [kernel] svc: svc_authenticate (6)
May 07 19:44:19 [kernel] RPC: svcauth_gss: argv->iov_len = 148
May 07 19:44:19 [kernel] RPC: gss_verify_mic_v2
May 07 19:44:19 [kernel] RPC: gss_get_mic_v2
May 07 19:44:19 [kernel] svc: calling dispatcher
May 07 19:44:19 [kernel] nfsd_dispatch: vers 4 proc 1
May 07 19:44:19 [kernel] nfsv4 compound op #1/2: 22 (OP_PUTFH)
May 07 19:44:19 [kernel] nfsd: fh_verify(32: 81060001 76ec352c e245ec13 557836b4 784ef9e3 cb8dd809)
May 07 19:44:19 [kernel] nfsv4 compound op c685b050 opcnt 2 #1: 22: status 0
May 07 19:44:19 [kernel] nfsv4 compound op #2/2: 25 (OP_READ)
May 07 19:44:19 [kernel] renewing client (clientid 4fa7ddc0/00000017)
May 07 19:44:19 [kernel] svc: socket f31fdf80 TCP data ready (svsk f2cf3000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] nfsv4 compound op c685b050 opcnt 2 #2: 25: status 0
May 07 19:44:19 [kernel] nfsv4 compound returned 0
May 07 19:44:19 [kernel] svc: socket f2cf3000 sendto([f3aa0000 92... ], 524380) = 524380 (addr 192.168.0.4, port=944)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 dequeued, inuse=1
May 07 19:44:19 [kernel] svc: server c5108000, pool 0, transport f2cf3000, inuse=2
May 07 19:44:19 [kernel] svc: tcp_recv f2cf3000 data 1 conn 0 close 0
May 07 19:44:19 [kernel] svc: socket f2cf3000 recvfrom(f2cf31d8, 0) = 4
May 07 19:44:19 [kernel] svc: TCP record, 176 bytes
May 07 19:44:19 [kernel] svc: socket f2cf3000 recvfrom(c6ca60b0, 3920) = 176
May 07 19:44:19 [kernel] svc: TCP complete record (176 bytes)
May 07 19:44:19 [kernel] svc: got len=176
May 07 19:44:19 [kernel] svc: transport f2cf3000 put into queue
May 07 19:44:19 [kernel] svc: svc_authenticate (6)
May 07 19:44:19 [kernel] RPC: svcauth_gss: argv->iov_len = 148
May 07 19:44:19 [kernel] RPC: gss_verify_mic_v2
May 07 19:44:19 [kernel] RPC: gss_get_mic_v2
May 07 19:44:19 [kernel] svc: calling dispatcher
May 07 19:44:19 [kernel] nfsd_dispatch: vers 4 proc 1
May 07 19:44:19 [kernel] nfsv4 compound op #1/2: 22 (OP_PUTFH)
May 07 19:44:19 [kernel] nfsd: fh_verify(32: 81060001 76ec352c e245ec13 557836b4 784ef9e3 cb8dd809)
May 07 19:44:19 [kernel] nfsv4 compound op c685b050 opcnt 2 #1: 22: status 0
May 07 19:44:19 [kernel] nfsv4 compound op #2/2: 25 (OP_READ)
May 07 19:44:19 [kernel] renewing client (clientid 4fa7ddc0/00000017)
May 07 19:44:19 [kernel] nfsv4 compound op c685b050 opcnt 2 #2: 25: status 0
May 07 19:44:19 [kernel] nfsv4 compound returned 0
May 07 19:44:19 [kernel] svc: socket f2cf3000 sendto([d2d0b000 92... ], 524380) = 524380 (addr 192.168.0.4, port=944)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 dequeued, inuse=1
May 07 19:44:19 [kernel] svc: server c5108000, pool 0, transport f2cf3000, inuse=2
May 07 19:44:19 [kernel] svc: tcp_recv f2cf3000 data 1 conn 0 close 0
May 07 19:44:19 [kernel] svc: socket f2cf3000 recvfrom(f2cf31d8, 0) = 4
May 07 19:44:19 [kernel] svc: TCP record, 176 bytes
May 07 19:44:19 [kernel] svc: socket f2cf3000 recvfrom(c6ca60b0, 3920) = 176
May 07 19:44:19 [kernel] svc: TCP complete record (176 bytes)
May 07 19:44:19 [kernel] svc: got len=176
May 07 19:44:19 [kernel] svc: transport f2cf3000 put into queue
May 07 19:44:19 [kernel] svc: svc_authenticate (6)
May 07 19:44:19 [kernel] RPC: svcauth_gss: argv->iov_len = 148
May 07 19:44:19 [kernel] RPC: gss_verify_mic_v2
May 07 19:44:19 [kernel] RPC: gss_get_mic_v2
May 07 19:44:19 [kernel] svc: calling dispatcher
May 07 19:44:19 [kernel] nfsd_dispatch: vers 4 proc 1
May 07 19:44:19 [kernel] nfsv4 compound op #1/2: 22 (OP_PUTFH)
May 07 19:44:19 [kernel] nfsd: fh_verify(32: 81060001 76ec352c e245ec13 557836b4 784ef9e3 cb8dd809)
May 07 19:44:19 [kernel] nfsv4 compound op c685b050 opcnt 2 #1: 22: status 0
May 07 19:44:19 [kernel] nfsv4 compound op #2/2: 25 (OP_READ)
May 07 19:44:19 [kernel] renewing client (clientid 4fa7ddc0/00000017)
May 07 19:44:19 [kernel] nfsv4 compound op c685b050 opcnt 2 #2: 25: status 0
May 07 19:44:19 [kernel] nfsv4 compound returned 0
May 07 19:44:19 [kernel] svc: socket f2cf3000 sendto([f2cff000 92... ], 524380) = 524380 (addr 192.168.0.4, port=944)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
----
May 07 19:44:19 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 dequeued, inuse=1
May 07 19:44:19 [kernel] svc: transport f2cf3000 put into queue
----
X~200
May 07 19:44:19 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:44:19 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:19 [kernel] svc: transport f2cf3000 dequeued, inuse=1
May 07 19:44:19 [kernel] svc: server c5108000, pool 0, transport f2cf3000, inuse=2
May 07 19:44:19 [kernel] svc: tcp_recv f2cf3000 data 1 conn 0 close 0
May 07 19:44:19 [kernel] svc: socket f2cf3000 recvfrom(f2cf31d8, 0) = 4
May 07 19:44:19 [kernel] svc: TCP record, 176 bytes
May 07 19:44:19 [kernel] svc: socket f2cf3000 recvfrom(c6ca60b0, 3920) = 176
May 07 19:44:19 [kernel] svc: TCP complete record (176 bytes)
May 07 19:44:19 [kernel] svc: got len=176
May 07 19:44:19 [kernel] svc: transport f2cf3000 put into queue
May 07 19:44:19 [kernel] svc: svc_authenticate (6)
May 07 19:44:19 [kernel] RPC: svcauth_gss: argv->iov_len = 148
May 07 19:44:19 [kernel] RPC: gss_verify_mic_v2
May 07 19:44:19 [kernel] RPC: gss_get_mic_v2
May 07 19:44:19 [kernel] svc: calling dispatcher
May 07 19:44:19 [kernel] nfsd_dispatch: vers 4 proc 1
May 07 19:44:19 [kernel] nfsv4 compound op #1/2: 22 (OP_PUTFH)
May 07 19:44:19 [kernel] nfsd: fh_verify(32: 81060001 76ec352c e245ec13 557836b4 784ef9e3 cb8dd809)
May 07 19:44:19 [kernel] nfsv4 compound op c685b050 opcnt 2 #1: 22: status 0
May 07 19:44:19 [kernel] nfsv4 compound op #2/2: 25 (OP_READ)
May 07 19:44:19 [kernel] renewing client (clientid 4fa7ddc0/00000017)
May 07 19:44:19 [kernel] nfsv4 compound op c685b050 opcnt 2 #2: 25: status 0
May 07 19:44:19 [kernel] nfsv4 compound returned 0
May 07 19:44:19 [kernel] svc: socket f2cf3000 sendto([f36bf000 92... ], 524380) = 524380 (addr 192.168.0.4, port=944)
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
---
May 07 19:44:19 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:44:19 [kernel] svc: transport f2cf3000 dequeued, inuse=1
May 07 19:44:19 [kernel] svc: transport f2cf3000 put into queue
---
X~5000
---
May 07 19:44:19 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:19 [kernel] svc: transport f2cf3000 busy, not enqueued
---
X~10-20 inbetween previous block of repeating messages (sometimes busy=0)
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:44:20 [kernel] svc: transport f2cf3000 dequeued, inuse=1
May 07 19:44:20 [kernel] svc: server c5108000, pool 0, transport f2cf3000, inuse=2
May 07 19:44:20 [kernel] svc: tcp_recv f2cf3000 data 1 conn 0 close 0
May 07 19:44:20 [kernel] svc: TCP record, 176 bytes
May 07 19:44:20 [kernel] svc: socket f2cf3000 recvfrom(c6ca60b0, 3920) = 176
May 07 19:44:20 [kernel] svc: TCP complete record (176 bytes)
May 07 19:44:20 [kernel] svc: got len=176
May 07 19:44:20 [kernel] svc: transport f2cf3000 put into queue
May 07 19:44:20 [kernel] svc: svc_authenticate (6)
May 07 19:44:20 [kernel] RPC: svcauth_gss: argv->iov_len = 148
May 07 19:44:20 [kernel] RPC: gss_verify_mic_v2
May 07 19:44:20 [kernel] RPC: gss_get_mic_v2
May 07 19:44:20 [kernel] svc: calling dispatcher
May 07 19:44:20 [kernel] nfsd_dispatch: vers 4 proc 1
May 07 19:44:20 [kernel] nfsv4 compound op #1/2: 22 (OP_PUTFH)
May 07 19:44:20 [kernel] nfsd: fh_verify(32: 81060001 76ec352c e245ec13 557836b4 784ef9e3 cb8dd809)
May 07 19:44:20 [kernel] nfsv4 compound op c685b050 opcnt 2 #1: 22: status 0
May 07 19:44:20 [kernel] nfsv4 compound op #2/2: 25 (OP_READ)
May 07 19:44:20 [kernel] renewing client (clientid 4fa7ddc0/00000017)
May 07 19:44:20 [kernel] nfsv4 compound op c685b050 opcnt 2 #2: 25: status 0
May 07 19:44:20 [kernel] nfsv4 compound returned 0
May 07 19:44:20 [kernel] svc: socket f2cf3000 sendto([d8bc0000 92... ], 524380) = 524380 (addr 192.168.0.4, port=944)
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
---
May 07 19:44:20 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:44:20 [kernel] svc: transport f2cf3000 dequeued, inuse=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 put into queue
---
X a lot (a couple hundred MB)
---
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=1
May 07 19:44:20 [kernel] svc: socket f2cf3000(inet f31fdf80), write_space busy=0
- Last output repeated 1052 times -
May 07 19:44:21 [kernel] svc: transport f2cf3000 served by daemon c5108000
May 07 19:44:39 [kernel] svc: socket f31fdf80 TCP data ready (svsk f2cf3000)
May 07 19:44:39 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:39 [kernel] svc: socket f31fdf80 TCP data ready (svsk f2cf3000)
May 07 19:44:39 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:44:39 [kernel] svc: socket f31fdf80 TCP data ready (svsk f2cf3000)
May 07 19:44:39 [kernel] svc: transport f2cf3000 busy, not enqueued
---
inbetween
here client restarts TCP connection obviously
May 07 19:45:20 [kernel] svc: socket f31fdf80 TCP (connected) state change 8 (svsk f2cf3000)
May 07 19:45:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:45:20 [kernel] svc: socket f31fdf80 TCP data ready (svsk f2cf3000)
May 07 19:45:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:45:20 [kernel] svc: transport f2cf3000 dequeued, inuse=1
May 07 19:45:20 [kernel] svc_recv: found XPT_CLOSE
May 07 19:45:20 [kernel] svc: svc_delete_xprt(f2cf3000)
May 07 19:45:20 [kernel] svc: svc_tcp_sock_detach(f2cf3000)
May 07 19:45:20 [kernel] svc: svc_sock_detach(f2cf3000)
May 07 19:45:20 [kernel] svc: transport f2cf3000 busy, not enqueued
May 07 19:45:20 [kernel] svc: svc_sock_free(f2cf3000)
May 07 19:45:20 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:45:20 [kernel] svc: socket f31fd200 TCP (listen) state change 10
May 07 19:45:20 [kernel] svc: transport d66f9800 served by daemon c5108000
May 07 19:45:20 [kernel] svc: tcp_accept d66f9800 sock d6c8b500
May 07 19:45:20 [kernel] svc: socket f31fc000 TCP (listen) state change 1
May 07 19:45:20 [kernel] nfsd: connect from 192.168.0.4, port=944
May 07 19:45:20 [kernel] setting up TCP socket for reading
May 07 19:45:20 [kernel] svc: svc_setup_socket created f3065800 (inet f31fc000)
May 07 19:45:20 [kernel] svc: transport f3065800 put into queue
May 07 19:45:20 [kernel] svc: transport d66f9800 put into queue
May 07 19:45:20 [kernel] svc: transport d66f9800 busy, not enqueued
May 07 19:45:20 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:45:20 [kernel] svc: transport f3065800 dequeued, inuse=1
May 07 19:45:20 [kernel] svc: server c5108000, pool 0, transport f3065800, inuse=2
May 07 19:45:20 [kernel] svc: tcp_recv f3065800 data 1 conn 0 close 0
May 07 19:45:20 [kernel] svc: socket f3065800 recvfrom(f30659d8, 0) = 4
May 07 19:45:20 [kernel] svc: TCP record, 176 bytes
May 07 19:45:20 [kernel] svc: socket f3065800 recvfrom(c6ca60b0, 3920) = 176
May 07 19:45:20 [kernel] svc: TCP complete record (176 bytes)
May 07 19:45:20 [kernel] svc: got len=176
May 07 19:45:20 [kernel] svc: svc_authenticate (6)
May 07 19:45:20 [kernel] RPC: svcauth_gss: argv->iov_len = 148
May 07 19:45:20 [kernel] RPC: gss_verify_mic_v2
May 07 19:45:20 [kernel] RPC: gss_get_mic_v2
May 07 19:45:20 [kernel] RPC: Want update, refage=120, age=61
May 07 19:45:20 [kernel] svc: calling dispatcher
May 07 19:45:20 [kernel] nfsd_dispatch: vers 4 proc 1
May 07 19:45:20 [kernel] nfsv4 compound op #1/2: 22 (OP_PUTFH)
May 07 19:45:20 [kernel] nfsd: fh_verify(32: 81060001 76ec352c e245ec13 557836b4 784ef9e3 cb8dd809)
May 07 19:45:20 [kernel] nfsv4 compound op c685b050 opcnt 2 #1: 22: status 0
May 07 19:45:20 [kernel] nfsv4 compound op #2/2: 25 (OP_READ)
May 07 19:45:20 [kernel] renewing client (clientid 4fa7ddc0/00000017)
May 07 19:45:20 [kernel] nfsv4 compound op c685b050 opcnt 2 #2: 25: status 0
May 07 19:45:20 [kernel] nfsv4 compound returned 0
May 07 19:45:20 [kernel] svc: socket f3065800 sendto([f36bf000 92... ], 524380) = 524380 (addr 192.168.0.4, port=944)
May 07 19:45:20 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:45:20 [kernel] svc: transport d66f9800 dequeued, inuse=1
May 07 19:45:20 [kernel] svc: tcp_accept d66f9800 sock d6c8b500
May 07 19:45:20 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:45:20 [kernel] svc: socket f31fc000 TCP data ready (svsk f3065800)
May 07 19:45:20 [kernel] svc: transport f3065800 served by daemon c5108000
May 07 19:45:20 [kernel] svc: server c5108000, pool 0, transport f3065800, inuse=2
May 07 19:45:20 [kernel] svc: tcp_recv f3065800 data 1 conn 0 close 0
May 07 19:45:20 [kernel] svc: socket f3065800 recvfrom(f30659d8, 0) = 4
May 07 19:45:20 [kernel] svc: TCP record, 116 bytes
May 07 19:45:20 [kernel] svc: socket f3065800 recvfrom(c6ca6074, 3980) = 116
May 07 19:45:20 [kernel] svc: TCP complete record (116 bytes)
May 07 19:45:20 [kernel] svc: got len=116
May 07 19:45:20 [kernel] svc: transport f3065800 put into queue
May 07 19:45:20 [kernel] svc: svc_authenticate (6)
May 07 19:45:20 [kernel] RPC: svcauth_gss: argv->iov_len = 88
May 07 19:45:20 [kernel] RPC: gss_verify_mic_v2
May 07 19:45:20 [kernel] RPC: gss_get_mic_v2
May 07 19:45:20 [kernel] RPC: Want update, refage=120, age=61
May 07 19:45:20 [kernel] svc: calling dispatcher
May 07 19:45:20 [kernel] nfsd_dispatch: vers 4 proc 1
May 07 19:45:20 [kernel] nfsv4 compound op #1/1: 30 (OP_RENEW)
May 07 19:45:20 [kernel] process_renew(4fa7ddc0/00000017): starting
May 07 19:45:20 [kernel] renewing client (clientid 4fa7ddc0/00000017)
May 07 19:45:20 [kernel] nfsv4 compound op c685b050 opcnt 1 #1: 30: status 0
May 07 19:45:20 [kernel] nfsv4 compound returned 0
May 07 19:45:20 [kernel] svc: socket f3065800 sendto([d6cb9000 76... ], 76) = 76 (addr 192.168.0.4, port=944)
May 07 19:45:20 [kernel] svc: transport f3065800 busy, not enqueued
May 07 19:45:20 [kernel] svc: server c5108000 waiting for data (to = 3600000)
May 07 19:45:20 [kernel] svc: transport f3065800 dequeued, inuse=1
May 07 19:45:20 [kernel] svc: server c5108000, pool 0, transport f3065800, inuse=2
and so on
^ permalink raw reply [flat|nested] 6+ messages in thread* Re: NFS server misbehaving (nfsd eats CPU and returns no data)
2012-05-07 22:44 NFS server misbehaving (nfsd eats CPU and returns no data) parafin
@ 2012-08-21 17:43 ` J. Bruce Fields
2012-08-21 18:54 ` parafin
0 siblings, 1 reply; 6+ messages in thread
From: J. Bruce Fields @ 2012-08-21 17:43 UTC (permalink / raw)
To: parafin; +Cc: linux-nfs
Are you still willing to test patches? If so, this would be worth a
try:
http://marc.info/?l=linux-nfs&m=134550227125610&w=2
>From a quick look at your logs it looks likely to address the same
problem.
Apologies for the delayed response, we finally just happened to get the
clue necessary to make the problem obvious....
--b.
On Tue, May 08, 2012 at 02:44:19AM +0400, parafin wrote:
> Hello.
> I'm having a problem with my NFS share. It's been present for some time
> now, kernel versions got upgraded, setup has been changed, but since I
> can't remember for sure when it started, I'll just describe my current
> configuration. But first the problem itself.
> Periodically (I would say every GB of data or so) reads from NFS share
> hang during which nfsd kernel thread on server eats CPU but no data
> gets sent to the client. After a minute everything comes to norm again
> (no action on my part is required). First thing I did to debug this is
> I enabled verbose output in all userspace daemons both on client and
> server - it produced no output whatsoever during the problematic period
> of time. Next I dumped network traffic on TCP port 2049 both on client
> and server - there was no packet drops or any other strange stuff,
> except that client restarted the TCP connection to 2049 port after a
> minute of silence from server (which resulted in data flowing again).
> This was confirmed by kernel debug output from client (echo 65535 | tee
> nfs_debug nfsd_debug nlm_debug rpc_debug) - NFS client sent a server
> READ request with 60 seconds timeout, timeout was reached and resulted
> in dropping and restarting of NFS TCP connection. So this points to NFS
> server kernel code. Kernel debug output on server is quite large and
> spikes during the hangs - I've attached deduplicated (by hand) version
> of it to this email. I couldn't find anything strange in there, but I
> don't understand most of it anyway.
> My current setup - both server and client are Linux 3.3.3, NFSv4 with
> sec=krb5, it runs through local network 192.168.0.0/24 with no
> firewalls (client has iptables disabled in kernel, server ACCEPTs
> everything from internal interface). Client uses Wi-Fi, server -
> Ethernet with VLANs, so traffic goes through AP. But since network dumps
> on server and client are the same, network configuration IMHO is
> irrelevant, I just added it for fullness of description. Most common
> usage (and test case) of this NFS share is watching some videos using
> mplayer. Underlying filesystem is XFS (though ext4 is used for other
> shares on the same server).
> I'm ready to provide additional information or test some patches, since
> this problem is quite annoying (and IMHO got worse with time).
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: NFS server misbehaving (nfsd eats CPU and returns no data)
2012-08-21 17:43 ` J. Bruce Fields
@ 2012-08-21 18:54 ` parafin
2012-08-21 21:01 ` J. Bruce Fields
0 siblings, 1 reply; 6+ messages in thread
From: parafin @ 2012-08-21 18:54 UTC (permalink / raw)
To: J. Bruce Fields; +Cc: linux-nfs
Hi.
I somewhat mitigated the problem by mount option timeo=10, but this
issue still heavily affects NFS throughput. So yes, I'm willing to test,
just have to find some free time to do it. I will report as soon as I
get results.
Thanks for reply, I thought my message was lost forever :)
On Tue, 21 Aug 2012 13:43:55 -0400
"J. Bruce Fields" <bfields@fieldses.org> wrote:
> Are you still willing to test patches? If so, this would be worth a
> try:
>
> http://marc.info/?l=linux-nfs&m=134550227125610&w=2
>
> >From a quick look at your logs it looks likely to address the same
> problem.
>
> Apologies for the delayed response, we finally just happened to get the
> clue necessary to make the problem obvious....
>
> --b.
>
> On Tue, May 08, 2012 at 02:44:19AM +0400, parafin wrote:
> > Hello.
> > I'm having a problem with my NFS share. It's been present for some time
> > now, kernel versions got upgraded, setup has been changed, but since I
> > can't remember for sure when it started, I'll just describe my current
> > configuration. But first the problem itself.
> > Periodically (I would say every GB of data or so) reads from NFS share
> > hang during which nfsd kernel thread on server eats CPU but no data
> > gets sent to the client. After a minute everything comes to norm again
> > (no action on my part is required). First thing I did to debug this is
> > I enabled verbose output in all userspace daemons both on client and
> > server - it produced no output whatsoever during the problematic period
> > of time. Next I dumped network traffic on TCP port 2049 both on client
> > and server - there was no packet drops or any other strange stuff,
> > except that client restarted the TCP connection to 2049 port after a
> > minute of silence from server (which resulted in data flowing again).
> > This was confirmed by kernel debug output from client (echo 65535 | tee
> > nfs_debug nfsd_debug nlm_debug rpc_debug) - NFS client sent a server
> > READ request with 60 seconds timeout, timeout was reached and resulted
> > in dropping and restarting of NFS TCP connection. So this points to NFS
> > server kernel code. Kernel debug output on server is quite large and
> > spikes during the hangs - I've attached deduplicated (by hand) version
> > of it to this email. I couldn't find anything strange in there, but I
> > don't understand most of it anyway.
> > My current setup - both server and client are Linux 3.3.3, NFSv4 with
> > sec=krb5, it runs through local network 192.168.0.0/24 with no
> > firewalls (client has iptables disabled in kernel, server ACCEPTs
> > everything from internal interface). Client uses Wi-Fi, server -
> > Ethernet with VLANs, so traffic goes through AP. But since network dumps
> > on server and client are the same, network configuration IMHO is
> > irrelevant, I just added it for fullness of description. Most common
> > usage (and test case) of this NFS share is watching some videos using
> > mplayer. Underlying filesystem is XFS (though ext4 is used for other
> > shares on the same server).
> > I'm ready to provide additional information or test some patches, since
> > this problem is quite annoying (and IMHO got worse with time).
>
>
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: NFS server misbehaving (nfsd eats CPU and returns no data)
2012-08-21 18:54 ` parafin
@ 2012-08-21 21:01 ` J. Bruce Fields
2012-08-25 21:11 ` parafin
0 siblings, 1 reply; 6+ messages in thread
From: J. Bruce Fields @ 2012-08-21 21:01 UTC (permalink / raw)
To: parafin; +Cc: linux-nfs
On Tue, Aug 21, 2012 at 10:54:23PM +0400, parafin wrote:
> I somewhat mitigated the problem by mount option timeo=10, but this
> issue still heavily affects NFS throughput. So yes, I'm willing to test,
> just have to find some free time to do it. I will report as soon as I
> get results.
OK, thanks.
> Thanks for reply, I thought my message was lost forever :)
In general feel free to retry every now and then (like after a week or
so, not every day please!) if you get ignored. We all get overloaded an
drop things occasionally.
--b.
>
> On Tue, 21 Aug 2012 13:43:55 -0400
> "J. Bruce Fields" <bfields@fieldses.org> wrote:
>
> > Are you still willing to test patches? If so, this would be worth a
> > try:
> >
> > http://marc.info/?l=linux-nfs&m=134550227125610&w=2
> >
> > >From a quick look at your logs it looks likely to address the same
> > problem.
> >
> > Apologies for the delayed response, we finally just happened to get the
> > clue necessary to make the problem obvious....
> >
> > --b.
> >
> > On Tue, May 08, 2012 at 02:44:19AM +0400, parafin wrote:
> > > Hello.
> > > I'm having a problem with my NFS share. It's been present for some time
> > > now, kernel versions got upgraded, setup has been changed, but since I
> > > can't remember for sure when it started, I'll just describe my current
> > > configuration. But first the problem itself.
> > > Periodically (I would say every GB of data or so) reads from NFS share
> > > hang during which nfsd kernel thread on server eats CPU but no data
> > > gets sent to the client. After a minute everything comes to norm again
> > > (no action on my part is required). First thing I did to debug this is
> > > I enabled verbose output in all userspace daemons both on client and
> > > server - it produced no output whatsoever during the problematic period
> > > of time. Next I dumped network traffic on TCP port 2049 both on client
> > > and server - there was no packet drops or any other strange stuff,
> > > except that client restarted the TCP connection to 2049 port after a
> > > minute of silence from server (which resulted in data flowing again).
> > > This was confirmed by kernel debug output from client (echo 65535 | tee
> > > nfs_debug nfsd_debug nlm_debug rpc_debug) - NFS client sent a server
> > > READ request with 60 seconds timeout, timeout was reached and resulted
> > > in dropping and restarting of NFS TCP connection. So this points to NFS
> > > server kernel code. Kernel debug output on server is quite large and
> > > spikes during the hangs - I've attached deduplicated (by hand) version
> > > of it to this email. I couldn't find anything strange in there, but I
> > > don't understand most of it anyway.
> > > My current setup - both server and client are Linux 3.3.3, NFSv4 with
> > > sec=krb5, it runs through local network 192.168.0.0/24 with no
> > > firewalls (client has iptables disabled in kernel, server ACCEPTs
> > > everything from internal interface). Client uses Wi-Fi, server -
> > > Ethernet with VLANs, so traffic goes through AP. But since network dumps
> > > on server and client are the same, network configuration IMHO is
> > > irrelevant, I just added it for fullness of description. Most common
> > > usage (and test case) of this NFS share is watching some videos using
> > > mplayer. Underlying filesystem is XFS (though ext4 is used for other
> > > shares on the same server).
> > > I'm ready to provide additional information or test some patches, since
> > > this problem is quite annoying (and IMHO got worse with time).
> >
> >
> --
> To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: NFS server misbehaving (nfsd eats CPU and returns no data)
2012-08-21 21:01 ` J. Bruce Fields
@ 2012-08-25 21:11 ` parafin
2012-08-26 0:58 ` J. Bruce Fields
0 siblings, 1 reply; 6+ messages in thread
From: parafin @ 2012-08-25 21:11 UTC (permalink / raw)
To: J. Bruce Fields; +Cc: linux-nfs
I've applied linked patch and rebooted (I'm still running kernel
version 3.3.3). So far so good, everything looks fine, so I guess my
issue is fixed by that patch, big thanx.
On Tue, 21 Aug 2012 17:01:16 -0400
"J. Bruce Fields" <bfields@fieldses.org> wrote:
> On Tue, Aug 21, 2012 at 10:54:23PM +0400, parafin wrote:
> > I somewhat mitigated the problem by mount option timeo=10, but this
> > issue still heavily affects NFS throughput. So yes, I'm willing to test,
> > just have to find some free time to do it. I will report as soon as I
> > get results.
>
> OK, thanks.
>
> > Thanks for reply, I thought my message was lost forever :)
>
> In general feel free to retry every now and then (like after a week or
> so, not every day please!) if you get ignored. We all get overloaded an
> drop things occasionally.
>
> --b.
>
> >
> > On Tue, 21 Aug 2012 13:43:55 -0400
> > "J. Bruce Fields" <bfields@fieldses.org> wrote:
> >
> > > Are you still willing to test patches? If so, this would be worth a
> > > try:
> > >
> > > http://marc.info/?l=linux-nfs&m=134550227125610&w=2
> > >
> > > >From a quick look at your logs it looks likely to address the same
> > > problem.
> > >
> > > Apologies for the delayed response, we finally just happened to get the
> > > clue necessary to make the problem obvious....
> > >
> > > --b.
> > >
> > > On Tue, May 08, 2012 at 02:44:19AM +0400, parafin wrote:
> > > > Hello.
> > > > I'm having a problem with my NFS share. It's been present for some time
> > > > now, kernel versions got upgraded, setup has been changed, but since I
> > > > can't remember for sure when it started, I'll just describe my current
> > > > configuration. But first the problem itself.
> > > > Periodically (I would say every GB of data or so) reads from NFS share
> > > > hang during which nfsd kernel thread on server eats CPU but no data
> > > > gets sent to the client. After a minute everything comes to norm again
> > > > (no action on my part is required). First thing I did to debug this is
> > > > I enabled verbose output in all userspace daemons both on client and
> > > > server - it produced no output whatsoever during the problematic period
> > > > of time. Next I dumped network traffic on TCP port 2049 both on client
> > > > and server - there was no packet drops or any other strange stuff,
> > > > except that client restarted the TCP connection to 2049 port after a
> > > > minute of silence from server (which resulted in data flowing again).
> > > > This was confirmed by kernel debug output from client (echo 65535 | tee
> > > > nfs_debug nfsd_debug nlm_debug rpc_debug) - NFS client sent a server
> > > > READ request with 60 seconds timeout, timeout was reached and resulted
> > > > in dropping and restarting of NFS TCP connection. So this points to NFS
> > > > server kernel code. Kernel debug output on server is quite large and
> > > > spikes during the hangs - I've attached deduplicated (by hand) version
> > > > of it to this email. I couldn't find anything strange in there, but I
> > > > don't understand most of it anyway.
> > > > My current setup - both server and client are Linux 3.3.3, NFSv4 with
> > > > sec=krb5, it runs through local network 192.168.0.0/24 with no
> > > > firewalls (client has iptables disabled in kernel, server ACCEPTs
> > > > everything from internal interface). Client uses Wi-Fi, server -
> > > > Ethernet with VLANs, so traffic goes through AP. But since network dumps
> > > > on server and client are the same, network configuration IMHO is
> > > > irrelevant, I just added it for fullness of description. Most common
> > > > usage (and test case) of this NFS share is watching some videos using
> > > > mplayer. Underlying filesystem is XFS (though ext4 is used for other
> > > > shares on the same server).
> > > > I'm ready to provide additional information or test some patches, since
> > > > this problem is quite annoying (and IMHO got worse with time).
> > >
> > >
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: NFS server misbehaving (nfsd eats CPU and returns no data)
2012-08-25 21:11 ` parafin
@ 2012-08-26 0:58 ` J. Bruce Fields
0 siblings, 0 replies; 6+ messages in thread
From: J. Bruce Fields @ 2012-08-26 0:58 UTC (permalink / raw)
To: parafin; +Cc: linux-nfs
On Sun, Aug 26, 2012 at 01:11:41AM +0400, parafin wrote:
> I've applied linked patch and rebooted (I'm still running kernel
> version 3.3.3). So far so good, everything looks fine, so I guess my
> issue is fixed by that patch, big thanx.
Good, thanks.--b.
>
> On Tue, 21 Aug 2012 17:01:16 -0400
> "J. Bruce Fields" <bfields@fieldses.org> wrote:
>
> > On Tue, Aug 21, 2012 at 10:54:23PM +0400, parafin wrote:
> > > I somewhat mitigated the problem by mount option timeo=10, but this
> > > issue still heavily affects NFS throughput. So yes, I'm willing to test,
> > > just have to find some free time to do it. I will report as soon as I
> > > get results.
> >
> > OK, thanks.
> >
> > > Thanks for reply, I thought my message was lost forever :)
> >
> > In general feel free to retry every now and then (like after a week or
> > so, not every day please!) if you get ignored. We all get overloaded an
> > drop things occasionally.
> >
> > --b.
> >
> > >
> > > On Tue, 21 Aug 2012 13:43:55 -0400
> > > "J. Bruce Fields" <bfields@fieldses.org> wrote:
> > >
> > > > Are you still willing to test patches? If so, this would be worth a
> > > > try:
> > > >
> > > > http://marc.info/?l=linux-nfs&m=134550227125610&w=2
> > > >
> > > > >From a quick look at your logs it looks likely to address the same
> > > > problem.
> > > >
> > > > Apologies for the delayed response, we finally just happened to get the
> > > > clue necessary to make the problem obvious....
> > > >
> > > > --b.
> > > >
> > > > On Tue, May 08, 2012 at 02:44:19AM +0400, parafin wrote:
> > > > > Hello.
> > > > > I'm having a problem with my NFS share. It's been present for some time
> > > > > now, kernel versions got upgraded, setup has been changed, but since I
> > > > > can't remember for sure when it started, I'll just describe my current
> > > > > configuration. But first the problem itself.
> > > > > Periodically (I would say every GB of data or so) reads from NFS share
> > > > > hang during which nfsd kernel thread on server eats CPU but no data
> > > > > gets sent to the client. After a minute everything comes to norm again
> > > > > (no action on my part is required). First thing I did to debug this is
> > > > > I enabled verbose output in all userspace daemons both on client and
> > > > > server - it produced no output whatsoever during the problematic period
> > > > > of time. Next I dumped network traffic on TCP port 2049 both on client
> > > > > and server - there was no packet drops or any other strange stuff,
> > > > > except that client restarted the TCP connection to 2049 port after a
> > > > > minute of silence from server (which resulted in data flowing again).
> > > > > This was confirmed by kernel debug output from client (echo 65535 | tee
> > > > > nfs_debug nfsd_debug nlm_debug rpc_debug) - NFS client sent a server
> > > > > READ request with 60 seconds timeout, timeout was reached and resulted
> > > > > in dropping and restarting of NFS TCP connection. So this points to NFS
> > > > > server kernel code. Kernel debug output on server is quite large and
> > > > > spikes during the hangs - I've attached deduplicated (by hand) version
> > > > > of it to this email. I couldn't find anything strange in there, but I
> > > > > don't understand most of it anyway.
> > > > > My current setup - both server and client are Linux 3.3.3, NFSv4 with
> > > > > sec=krb5, it runs through local network 192.168.0.0/24 with no
> > > > > firewalls (client has iptables disabled in kernel, server ACCEPTs
> > > > > everything from internal interface). Client uses Wi-Fi, server -
> > > > > Ethernet with VLANs, so traffic goes through AP. But since network dumps
> > > > > on server and client are the same, network configuration IMHO is
> > > > > irrelevant, I just added it for fullness of description. Most common
> > > > > usage (and test case) of this NFS share is watching some videos using
> > > > > mplayer. Underlying filesystem is XFS (though ext4 is used for other
> > > > > shares on the same server).
> > > > > I'm ready to provide additional information or test some patches, since
> > > > > this problem is quite annoying (and IMHO got worse with time).
> > > >
> > > >
> > > --
> > > To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
> > > the body of a message to majordomo@vger.kernel.org
> > > More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2012-08-26 0:58 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2012-05-07 22:44 NFS server misbehaving (nfsd eats CPU and returns no data) parafin
2012-08-21 17:43 ` J. Bruce Fields
2012-08-21 18:54 ` parafin
2012-08-21 21:01 ` J. Bruce Fields
2012-08-25 21:11 ` parafin
2012-08-26 0:58 ` J. Bruce Fields
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).