LinuxLists.cc - NFS regression? Odd delays and lockups accessing an NFS export.

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Mon, 2008-08-18 at 19:50 +0100, Athanasius wrote:
> On Mon, Aug 18, 2008 at 12:02:20PM +1000, Grant Coady wrote:
> > I've been using NFS here for years, lately there's something odd going on
> > since about a month or so. Previously reported last month:
> > http://www.gossamer-threads.com/lists/linux/kernel/951419?page=last
> >
> > Now with 2.6.27-rc3 on one of the client boxes I get a complete stall
> > at odd times when accessing the server's exported directory, cannot
> > see a pattern to it. Eventually recovers after a Ctrl-C. Nothing in
> > the server or client log files. Not easy to reproduce either.
>
> I wonder if this is what I've been seeing. I've been otherwise too
> busy to properly report it, thinking that *someone* else must also be
> seeing it and it's being worked on, else it's a subtle configuration
> problem my end.

Your lockdep trace basically shows that the rpc layer is blocking for
some reason. Could you please try to reproduce the problem, and then do

echo 0 >/proc/sys/sunrpc/rpc_debug

...and see what the output from 'dmesg' shows?

Cheers
Trond

2008-08-18 19:21:20

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Mon, 2008-08-18 at 12:02 +1000, Grant Coady wrote:
> Hi there,
>
> I've been using NFS here for years, lately there's something odd going on
> since about a month or so. Previously reported last month:
> http://www.gossamer-threads.com/lists/linux/kernel/951419?page=last
>
> Now with 2.6.27-rc3 on one of the client boxes I get a complete stall
> at odd times when accessing the server's exported directory, cannot
> see a pattern to it. Eventually recovers after a Ctrl-C. Nothing in
> the server or client log files. Not easy to reproduce either.
>
> The server runs 2.6.26.2 at the moment.
>
> Server config, etc: http://bugsplatter.id.au/kernel/boxen/deltree/
> Client config, etc: http://bugsplatter.id.au/kernel/boxen/pooh/

Please try to reproduce the hang, then do

echo 0 >/proc/sys/sunrpc/rpc_debug

and send the output from 'dmesg'...

Cheers
Trond

2008-08-18 19:41:19

by J. K. Cliburn

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

Athanasius wrote:
> On Mon, Aug 18, 2008 at 12:02:20PM +1000, Grant Coady wrote:
>> I've been using NFS here for years, lately there's something odd going on
>> since about a month or so. Previously reported last month:
>> http://www.gossamer-threads.com/lists/linux/kernel/951419?page=last
>>
>> Now with 2.6.27-rc3 on one of the client boxes I get a complete stall
>> at odd times when accessing the server's exported directory, cannot
>> see a pattern to it. Eventually recovers after a Ctrl-C. Nothing in
>> the server or client log files. Not easy to reproduce either.
>
> I wonder if this is what I've been seeing. I've been otherwise too
> busy to properly report it, thinking that *someone* else must also be
> seeing it and it's being worked on, else it's a subtle configuration
> problem my end.
>
> I first started seeing this with 2.6.26 on the client end,

I see you're running the atl1 driver on your client. I'm chasing an
intermittent bug in that driver that seems to be affected by certain
offload parameters. Try disabling TSO and see if things improve.

ethtool -K eth0 tso off

Let me know if it helps.

Jay

2008-08-18 23:13:55

by Athanasius

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Mon, Aug 18, 2008 at 02:37:45PM -0500, J. K. Cliburn wrote:
> Athanasius wrote:
> > I wonder if this is what I've been seeing. I've been otherwise too
> >busy to properly report it, thinking that *someone* else must also be
> >seeing it and it's being worked on, else it's a subtle configuration
> >problem my end.
> >
> > I first started seeing this with 2.6.26 on the client end,
>
> I see you're running the atl1 driver on your client. I'm chasing an
> intermittent bug in that driver that seems to be affected by certain
> offload parameters. Try disabling TSO and see if things improve.
>
> ethtool -K eth0 tso off
>
> Let me know if it helps.

Indeed it does, and indeed tso was on by default. I booted up once
after first trying this, thinking I had things set to apply it
automatically, but hadn't and ran into the exact same problem. This 2nd
time around with the setting definitely applied things appear to be
working normally. At least I can actually start Firefox up and have it
work (lots of /home/users/... access over NFS to the server).

thanks,

-Ath
--
- Athanasius = Athanasius(at)miggy.org / http://www.miggy.org/
Finger athan(at)fysh.org for PGP key
"And it's me who is my enemy. Me who beats me up.
Me who makes the monsters. Me who strips my confidence." Paula Cole - ME

Attachments:

(No filename) (1.30 kB)
signature.asc (189.00 B)
Digital signature Download all attachments

2008-08-20 01:11:48

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

Hi Trond,

On Mon, 18 Aug 2008 15:20:58 -0400, Trond Myklebust <[email protected]> wrote:

>On Mon, 2008-08-18 at 12:02 +1000, Grant Coady wrote:
>> Hi there,
>>
>> I've been using NFS here for years, lately there's something odd going on
>> since about a month or so. Previously reported last month:
>> http://www.gossamer-threads.com/lists/linux/kernel/951419?page=last
>>
>> Now with 2.6.27-rc3 on one of the client boxes I get a complete stall
>> at odd times when accessing the server's exported directory, cannot
>> see a pattern to it. Eventually recovers after a Ctrl-C. Nothing in
>> the server or client log files. Not easy to reproduce either.
>>
>> The server runs 2.6.26.2 at the moment.
>>
>> Server config, etc: http://bugsplatter.id.au/kernel/boxen/deltree/
>> Client config, etc: http://bugsplatter.id.au/kernel/boxen/pooh/
>
>Please try to reproduce the hang, then do
>
> echo 0 >/proc/sys/sunrpc/rpc_debug
>
>and send the output from 'dmesg'...

dmesg and logs from client machine showed nothing, dmesg from server:

-pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--

(nothing, nada, zilch after what looks like the header line)

Situation, first use of 'df' after reboot, client machine hung for many
seconds before the /home/common export showed up, this is not repeatable.
Mounting another export and doing 'df' again had no delays.

Client is running 2.6.27-rc3-git5 (x86_64) at the moment, configs, etc
at: http://bugsplatter.id.au/kernel/boxen/pooh64/

Server as above. Am I supposed to have some debugging turned on in the
.configs?

Grant.

2008-08-20 23:17:49

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Mon, 18 Aug 2008 15:20:58 -0400, Trond Myklebust <[email protected]> wrote:

>On Mon, 2008-08-18 at 12:02 +1000, Grant Coady wrote:
>> Hi there,
>>
>> I've been using NFS here for years, lately there's something odd going on
>> since about a month or so. Previously reported last month:
>> http://www.gossamer-threads.com/lists/linux/kernel/951419?page=last
>>
>> Now with 2.6.27-rc3 on one of the client boxes I get a complete stall
>> at odd times when accessing the server's exported directory, cannot
>> see a pattern to it. Eventually recovers after a Ctrl-C. Nothing in
>> the server or client log files. Not easy to reproduce either.
>>
>> The server runs 2.6.26.2 at the moment.
>>
>> Server config, etc: http://bugsplatter.id.au/kernel/boxen/deltree/
>> Client config, etc: http://bugsplatter.id.au/kernel/boxen/pooh/
>
>Please try to reproduce the hang, then do
>
> echo 0 >/proc/sys/sunrpc/rpc_debug
>
>and send the output from 'dmesg'...

It's not NFS, I just had WinXP box stall completely (no KB NumLock
response) on a PuTTY (ssh) terminal to a linux box running 2.6.26.3
for about five or ten seconds, when it came back to operation the
PuTYY toolbar icon was flashing. Dunno which terminal as I had four
open at the time, but they all to a server box running 2.6.26.3 with
multiple Intel pro/100 (e100) NICs.

I think this may be to do with the e100 network driver instead, as a
few weeks ago I started compiling it in rather than as a module like
I've been doing for years (in response to the firmware (microcode)
being dropped on the floor last month issue). This box is the server
(deltree) that all linux boxes mount a /home/common NFS export from.

