Re: v3.5 nfsd4 regression; utime sometimes takes 40+ seconds to return

[Jamie Heilman <jamie@audible.transient.net>]

[-- Attachment #1: Type: text/plain, Size: 3180 bytes --]

J. Bruce Fields wrote:
> On Wed, Aug 15, 2012 at 01:58:54PM +0000, Jamie Heilman wrote:
> > Jamie Heilman wrote:
> > > I'll try to get full rcpdebug traces on client and server as the delay
> > > is occuring in the hopes that helps pin things down, and post them
> > > separately.
> > 
> > OK, here are the logs from client and server, where a run of my test program
> > under strace -T resulted in:
> > 
> > utime("utime-test.c", [2012/08/15-13:35:20, 2012/08/15-13:22:04]) = 0 <0.150815>
> > open("utime-test.c", O_RDONLY)          = 3 <0.242635>
> > close(3)                                = 0 <0.147768>
> > stat("utime-test.c", {st_mode=S_IFREG|0644, st_size=696, ...}) = 0 <0.002772>
> > utime("utime-test.c", [2012/08/15-13:35:20, 2012/08/15-13:22:04]) = 0 <71.878058>
> > 
> > The client is a 64-bit v3.4.8 kernel, the server is 32-bit, v3.5.1 +
> > the two sunprc patches that will be in v3.5.2.
> > 
> > (The client's system clock is a touch faster than the server's, but
> > these logs start at the same instant.)
> 
> Thanks for all the details.
> 
> What's probably happening is that the client is returning a delegation
> with the open.  The setattr then breaks that delegation; you can see it
> getting 10008 (NFS4ERR_DELAY) replies while the server waits for the
> delegation to be returned.  But for some reason the callback to break
> the delegation isn't working.  ("NFSD: warning: no callback path to
> client 192.168.2.42/192.168.2.4 tcp UNIX 0: error -110" (110 is
> ETIMEDOUT).)  So instead you wait for the delegation to time out and get
> forcibly revoked.
> 
> The reproducer might be more reliable if you did two opens.

I made the change... not entirely sure it helped, but I think I've
bisected this reliably anyway.  It came down to:

d5497fc693a446ce9100fcf4117c3f795ddfd0d2 is the first bad commit
commit d5497fc693a446ce9100fcf4117c3f795ddfd0d2
Author: J. Bruce Fields <bfields@redhat.com>
Date:   Mon May 14 22:06:49 2012 -0400

    nfsd4: move rq_flavor into svc_cred
    
    Move the rq_flavor into struct svc_cred, and use it in setclientid and
    exchange_id comparisons as well.
    
    Signed-off-by: J. Bruce Fields <bfields@redhat.com>

:040000 040000 165568aae0fc47067863ea8ca911494033cbf2ce 54244f0084f58df4844b09d56e8e6bad0e19d913 M      fs
:040000 040000 bae5a74a85bda2aa2b155b0bdca1ea0028502164 207751ce30c8f49c68fb0a85d0772cb0fa426ae1 M      include
:040000 040000 ef940cf0c558fe65a21a710e6c95b2cefb2996fd 459ac143acf5cb2b3b7f59df29c417cedbb23c4b M      net

FWIW reverting this commit does seem to fix the problem.

> It'd be worth looking at the traffic in wireshark.  You should see
> setattr, open, close, setattr, a DELAY reply to the setattr, a
> CB_RECALL, and then a DELEGRETURN that gets a succesful reply.  But for
> some reason the DELEGRETURN isn't getting through in your case, I'm not
> sure why.  I can't reproduce that.  You'll need to start wireshark
> before you mount to make sure it knows how to parse the callbacks.

Captures from the server showing the delay (running 3.5.2) and the
previous behavior (running 3.4.9) are attached.

-- 
Jamie Heilman                     http://audible.transient.net/~jamie/

[-- Attachment #2: nfsd4-delay.pcap.gz --]
[-- Type: application/octet-stream, Size: 8805 bytes --]

[-- Attachment #3: nfsd4-ok.pcap.gz --]
[-- Type: application/octet-stream, Size: 7270 bytes --]