All machines have the Intel pro/100 NIC, going to recompile the lot
back to modules, see if that fixes the problem.

Grant.

2008-08-22 10:25:00

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Mon, 2008-08-18 at 15:20 -0400, Trond Myklebust wrote:
> Please try to reproduce the hang, then do
>
> echo 0 >/proc/sys/sunrpc/rpc_debug
>
> and send the output from 'dmesg'...

I've also been seeing some NFS related lockups, although I'm not sure if
they are the same as the one in this thread or not. Client is 2.6.26
(Debian's kernel) and Server is 2.6.25 (also a Debian kernel, but from
backports.org).

rpc_debug on the server gives nothing, on the client gives:
[144741.637997] -pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--
[144741.637997] 3439 0004 0080 -11 f3f48200 100003 f7770000 0 xprt_sending fa0ae88e fa0bddf4
[144741.637997] 3438 0001 00a0 0 f77f2a00 100003 f77700d0 15000 xprt_pending fa0ae88e fa0bddf4

There are no processes running with pid 3439 3438 (I don't think it's
that sort of pid though).

mounts points are:
hopkins:/storage/music /storage/music nfs rw,nosuid,vers=3,rsize=32768,wsize=32768,namlen=255,hard,intr,proto=tcp,timeo=600,retrans=2,sec=sys,mountproto=udp,addr=192.168.1.6 0 0
hopkins:/storage/mythtv/recordings /var/lib/mythtv/recordings nfs rw,nosuid,vers=3,rsize=32768,wsize=32768,namlen=255,acregmin=0,acregmax=0,acdirmin=0,acdirmax=0,hard,intr,proto=tcp,timeo=600,retrans=2,sec=sys,mountproto=udp,addr=192.168.1.6 0 0
hopkins:/var/lib/mythvideo /var/lib/mythvideo nfs rw,nosuid,vers=3,rsize=32768,wsize=32768,namlen=255,acregmin=0,acregmax=0,acdirmin=0,acdirmax=0,hard,intr,proto=tcp,timeo=600,retrans=2,sec=sys,mountproto=udp,addr=192.168.1.6 0 0
hopkins:/storage/home/ijc /home/ijc nfs rw,vers=3,rsize=131072,wsize=131072,namlen=255,hard,nointr,proto=tcp,timeo=600,retrans=2,sec=sys,mountproto=udp,addr=192.168.1.6 0 0
and all seem to be effected.

It hasn't happened this time (yet) but usually I get a hung task
backtrace like this:
Aug 4 06:27:28 iranon kernel: [137969.382277] INFO: task mythbackend:3161 blocked for more than 120 seconds.
Aug 4 06:27:28 iranon kernel: [137969.382287] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 4 06:27:28 iranon kernel: [137969.382291] mythbackend D 00005dfc 0 3161 1
Aug 4 06:27:28 iranon kernel: [137969.382295] f2006c70 00000082 4b05cc7e 00005dfc f2006df0 c1c0e920 00000000 f7273390
Aug 4 06:27:28 iranon kernel: [137969.382301] 0000c8b4 00000000 00000001 f7273398 00000282 00000202 f71b0ab0 f200ddf0
Aug 4 06:27:28 iranon kernel: [137969.382306] c1c012bc fa18f0a6 fa18f0bf c02b45a7 f71b0ab0 00000000 f200de0c fa18f0a6
Aug 4 06:27:28 iranon kernel: [137969.382311] Call Trace:
Aug 4 06:27:28 iranon kernel: [137969.382347] [<fa18f0a6>] nfs_wait_schedule+0x0/0x1e [nfs]
Aug 4 06:27:28 iranon kernel: [137969.382384] [<fa18f0bf>] nfs_wait_schedule+0x19/0x1e [nfs]
Aug 4 06:27:28 iranon kernel: [137969.382399] [<c02b45a7>] __wait_on_bit_lock+0x2a/0x52
Aug 4 06:27:28 iranon kernel: [137969.382407] [<fa18f0a6>] nfs_wait_schedule+0x0/0x1e [nfs]
Aug 4 06:27:28 iranon kernel: [137969.382421] [<c02b462e>] out_of_line_wait_on_bit_lock+0x5f/0x67
Aug 4 06:27:28 iranon kernel: [137969.382429] [<c0133a1d>] wake_bit_function+0x0/0x3c
Aug 4 06:27:28 iranon kernel: [137969.382441] [<fa18f16e>] __nfs_revalidate_inode+0xaa/0x211 [nfs]
Aug 4 06:27:28 iranon kernel: [137969.382458] [<c017bac0>] do_lookup+0x53/0x145
Aug 4 06:27:28 iranon kernel: [137969.382466] [<c0187609>] mntput_no_expire+0x11/0x64
Aug 4 06:27:28 iranon kernel: [137969.382472] [<c017d971>] __link_path_walk+0xa71/0xb65
Aug 4 06:27:28 iranon kernel: [137969.382477] [<c017bac0>] do_lookup+0x53/0x145
Aug 4 06:27:28 iranon kernel: [137969.382483] [<c0187609>] mntput_no_expire+0x11/0x64
Aug 4 06:27:28 iranon kernel: [137969.382492] [<c0187609>] mntput_no_expire+0x11/0x64
Aug 4 06:27:28 iranon kernel: [137969.382496] [<c017daf5>] path_walk+0x90/0x98
Aug 4 06:27:28 iranon kernel: [137969.382502] [<fa18f935>] nfs_getattr+0x8f/0xbe [nfs]
Aug 4 06:27:28 iranon kernel: [137969.382520] [<fa18f8a6>] nfs_getattr+0x0/0xbe [nfs]
Aug 4 06:27:28 iranon kernel: [137969.382536] [<c01785ac>] vfs_getattr+0x36/0x4d
Aug 4 06:27:28 iranon kernel: [137969.382545] [<c0178684>] vfs_lstat_fd+0x27/0x39
Aug 4 06:27:28 iranon kernel: [137969.382550] [<fa18bca6>] nfs_permission+0x0/0x129 [nfs]
Aug 4 06:27:28 iranon kernel: [137969.382567] [<c0187609>] mntput_no_expire+0x11/0x64
Aug 4 06:27:28 iranon kernel: [137969.382572] [<c0174914>] sys_faccessat+0x11e/0x15d
Aug 4 06:27:28 iranon kernel: [137969.382582] [<c0178703>] sys_lstat64+0xf/0x23
Aug 4 06:27:28 iranon kernel: [137969.382588] [<c017603c>] vfs_read+0xe3/0x11e
Aug 4 06:27:28 iranon kernel: [137969.382598] [<c0174962>] sys_access+0xf/0x13
Aug 4 06:27:28 iranon kernel: [137969.382603] [<c01077e8>] sysenter_past_esp+0x6d/0xa5
Aug 4 06:27:28 iranon kernel: [137969.382617] =======================

Sysrq-T from dmesg (therefore truncated a bit) is attached.

Ian.

--
Ian Campbell

There are no answers, only cross-references.
-- Weiner

Attachments:

sysrq (121.87 kB)

2008-08-22 18:08:31

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Fri, 2008-08-22 at 11:23 +0100, Ian Campbell wrote:
> On Mon, 2008-08-18 at 15:20 -0400, Trond Myklebust wrote:
> > Please try to reproduce the hang, then do
> >
> > echo 0 >/proc/sys/sunrpc/rpc_debug
> >
> > and send the output from 'dmesg'...
>
> I've also been seeing some NFS related lockups, although I'm not sure if
> they are the same as the one in this thread or not. Client is 2.6.26
> (Debian's kernel) and Server is 2.6.25 (also a Debian kernel, but from
> backports.org).
>
> rpc_debug on the server gives nothing, on the client gives:
> [144741.637997] -pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--
> [144741.637997] 3439 0004 0080 -11 f3f48200 100003 f7770000 0 xprt_sending fa0ae88e fa0bddf4
> [144741.637997] 3438 0001 00a0 0 f77f2a00 100003 f77700d0 15000 xprt_pending fa0ae88e fa0bddf4

That's probably also a networking device driver issue candidate: your
RPC task is queued up waiting to be sent.

What networking card+device driver are you using here?

> There are no processes running with pid 3439 3438 (I don't think it's
> that sort of pid though).

The 'pid' is an internal RPC cookie that just serves to identify and
track specific RPC requests.

Cheers
Trond

2008-08-22 18:14:08

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Fri, 2008-08-22 at 11:08 -0700, Trond Myklebust wrote:
> On Fri, 2008-08-22 at 11:23 +0100, Ian Campbell wrote:
> > On Mon, 2008-08-18 at 15:20 -0400, Trond Myklebust wrote:
> > > Please try to reproduce the hang, then do
> > >
> > > echo 0 >/proc/sys/sunrpc/rpc_debug
> > >
> > > and send the output from 'dmesg'...
> >
> > I've also been seeing some NFS related lockups, although I'm not sure if
> > they are the same as the one in this thread or not. Client is 2.6.26
> > (Debian's kernel) and Server is 2.6.25 (also a Debian kernel, but from
> > backports.org).
> >
> > rpc_debug on the server gives nothing, on the client gives:
> > [144741.637997] -pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--
> > [144741.637997] 3439 0004 0080 -11 f3f48200 100003 f7770000 0 xprt_sending fa0ae88e fa0bddf4
> > [144741.637997] 3438 0001 00a0 0 f77f2a00 100003 f77700d0 15000 xprt_pending fa0ae88e fa0bddf4
>
> That's probably also a networking device driver issue candidate: your
> RPC task is queued up waiting to be sent.
>
> What networking card+device driver are you using here?

# ethtool -i eth0
driver: e1000
version: 7.3.20-k2-NAPI
firmware-version: N/A
bus-info: 0000:01:0a.0

Adding CC's to peeps listed in MAINTAINERS

I have to reboot the system now (or else there will be no TV to watch
during my tea ;-). It will probably repro again quite soon though.

> > There are no processes running with pid 3439 3438 (I don't think it's
> > that sort of pid though).
>
> The 'pid' is an internal RPC cookie that just serves to identify and
> track specific RPC requests.

Right, thanks.

Ian.

--
Ian Campbell

Colors may fade.

Attachments:

signature.asc (197.00 B)
This is a digitally signed message part

2008-08-22 19:33:20

by John Ronciak

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Fri, Aug 22, 2008 at 11:13 AM, Ian Campbell <[email protected]> wrote:

>> That's probably also a networking device driver issue candidate: your
>> RPC task is queued up waiting to be sent.
>>
>> What networking card+device driver are you using here?
>
> # ethtool -i eth0
> driver: e1000
> version: 7.3.20-k2-NAPI
> firmware-version: N/A
> bus-info: 0000:01:0a.0
There is nothing indicating that the NIC/driver is causing any sort of
problem here, at least not with what has been presented so far. When
the NFS mount isn't working is the networking still active and
working?

--
Cheers,
John

2008-08-22 20:00:31

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Fri, 2008-08-22 at 12:33 -0700, John Ronciak wrote:
> On Fri, Aug 22, 2008 at 11:13 AM, Ian Campbell <[email protected]> wrote:
>
> >> That's probably also a networking device driver issue candidate: your
> >> RPC task is queued up waiting to be sent.
> >>
> >> What networking card+device driver are you using here?
> >
> > # ethtool -i eth0
> > driver: e1000
> > version: 7.3.20-k2-NAPI
> > firmware-version: N/A
> > bus-info: 0000:01:0a.0
> There is nothing indicating that the NIC/driver is causing any sort of
> problem here, at least not with what has been presented so far. When
> the NFS mount isn't working is the networking still active and
> working?

So far as I can tell, yes. I can login via ssh so long as the user
doesn't have NFS $HOME, I haven't tried much else and the box isn't
locked up at the moment, I'd bet it's fine though.

Ian.

--
Ian Campbell

"On a normal ascii line, the only safe condition to detect is a 'BREAK'
- everything else having been assigned functions by Gnu EMACS."
(By Tarl Neustaedter)

Attachments:

signature.asc (197.00 B)
This is a digitally signed message part

2008-08-22 21:15:50

by John Ronciak

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Fri, Aug 22, 2008 at 1:00 PM, Ian Campbell <[email protected]> wrote:

> So far as I can tell, yes. I can login via ssh so long as the user
> doesn't have NFS $HOME, I haven't tried much else and the box isn't
> locked up at the moment, I'd bet it's fine though.
Then it's highly unlikely that the NIC/driver is causing your problem.
We'll continue to monitor this thread waiting for any info that this
is somehow NIC/driver related.

Good luck.

--
Cheers,
John

2008-08-22 21:23:43

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Fri, 2008-08-22 at 21:00 +0100, Ian Campbell wrote:
> On Fri, 2008-08-22 at 12:33 -0700, John Ronciak wrote:
> > On Fri, Aug 22, 2008 at 11:13 AM, Ian Campbell <[email protected]> wrote:
> >
> > >> That's probably also a networking device driver issue candidate: your
> > >> RPC task is queued up waiting to be sent.
> > >>
> > >> What networking card+device driver are you using here?
> > >
> > > # ethtool -i eth0
> > > driver: e1000
> > > version: 7.3.20-k2-NAPI
> > > firmware-version: N/A
> > > bus-info: 0000:01:0a.0
> > There is nothing indicating that the NIC/driver is causing any sort of
> > problem here, at least not with what has been presented so far. When
> > the NFS mount isn't working is the networking still active and
> > working?
>
> So far as I can tell, yes. I can login via ssh so long as the user
> doesn't have NFS $HOME, I haven't tried much else and the box isn't
> locked up at the moment, I'd bet it's fine though.

...and the server? Something is preventing that RPC payload from being
delivered...

Trond

2008-08-22 21:37:46

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Fri, 2008-08-22 at 14:23 -0700, Trond Myklebust wrote:
> On Fri, 2008-08-22 at 21:00 +0100, Ian Campbell wrote:
> > On Fri, 2008-08-22 at 12:33 -0700, John Ronciak wrote:
> > > On Fri, Aug 22, 2008 at 11:13 AM, Ian Campbell <[email protected]> wrote:
> > >
> > > >> That's probably also a networking device driver issue candidate: your
> > > >> RPC task is queued up waiting to be sent.
> > > >>
> > > >> What networking card+device driver are you using here?
> > > >
> > > > # ethtool -i eth0
> > > > driver: e1000
> > > > version: 7.3.20-k2-NAPI
> > > > firmware-version: N/A
> > > > bus-info: 0000:01:0a.0
> > > There is nothing indicating that the NIC/driver is causing any sort of
> > > problem here, at least not with what has been presented so far. When
> > > the NFS mount isn't working is the networking still active and
> > > working?
> >
> > So far as I can tell, yes. I can login via ssh so long as the user
> > doesn't have NFS $HOME, I haven't tried much else and the box isn't
> > locked up at the moment, I'd bet it's fine though.
>
> ...and the server? Something is preventing that RPC payload from being
> delivered...

I can ssh to the server fine. The same server also serves my NFS home
directory to the box I'm writing this from and I've not seen any trouble
with this box at all, it's a 2.6.18-xen box.

If I downgrade the problematic box to 2.6.24 then the hangs do not
occur. They do occur with 2.6.25. (sorry that's a critical bit of
information which I stupidly forgot to mention up til now).

Ian.

--
Ian Campbell

It is much easier to be critical than to be correct.
-- Benjamin Disraeli

Attachments:

signature.asc (197.00 B)
This is a digitally signed message part

2008-08-22 21:57:21

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Fri, 2008-08-22 at 22:37 +0100, Ian Campbell wrote:
> I can ssh to the server fine. The same server also serves my NFS home
> directory to the box I'm writing this from and I've not seen any trouble
> with this box at all, it's a 2.6.18-xen box.

OK... Are you able to reproduce the problem reliably?

If so, can you provide me with a binary tcpdump or wireshark dump? If
using tcpdump, then please use something like

tcpdump -w /tmp/dump.out -s 90000 host myserver.foo.bar and port 2049

Please also try to provide a netstat dump of the current TCP connections
as soon as the hang occurs:

netstat -t

Cheers
Trond

2008-08-22 22:42:04

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

Attachments:

signature.asc (197.00 B)
This is a digitally signed message part

2008-08-25 10:00:47

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Sun, 2008-08-24 at 18:15 -0400, Trond Myklebust wrote:
> The server should ideally start to close the socket as soon as it
> receives the FIN from the client. I'll have a look at the code.

The server is a 2.6.25 kernel from Debian backports.org. I was planning
to downgrade to the 2.6.24 "Etch and a half" kernel but was holding off
while this thread was in progress. If you think it would be a useful
data point I can do it sooner rather than later.

It's changing the client kernel which seems to make a difference since
running 2.6.24 against this server has given me no trouble. I guess the
newer client could expose a bug in the server though.

Ian.
--
Ian Campbell

I can't understand why a person will take a year or two to write a
novel when he can easily buy one for a few dollars.
-- Fred Allen

Attachments:

signature.asc (197.00 B)
This is a digitally signed message part

2008-08-24 22:15:54

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Sun, 2008-08-24 at 23:09 +0100, Ian Campbell wrote:
> (added some quoting from previous mail to save replying twice)
>
> On Sun, 2008-08-24 at 15:19 -0400, Trond Myklebust wrote:
> > On Sun, 2008-08-24 at 15:17 -0400, Trond Myklebust wrote:
> > > >From the tcpdump, it looks as if the NFS server is failing to close the
> > > socket, when the client closes its side. You therefore end up getting
> > > stuck in the FIN_WAIT2 state (as netstat clearly shows above).
> > >
> > > Is the server keeping the client in this state for a very long
> > > period?
>
> Well, it had been around an hour and a half on this occasion. Next time
> it happens I can wait longer but I'm pretty sure I've come back from
> time away and it's been wedged for at least a day. How long would you
> expect it to remain in this state for?

The server should ideally start to close the socket as soon as it
receives the FIN from the client. I'll have a look at the code.

Trond

2008-08-24 19:17:22

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Sun, 2008-08-24 at 19:53 +0100, Ian Campbell wrote:
> On Fri, 2008-08-22 at 14:56 -0700, Trond Myklebust wrote:
> > On Fri, 2008-08-22 at 22:37 +0100, Ian Campbell wrote:
> > > I can ssh to the server fine. The same server also serves my NFS home
> > > directory to the box I'm writing this from and I've not seen any trouble
> > > with this box at all, it's a 2.6.18-xen box.
> >
> > OK... Are you able to reproduce the problem reliably?
> >
> > If so, can you provide me with a binary tcpdump or wireshark dump? If
> > using tcpdump, then please use something like
> >
> > tcpdump -w /tmp/dump.out -s 90000 host myserver.foo.bar and port 2049
> >
> > Please also try to provide a netstat dump of the current TCP connections
> > as soon as the hang occurs:
> >
> > netstat -t
>
> Aug 24 18:08:59 iranon kernel: [168839.556017] nfs: server hopkins not responding, still trying
> but I wasn't around until 19:38 to spot it.
>
> netstat when I got to it was:
>
> Proto Recv-Q Send-Q Local Address Foreign Address State
> tcp 0 0 localhost.localdo:50891 localhost.localdom:6543 ESTABLISHED
> tcp 1 0 iranon.hellion.org.:ssh azathoth.hellion.:52682 CLOSE_WAIT
> tcp 0 0 localhost.localdom:6543 localhost.localdo:50893 ESTABLISHED
> tcp 0 0 iranon.hellion.org.:837 hopkins.hellion.org:nfs FIN_WAIT2
> tcp 0 0 localhost.localdom:6543 localhost.localdo:41831 ESTABLISHED
> tcp 0 0 localhost.localdo:13666 localhost.localdo:59482 ESTABLISHED
> tcp 0 0 localhost.localdo:34288 localhost.localdom:6545 ESTABLISHED
> tcp 0 0 iranon.hellion.org.:ssh azathoth.hellion.:48977 ESTABLISHED
> tcp 0 0 iranon.hellion.org.:ssh azathoth.hellion.:52683 ESTABLISHED
> tcp 0 0 localhost.localdom:6545 localhost.localdo:34288 ESTABLISHED
> tcp 0 0 localhost.localdom:6543 localhost.localdo:50891 ESTABLISHED
> tcp 0 0 localhost.localdo:50893 localhost.localdom:6543 ESTABLISHED
> tcp 0 0 localhost.localdo:41831 localhost.localdom:6543 ESTABLISHED
> tcp 0 87 localhost.localdo:59482 localhost.localdo:13666 ESTABLISHED
> tcp 1 0 localhost.localdom:6543 localhost.localdo:41830 CLOSE_WAIT
>
> (iranon is the problematic host .4, azathoth is my desktop machine .5, hopkins is the NFS server .6)
>
> tcpdumps are pretty big. I've attached the last 100 packets captured. If
> you need more I can put the full file up somewhere.
>
> -rw-r--r-- 1 root root 1.3G Aug 24 17:57 dump.out0
> -rw-r--r-- 1 root root 536M Aug 24 19:38 dump.out1
>
> Ian.

>From the tcpdump, it looks as if the NFS server is failing to close the
socket, when the client closes its side. You therefore end up getting
stuck in the FIN_WAIT2 state (as netstat clearly shows above).

Is the server keeping the client in this state for a very long period?

Cheers
Trond

2008-08-24 22:12:07

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

(added some quoting from previous mail to save replying twice)

On Sun, 2008-08-24 at 15:19 -0400, Trond Myklebust wrote:
> On Sun, 2008-08-24 at 15:17 -0400, Trond Myklebust wrote:
> > >From the tcpdump, it looks as if the NFS server is failing to close the
> > socket, when the client closes its side. You therefore end up getting
> > stuck in the FIN_WAIT2 state (as netstat clearly shows above).
> >
> > Is the server keeping the client in this state for a very long
> > period?

Well, it had been around an hour and a half on this occasion. Next time
it happens I can wait longer but I'm pretty sure I've come back from
time away and it's been wedged for at least a day. How long would you
expect it to remain in this state for?

> BTW: the RPC client is closing the socket because it detected no NFS
> activity for 5 minutes. Did you expect any NFS activity during this
> time?

It's a mythtv box so at times where no one is watching anything and
there isn't anything to record I expect NFS activity is pretty minimal.

Ian.

--
Ian Campbell

Can anyone remember when the times were not hard, and money not scarce?

Attachments:

signature.asc (197.00 B)
This is a digitally signed message part

2008-08-24 19:20:18

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Sun, 2008-08-24 at 15:17 -0400, Trond Myklebust wrote:
> >From the tcpdump, it looks as if the NFS server is failing to close the
> socket, when the client closes its side. You therefore end up getting
> stuck in the FIN_WAIT2 state (as netstat clearly shows above).

BTW: the RPC client is closing the socket because it detected no NFS
activity for 5 minutes. Did you expect any NFS activity during this
time?

Trond

2008-08-24 18:53:49

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Fri, 2008-08-22 at 14:56 -0700, Trond Myklebust wrote:
> On Fri, 2008-08-22 at 22:37 +0100, Ian Campbell wrote:
> > I can ssh to the server fine. The same server also serves my NFS home
> > directory to the box I'm writing this from and I've not seen any trouble
> > with this box at all, it's a 2.6.18-xen box.
>
> OK... Are you able to reproduce the problem reliably?
>
> If so, can you provide me with a binary tcpdump or wireshark dump? If
> using tcpdump, then please use something like
>
> tcpdump -w /tmp/dump.out -s 90000 host myserver.foo.bar and port 2049
>
> Please also try to provide a netstat dump of the current TCP connections
> as soon as the hang occurs:
>
> netstat -t

Aug 24 18:08:59 iranon kernel: [168839.556017] nfs: server hopkins not responding, still trying
but I wasn't around until 19:38 to spot it.

netstat when I got to it was:

Proto Recv-Q Send-Q Local Address Foreign Address State
tcp 0 0 localhost.localdo:50891 localhost.localdom:6543 ESTABLISHED
tcp 1 0 iranon.hellion.org.:ssh azathoth.hellion.:52682 CLOSE_WAIT
tcp 0 0 localhost.localdom:6543 localhost.localdo:50893 ESTABLISHED
tcp 0 0 iranon.hellion.org.:837 hopkins.hellion.org:nfs FIN_WAIT2
tcp 0 0 localhost.localdom:6543 localhost.localdo:41831 ESTABLISHED
tcp 0 0 localhost.localdo:13666 localhost.localdo:59482 ESTABLISHED
tcp 0 0 localhost.localdo:34288 localhost.localdom:6545 ESTABLISHED
tcp 0 0 iranon.hellion.org.:ssh azathoth.hellion.:48977 ESTABLISHED
tcp 0 0 iranon.hellion.org.:ssh azathoth.hellion.:52683 ESTABLISHED
tcp 0 0 localhost.localdom:6545 localhost.localdo:34288 ESTABLISHED
tcp 0 0 localhost.localdom:6543 localhost.localdo:50891 ESTABLISHED
tcp 0 0 localhost.localdo:50893 localhost.localdom:6543 ESTABLISHED
tcp 0 0 localhost.localdo:41831 localhost.localdom:6543 ESTABLISHED
tcp 0 87 localhost.localdo:59482 localhost.localdo:13666 ESTABLISHED
tcp 1 0 localhost.localdom:6543 localhost.localdo:41830 CLOSE_WAIT

(iranon is the problematic host .4, azathoth is my desktop machine .5, hopkins is the NFS server .6)

tcpdumps are pretty big. I've attached the last 100 packets captured. If
you need more I can put the full file up somewhere.

-rw-r--r-- 1 root root 1.3G Aug 24 17:57 dump.out0
-rw-r--r-- 1 root root 536M Aug 24 19:38 dump.out1

Ian.

--
Ian Campbell

Prizes are for children.
-- Charles Ives, upon being given, but refusing, the
Pulitzer prize

Attachments:

last100.dump.bz2 (105.23 kB)
signature.asc (197.00 B)
This is a digitally signed message part Download all attachments

2008-08-25 16:04:20

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

Trond Myklebust wrote:
> On Sun, 2008-08-24 at 23:09 +0100, Ian Campbell wrote:
>> (added some quoting from previous mail to save replying twice)
>>
>> On Sun, 2008-08-24 at 15:19 -0400, Trond Myklebust wrote:
>>> On Sun, 2008-08-24 at 15:17 -0400, Trond Myklebust wrote:
>>>> >From the tcpdump, it looks as if the NFS server is failing to close the
>>>> socket, when the client closes its side. You therefore end up getting
>>>> stuck in the FIN_WAIT2 state (as netstat clearly shows above).
>>>>
>>>> Is the server keeping the client in this state for a very long
>>>> period?
>> Well, it had been around an hour and a half on this occasion. Next time
>> it happens I can wait longer but I'm pretty sure I've come back from
>> time away and it's been wedged for at least a day. How long would you
>> expect it to remain in this state for?
>
> The server should ideally start to close the socket as soon as it
> receives the FIN from the client. I'll have a look at the code.
>

I don't think it should matter how long the connection stays in FIN WAIT,
the client should reconnect anyway.

Since the client seems to be the variable, I would think it might be an
issue with the client reconnect logic?

That said, 2.6.25 is when the server side transport switch logic went in.

Tom

> Trond
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html

2008-08-25 16:54:33

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Mon, 2008-08-25 at 11:04 -0500, Tom Tucker wrote:
> I don't think it should matter how long the connection stays in FIN WAIT,
> the client should reconnect anyway.

Which would break the replay cache, since we can't reconnect using the
same port.

> Since the client seems to be the variable, I would think it might be an
> issue with the client reconnect logic?

No.

Trond

2008-08-25 20:15:19

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

Trond Myklebust wrote:
> On Mon, 2008-08-25 at 11:04 -0500, Tom Tucker wrote:
>> I don't think it should matter how long the connection stays in FIN WAIT,
>> the client should reconnect anyway.
>
> Which would break the replay cache, since we can't reconnect using the
> same port.
>
>> Since the client seems to be the variable, I would think it might be an
>> issue with the client reconnect logic?
>
> No.
>

Yeah, you're right. I got confused about which host was stuck in FIN_WAIT2.
It's the client as you pointed out earlier.

Thanks,
Tom

> Trond
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html

2008-08-25 20:24:20

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Fri, 22 Aug 2008 14:56:53 -0700, Trond Myklebust <[email protected]> wrote:

>On Fri, 2008-08-22 at 22:37 +0100, Ian Campbell wrote:
>> I can ssh to the server fine. The same server also serves my NFS home
>> directory to the box I'm writing this from and I've not seen any trouble
>> with this box at all, it's a 2.6.18-xen box.
>
>OK... Are you able to reproduce the problem reliably?
>
>If so, can you provide me with a binary tcpdump or wireshark dump? If
>using tcpdump, then please use something like
>
> tcpdump -w /tmp/dump.out -s 90000 host myserver.foo.bar and port 2049
^^^^^^^^--> typo?

man tcpdump:
-s Snarf snaplen bytes of data from each packet rather than the default of
68 (with SunOS's NIT, the minimum is actually 96). 68 bytes is adequate

I've reverted the NFS server to 2.6.24.7 -- inconclusive results for me
'cos NFS stalls seem so random.

Grant.

2008-08-25 21:40:29

by Roger Heflin

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

Ian Campbell wrote:
> (added some quoting from previous mail to save replying twice)
>
> On Sun, 2008-08-24 at 15:19 -0400, Trond Myklebust wrote:
>> On Sun, 2008-08-24 at 15:17 -0400, Trond Myklebust wrote:
>>> >From the tcpdump, it looks as if the NFS server is failing to close the
>>> socket, when the client closes its side. You therefore end up getting
>>> stuck in the FIN_WAIT2 state (as netstat clearly shows above).
>>>
>>> Is the server keeping the client in this state for a very long
>>> period?
>
> Well, it had been around an hour and a half on this occasion. Next time
> it happens I can wait longer but I'm pretty sure I've come back from
> time away and it's been wedged for at least a day. How long would you
> expect it to remain in this state for?
>
>> BTW: the RPC client is closing the socket because it detected no NFS
>> activity for 5 minutes. Did you expect any NFS activity during this
>> time?
>
> It's a mythtv box so at times where no one is watching anything and
> there isn't anything to record I expect NFS activity is pretty minimal.
>
> Ian.
>

Ian,

Do you have a recording group setup on the NFS partition that mythtv is
going to be accessing?

I have seen similar funny stuff happen, it used to happened around 2.6.22*
(on each end), and quit happening around 2.6.24* and now has started happening
again with 2.6.25* on both ends.

Similar to what you have the only thing I see is "NFS server not responding" and
restarting the NFS server end (/etc/init.d/nfs restart) appears to get things to
continue on the NFS client. No other messages appear on either end that
indicate that anything is wrong, other non-nfs partitions on the client work
find, the machine is still up, and the NFS server is still up and fine, and
after a restart things will again work for a while (hours or days).

Roger

2008-08-25 22:11:29

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Tue, 2008-08-26 at 06:23 +1000, Grant Coady wrote:
> On Fri, 22 Aug 2008 14:56:53 -0700, Trond Myklebust <[email protected]> wrote:
>
> >On Fri, 2008-08-22 at 22:37 +0100, Ian Campbell wrote:
> >> I can ssh to the server fine. The same server also serves my NFS home
> >> directory to the box I'm writing this from and I've not seen any trouble
> >> with this box at all, it's a 2.6.18-xen box.
> >
> >OK... Are you able to reproduce the problem reliably?
> >
> >If so, can you provide me with a binary tcpdump or wireshark dump? If
> >using tcpdump, then please use something like
> >
> > tcpdump -w /tmp/dump.out -s 90000 host myserver.foo.bar and port 2049
> ^^^^^^^^--> typo?

No. The intention was to record _all_ the info in the packet for
analysis, not just random header info.

Trond

2008-08-26 00:29:52

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

2008-08-26 00:59:52

by Muntz, Daniel

[permalink] [raw]

Subject: RE: NFS regression? Odd delays and lockups accessing an NFS export.

Try '-s 0', from tcpdump(8): "Setting snaplen to 0 means use the
required length to catch whole packets."

-Dan

-----Original Message-----
From: Grant Coady [mailto:[email protected]]
Sent: Monday, August 25, 2008 5:29 PM
To: Trond Myklebust
Cc: Grant Coady; Ian Campbell; John Ronciak;
[email protected]; [email protected]; [email protected];
[email protected]; Jeff Kirsher; Jesse Brandeburg; Bruce Allan;
PJ Waskiewicz; John Ronciak; [email protected]
Subject: Re: NFS regression? Odd delays and lockups accessing an NFS
export.

On Mon, 25 Aug 2008 18:11:12 -0400, Trond Myklebust
<[email protected]> wrote:

>On Tue, 2008-08-26 at 06:23 +1000, Grant Coady wrote:
>> On Fri, 22 Aug 2008 14:56:53 -0700, Trond Myklebust
<[email protected]> wrote:
>>
>> >On Fri, 2008-08-22 at 22:37 +0100, Ian Campbell wrote:
>> >> I can ssh to the server fine. The same server also serves my NFS
>> >> home directory to the box I'm writing this from and I've not seen
>> >> any trouble with this box at all, it's a 2.6.18-xen box.
>> >
>> >OK... Are you able to reproduce the problem reliably?
>> >
>> >If so, can you provide me with a binary tcpdump or wireshark dump?
>> >If using tcpdump, then please use something like
>> >
>> > tcpdump -w /tmp/dump.out -s 90000 host myserver.foo.bar and port
>> > 2049
>> ^^^^^^^^--> typo?
>
>No. The intention was to record _all_ the info in the packet for
>analysis, not just random header info.

Hi Trond,

My tcpdump seems to have a 16 bit snaplen counter:

~# tcpdump -w /tmp/dump.out -s 65535 host deltree and port 2049
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size
65535 bytes ^C0 packets captured
4 packets received by filter
0 packets dropped by kernel

~# tcpdump -w /tmp/dump.out -s 65536 host deltree and port 2049
tcpdump: invalid snaplen 65536

~# tcpdump --version
tcpdump version 3.9.8
libpcap version 0.9.8

So I'm now using:
~# tcpdump -w /tmp/dump.out -s 65535 -C 10 -W 100 host deltree and port
2049
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size
65535 bytes

to get a 1GB round-robin trace buffer, I can stop the trace when problem
noticed, as it is so long between delay/stall happenings. Then I'll try
to trigger the thing.

Is this the correct style of trace you are expecting?

~$ /usr/sbin/tcpdump -r /tmp/dump.out00
reading from file /tmp/dump.out00, link-type EN10MB (Ethernet)
10:13:49.719781 IP pooh64.mire.mine.nu.2156510591 >
deltree.mire.mine.nu.nfs: 116 access fh 0,1/218104576 001f
10:13:49.720215 IP deltree.mire.mine.nu.nfs >
pooh64.mire.mine.nu.2156510591: reply ok 124 access c 001f
10:13:49.720225 IP pooh64.mire.mine.nu.984 > deltree.mire.mine.nu.nfsd:
. ack 1649405551 win 5840
10:13:49.720288 IP pooh64.mire.mine.nu.2173287807 >
deltree.mire.mine.nu.nfs: 136 readdirplus fh 0,1/218104576 512 bytes @ 0
10:13:49.742450 IP deltree.mire.mine.nu.nfs >
pooh64.mire.mine.nu.2173287807: reply ok 1460 readdirplus

Is there some test suite I can use? Compiling kernels over NFS worked
fine yesterday, apart from the fastest box' make complaining about clock
skew. The kernel booted though, so that was okay.

Guess it's back to the interactive editing over NFS and see if the thing
manifest the delay/stalls again, I'm on the .27-rc4-git4 kernel as soon
as it compiles for the client, NFS server is 2.6.24.7 at the moment.

Grant.

2008-08-26 01:07:26

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Mon, 25 Aug 2008 18:11:12 -0400, Trond Myklebust <[email protected]> wrote:

>On Tue, 2008-08-26 at 06:23 +1000, Grant Coady wrote:
>> On Fri, 22 Aug 2008 14:56:53 -0700, Trond Myklebust <[email protected]> wrote:
>>
>> >On Fri, 2008-08-22 at 22:37 +0100, Ian Campbell wrote:
>> >> I can ssh to the server fine. The same server also serves my NFS home
>> >> directory to the box I'm writing this from and I've not seen any trouble
>> >> with this box at all, it's a 2.6.18-xen box.
>> >
>> >OK... Are you able to reproduce the problem reliably?
>> >
>> >If so, can you provide me with a binary tcpdump or wireshark dump? If
>> >using tcpdump, then please use something like
>> >
>> > tcpdump -w /tmp/dump.out -s 90000 host myserver.foo.bar and port 2049
>> ^^^^^^^^--> typo?
>
>No. The intention was to record _all_ the info in the packet for
>analysis, not just random header info.

I booted 2.6.27-rc4-git4a and started the tcpdump trace as described in
last email, got an immediate stall which cleared after 10-20 seconds, on
running a small script exported from the NFS server as user:

~$ cat /home/common/bin/boot-report
#! /bin/bash
#
version=$(uname -r)

dmesg >/home/common/dmesg-$version

# 2006-12-15 no more filter .config
#grep = /boot/config-$version >/home/common/config-$version
cp /boot/config-$version /home/common

The script had not created the file on the server when the command prompt
returned, during the stall I also opened another client terminal and ran
'df', it stalled too, and both client terminals came back to prompt after
the 10-20s delay. Then I hit Ctrl-C on the tcpdump terminal to prepare
this report.

The trace is only 27 lines, deltree is the server, pooh64 the client:
grant@pooh64:~$ /usr/sbin/tcpdump -r /tmp/dump.out00
reading from file /tmp/dump.out00, link-type EN10MB (Ethernet)
10:42:14.061410 IP pooh64.mire.mine.nu.0 > deltree.mire.mine.nu.nfs: 0 null
10:42:14.062691 IP deltree.mire.mine.nu.nfsd > pooh64.mire.mine.nu.839: S 2746115414:2746115414(0) ack 3659136038 win 5840 <mss 1460,nop,nop,sackOK>
10:42:14.062708 IP pooh64.mire.mine.nu.839 > deltree.mire.mine.nu.nfsd: . ack 1 win 5840
10:42:14.062750 IP pooh64.mire.mine.nu.1392480046 > deltree.mire.mine.nu.nfs: 112 getattr fh 0,1/218104576
10:42:14.062765 IP pooh64.mire.mine.nu.1409257262 > deltree.mire.mine.nu.nfs: 112 fsstat fh 0,1/218104576
10:42:14.062944 IP deltree.mire.mine.nu.nfsd > pooh64.mire.mine.nu.839: . ack 113 win 5840
10:42:14.062951 IP deltree.mire.mine.nu.nfsd > pooh64.mire.mine.nu.839: . ack 225 win 5840
10:42:14.063873 IP deltree.mire.mine.nu.nfs > pooh64.mire.mine.nu.1392480046: reply ok 116 getattr DIR 40755 ids 1000/10 sz 448
10:42:14.063881 IP pooh64.mire.mine.nu.839 > deltree.mire.mine.nu.nfsd: . ack 117 win 5840
10:42:14.063890 IP deltree.mire.mine.nu.nfs > pooh64.mire.mine.nu.1409257262: reply ok 88 fsstat tbytes 8422359040 fbytes 6605647872 abytes 6605647872
10:42:14.063893 IP pooh64.mire.mine.nu.839 > deltree.mire.mine.nu.nfsd: . ack 205 win 5840
10:42:14.064319 IP pooh64.mire.mine.nu.1426034478 > deltree.mire.mine.nu.nfs: 116 access fh 0,1/218104576 001f
10:42:14.064677 IP deltree.mire.mine.nu.nfs > pooh64.mire.mine.nu.1426034478: reply ok 124 access c 001f
10:42:14.064732 IP pooh64.mire.mine.nu.1442811694 > deltree.mire.mine.nu.nfs: 136 readdirplus fh 0,1/218104576 512 bytes @ 0
10:42:14.067193 IP deltree.mire.mine.nu.nfs > pooh64.mire.mine.nu.1442811694: reply ok 1460 readdirplus
10:42:14.067203 IP pooh64.mire.mine.nu.839 > deltree.mire.mine.nu.nfsd: . ack 1789 win 8760
10:42:14.067208 IP deltree.mire.mine.nu.nfs > pooh64.mire.mine.nu.841889326: reply ok 1324
10:42:14.067328 IP pooh64.mire.mine.nu.1459588910 > deltree.mire.mine.nu.nfs: 112 getattr fh Unknown/010000000003000D0200000000000024010000060003000D02000000FE6F0000
10:42:14.068572 IP deltree.mire.mine.nu.nfs > pooh64.mire.mine.nu.1459588910: reply ok 116 getattr DIR 40755 ids 1000/10 sz 448
10:42:14.068619 IP pooh64.mire.mine.nu.1476366126 > deltree.mire.mine.nu.nfs: 136 getattr fh Unknown/010000060003000D02000000676A000002000000000000000200000001000000
10:42:14.070615 IP deltree.mire.mine.nu.nfs > pooh64.mire.mine.nu.1476366126: reply ok 116 getattr DIR 40755 ids 1000/10 sz 360
10:42:14.070652 IP pooh64.mire.mine.nu.1493143342 > deltree.mire.mine.nu.nfs: 140 access fh Unknown/010000060003000D02000000676A000002000000000000000200000001000000 001f
10:42:14.071576 IP deltree.mire.mine.nu.nfs > pooh64.mire.mine.nu.1493143342: reply ok 124 access c 001f
10:42:14.071638 IP pooh64.mire.mine.nu.1509920558 > deltree.mire.mine.nu.nfs: 160 readdirplus fh Unknown/010000060003000D02000000676A000002000000000000000200000001000000 512 bytes @ 0
10:42:14.073382 IP deltree.mire.mine.nu.nfs > pooh64.mire.mine.nu.1509920558: reply ok 1460 readdirplus
10:42:14.074096 IP deltree.mire.mine.nu.nfs > pooh64.mire.mine.nu.0: reply Unknown rpc response code=6 516
10:42:14.074102 IP pooh64.mire.mine.nu.839 > deltree.mire.mine.nu.nfsd: . ack 5445 win 17520

Sorry I forgot to do the netstat -t.

Attached the tcpdump file in case there's more info in it.

config and dmesg for client at:
http://bugsplatter.id.au/kernel/boxen/pooh64/config-2.6.27-rc4-git4a
http://bugsplatter.id.au/kernel/boxen/pooh64/dmesg-2.6.27-rc4-git4a

for server:
http://bugsplatter.id.au/kernel/boxen/deltree/config-2.6.24.7a.gz
http://bugsplatter.id.au/kernel/boxen/deltree/dmesg-2.6.24.7a.gz

Grant.

Attachments:

dump.out00.gz (2.23 kB)
pooh64-2.6.27-rc4-git4a

2008-08-26 19:28:01

by J. Bruce Fields

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Mon, Aug 25, 2008 at 11:04:08AM -0500, Tom Tucker wrote:
> Trond Myklebust wrote:
>> On Sun, 2008-08-24 at 23:09 +0100, Ian Campbell wrote:
>>> (added some quoting from previous mail to save replying twice)
>>>
>>> On Sun, 2008-08-24 at 15:19 -0400, Trond Myklebust wrote:
>>>> On Sun, 2008-08-24 at 15:17 -0400, Trond Myklebust wrote:
>>>>> >From the tcpdump, it looks as if the NFS server is failing to close the
>>>>> socket, when the client closes its side. You therefore end up getting
>>>>> stuck in the FIN_WAIT2 state (as netstat clearly shows above).
>>>>>
>>>>> Is the server keeping the client in this state for a very long
>>>>> period?
>>> Well, it had been around an hour and a half on this occasion. Next time
>>> it happens I can wait longer but I'm pretty sure I've come back from
>>> time away and it's been wedged for at least a day. How long would you
>>> expect it to remain in this state for?
>>
>> The server should ideally start to close the socket as soon as it
>> receives the FIN from the client. I'll have a look at the code.
>>
>
> I don't think it should matter how long the connection stays in FIN WAIT,
> the client should reconnect anyway.
>
> Since the client seems to be the variable, I would think it might be an
> issue with the client reconnect logic?
>
> That said, 2.6.25 is when the server side transport switch logic went in.

Any chance you could help Trond figure out why the server might be doing
this?

If not, I'll get to it, but not as soon as I should.

--b.

2008-08-27 14:43:19

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

J. Bruce Fields wrote:
> On Mon, Aug 25, 2008 at 11:04:08AM -0500, Tom Tucker wrote:
>> Trond Myklebust wrote:
>>> On Sun, 2008-08-24 at 23:09 +0100, Ian Campbell wrote:
>>>> (added some quoting from previous mail to save replying twice)
>>>>
>>>> On Sun, 2008-08-24 at 15:19 -0400, Trond Myklebust wrote:
>>>>> On Sun, 2008-08-24 at 15:17 -0400, Trond Myklebust wrote:
>>>>>> >From the tcpdump, it looks as if the NFS server is failing to close the
>>>>>> socket, when the client closes its side. You therefore end up getting
>>>>>> stuck in the FIN_WAIT2 state (as netstat clearly shows above).
>>>>>>
>>>>>> Is the server keeping the client in this state for a very long
>>>>>> period?
>>>> Well, it had been around an hour and a half on this occasion. Next time
>>>> it happens I can wait longer but I'm pretty sure I've come back from
>>>> time away and it's been wedged for at least a day. How long would you
>>>> expect it to remain in this state for?
>>> The server should ideally start to close the socket as soon as it
>>> receives the FIN from the client. I'll have a look at the code.
>>>
>> I don't think it should matter how long the connection stays in FIN WAIT,
>> the client should reconnect anyway.
>>
>> Since the client seems to be the variable, I would think it might be an
>> issue with the client reconnect logic?
>>
>> That said, 2.6.25 is when the server side transport switch logic went in.
>
> Any chance you could help Trond figure out why the server might be doing
> this?
>
> If not, I'll get to it, but not as soon as I should.
>

Sure. I've actually tried to reproduce it here unsuccessfully.

As a starter, I would suggest turning on transport debugging:

# echo 256 > /proc/sys/sunrpc/rpc_debug

Here are my thoughts on how it is supposed to work. Trond if this doesn't match
your understanding, please let me know.

For the case where the client closes the connection first
because it's timeout is shorter (5min vs. 6), the sequence of events should be:

client server

close
sends FIN goes to FIN-WAIT-1
receives FIN replies with ACK
and goes to CLOSE-WAIT
receives ACK goes to FIN-WAIT-2
calls tcp_state_change callback on socket
svc_tcp_state_change sets XPT_CLOSE on
the transport and enqueues transport for
servicing by svc thread.

thread gets dequeued, calls svc_recv
svc_recv sees XPT_CLOSE and calls
svc_xprt_destroy that closes the socket

TCP sends FIN/ACK after close
receives FIN/ACK goes to TIME-WAIT

since state is TIME-WAIT and
reuse port is set, we can re-connect

There's a couple places we could be getting stuck:

- The state-change callback never gets called.
- The state-change callback gets called but svsk is null and it ignores the event
- svc_tcp_state_change enqueues the transport, but due to a race bug, the transport
doesn't actually get queued and since there is no activity it never closes
- something else

The message log with RPCDBG_SVCXPRT (256) enabled as shown above would help figure
out where it's happening.

If Ian is willing to create the log (or already has one), I'm certainly willing to
look at it.

Tom

> --b.
> --
> To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html

2008-08-30 15:48:09

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Wed, 2008-08-27 at 09:43 -0500, Tom Tucker wrote:
> Sure. I've actually tried to reproduce it here unsuccessfully.
>
> As a starter, I would suggest turning on transport debugging:
>
> # echo 256 > /proc/sys/sunrpc/rpc_debug
> [...]
> If Ian is willing to create the log (or already has one), I'm
> certainly willing to look at it.

It produced only the following (is that what was expected?):

[146866.448112] -pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--
[146866.448112] 30576 0001 00a0 0 f77a1600 100003 f7903340 15000 xprt_pending fa0ba88e fa0c9df4
[146866.448112] 30577 0004 0080 -11 f77a1600 100003 f7903000 0 xprt_sending fa0ba88e fa0c9df4

Ian.
--
Ian Campbell

Life is a concentration camp. You're stuck here and there's no way
out and you can only rage impotently against your persecutors.
-- Woody Allen

Attachments:

signature.asc (197.00 B)
This is a digitally signed message part

2008-08-31 19:30:59

by J. Bruce Fields

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Sat, Aug 30, 2008 at 04:47:41PM +0100, Ian Campbell wrote:
> On Wed, 2008-08-27 at 09:43 -0500, Tom Tucker wrote:
> > Sure. I've actually tried to reproduce it here unsuccessfully.
> >
> > As a starter, I would suggest turning on transport debugging:
> >
> > # echo 256 > /proc/sys/sunrpc/rpc_debug
> > [...]
> > If Ian is willing to create the log (or already has one), I'm
> > certainly willing to look at it.
>
> It produced only the following (is that what was expected?):
>
> [146866.448112] -pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--
> [146866.448112] 30576 0001 00a0 0 f77a1600 100003 f7903340 15000 xprt_pending fa0ba88e fa0c9df4
> [146866.448112] 30577 0004 0080 -11 f77a1600 100003 f7903000 0 xprt_sending fa0ba88e fa0c9df4

It's normal to get something like that when you turn it on, yes (unless
someone else spots anything odd about that...) but what's really needed
is to turn this on and then reproduce the problem--it's the debugging
output that goes to the logs during the problem that'll be interesting.

--b.

2008-08-31 19:44:24

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Sun, 2008-08-31 at 15:30 -0400, J. Bruce Fields wrote:
> On Sat, Aug 30, 2008 at 04:47:41PM +0100, Ian Campbell wrote:
> > On Wed, 2008-08-27 at 09:43 -0500, Tom Tucker wrote:
> > > Sure. I've actually tried to reproduce it here unsuccessfully.
> > >
> > > As a starter, I would suggest turning on transport debugging:
> > >
> > > # echo 256 > /proc/sys/sunrpc/rpc_debug
> > > [...]
> > > If Ian is willing to create the log (or already has one), I'm
> > > certainly willing to look at it.
> >
> > It produced only the following (is that what was expected?):
> >
> > [146866.448112] -pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--
> > [146866.448112] 30576 0001 00a0 0 f77a1600 100003 f7903340 15000 xprt_pending fa0ba88e fa0c9df4
> > [146866.448112] 30577 0004 0080 -11 f77a1600 100003 f7903000 0 xprt_sending fa0ba88e fa0c9df4
>
> It's normal to get something like that when you turn it on, yes (unless
> someone else spots anything odd about that...) but what's really needed
> is to turn this on and then reproduce the problem--it's the debugging
> output that goes to the logs during the problem that'll be interesting.

That's what I did. The first time I did the echo I just got the header
line, then I waited for the repro and since there had been no further
logging I ran the echo again and got the three lines above.

Sounds like you expected there to be more and ongoing logging?

Ian.

> --b.
>
--
Ian Campbell

kernel, n.:
A part of an operating system that preserves the medieval
traditions of sorcery and black art.

Attachments:

signature.asc (197.00 B)
This is a digitally signed message part

2008-08-31 19:46:30

by J. Bruce Fields

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Sun, Aug 31, 2008 at 08:44:02PM +0100, Ian Campbell wrote:
> On Sun, 2008-08-31 at 15:30 -0400, J. Bruce Fields wrote:
> > On Sat, Aug 30, 2008 at 04:47:41PM +0100, Ian Campbell wrote:
> > > On Wed, 2008-08-27 at 09:43 -0500, Tom Tucker wrote:
> > > > Sure. I've actually tried to reproduce it here unsuccessfully.
> > > >
> > > > As a starter, I would suggest turning on transport debugging:
> > > >
> > > > # echo 256 > /proc/sys/sunrpc/rpc_debug
> > > > [...]
> > > > If Ian is willing to create the log (or already has one), I'm
> > > > certainly willing to look at it.
> > >
> > > It produced only the following (is that what was expected?):
> > >
> > > [146866.448112] -pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--
> > > [146866.448112] 30576 0001 00a0 0 f77a1600 100003 f7903340 15000 xprt_pending fa0ba88e fa0c9df4
> > > [146866.448112] 30577 0004 0080 -11 f77a1600 100003 f7903000 0 xprt_sending fa0ba88e fa0c9df4
> >
> > It's normal to get something like that when you turn it on, yes (unless
> > someone else spots anything odd about that...) but what's really needed
> > is to turn this on and then reproduce the problem--it's the debugging
> > output that goes to the logs during the problem that'll be interesting.
>
> That's what I did. The first time I did the echo I just got the header
> line, then I waited for the repro and since there had been no further
> logging I ran the echo again and got the three lines above.
>
> Sounds like you expected there to be more and ongoing logging?

Yes. It's the server side we're interested in, by the way--are you
collecting this deubgging on the client?

--b.

2008-08-31 19:50:26

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

On Sun, 2008-08-31 at 15:46 -0400, J. Bruce Fields wrote:
> Yes. It's the server side we're interested in, by the way--are you
> collecting this deubgging on the client?

Er, yeah, since the client appeared to be the problem.

I'll try again on the server!

Ian.
--
Ian Campbell

The descent to Hades is the same from every place.
-- Anaxagoras

Attachments:

signature.asc (197.00 B)
This is a digitally signed message part

2008-08-31 19:51:41

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

Ian Campbell wrote:
> On Sun, 2008-08-31 at 15:30 -0400, J. Bruce Fields wrote:
>> On Sat, Aug 30, 2008 at 04:47:41PM +0100, Ian Campbell wrote:
>>> On Wed, 2008-08-27 at 09:43 -0500, Tom Tucker wrote:
>>>> Sure. I've actually tried to reproduce it here unsuccessfully.
>>>>
>>>> As a starter, I would suggest turning on transport debugging:
>>>>
>>>> # echo 256 > /proc/sys/sunrpc/rpc_debug
>>>> [...]
>>>> If Ian is willing to create the log (or already has one), I'm
>>>> certainly willing to look at it.
>>> It produced only the following (is that what was expected?):
>>>
>>> [146866.448112] -pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--
>>> [146866.448112] 30576 0001 00a0 0 f77a1600 100003 f7903340 15000 xprt_pending fa0ba88e fa0c9df4
>>> [146866.448112] 30577 0004 0080 -11 f77a1600 100003 f7903000 0 xprt_sending fa0ba88e fa0c9df4
>> It's normal to get something like that when you turn it on, yes (unless
>> someone else spots anything odd about that...) but what's really needed
>> is to turn this on and then reproduce the problem--it's the debugging
>> output that goes to the logs during the problem that'll be interesting.
>
> That's what I did. The first time I did the echo I just got the header
> line, then I waited for the repro and since there had been no further
> logging I ran the echo again and got the three lines above.
>
> Sounds like you expected there to be more and ongoing logging?
>
> Ian.
>

Looks like you ran this on the client. Sorry, Ian, I should have been more
specific. You need to modify the rpc_debug file on the server.

Tom

>> --b.
>>

2008-08-31 19:52:13

[permalink] [raw]

Subject: Re: NFS regression? Odd delays and lockups accessing an NFS export.

Ian Campbell wrote:
> On Sun, 2008-08-31 at 15:46 -0400, J. Bruce Fields wrote:
>> Yes. It's the server side we're interested in, by the way--are you
>> collecting this deubgging on the client?
>
> Er, yeah, since the client appeared to be the problem.
>
> I'll try again on the server!
>

Thanks Ian,

Tom

> Ian.

2008-08-31 21:18:42