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

This is a discussion on NFS regression? Odd delays and lockups accessing an NFS export. - Kernel ; 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 ...

+ Reply to Thread
Page 2 of 3 FirstFirst 1 2 3 LastLast
Results 21 to 40 of 59

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

  1. 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

    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  2. 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

    -----BEGIN PGP SIGNATURE-----
    Version: GnuPG v1.4.9 (GNU/Linux)

    iEYEABECAAYFAkiygoMACgkQM0+0qS9rzVnsagCgzryVDvY2DQ/Trdq5Co7Vvbpx
    sr4AnR3rwXc7aCbdRKGaj44oQuIYinRZ
    =Weq0
    -----END PGP SIGNATURE-----


  3. 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 majordomo@vger.kernel.org
    > More majordomo info at http://vger.kernel.org/majordomo-info.html


    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  4. 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

    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  5. 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 majordomo@vger.kernel.org
    > More majordomo info at http://vger.kernel.org/majordomo-info.html


    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

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

    On Fri, 22 Aug 2008 14:56:53 -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

    ^^^^^^^^--> 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.
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  7. 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
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  8. 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 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

    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

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

    On Mon, 25 Aug 2008 18:11:12 -0400, Trond Myklebust wrote:

    >On Tue, 2008-08-26 at 06:23 +1000, Grant Coady wrote:
    >> On Fri, 22 Aug 2008 14:56:53 -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

    >> ^^^^^^^^--> 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.
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  10. 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:grant_lkml@dodo.com.au]
    Sent: Monday, August 25, 2008 5:29 PM
    To: Trond Myklebust
    Cc: Grant Coady; Ian Campbell; John Ronciak;
    linux-kernel@vger.kernel.org; neilb@suse.de; bfields@fieldses.org;
    linux-nfs@vger.kernel.org; Jeff Kirsher; Jesse Brandeburg; Bruce Allan;
    PJ Waskiewicz; John Ronciak; e1000-devel@lists.sourceforge.net
    Subject: Re: NFS regression? Odd delays and lockups accessing an NFS
    export.

    On Mon, 25 Aug 2008 18:11:12 -0400, Trond Myklebust
    wrote:

    >On Tue, 2008-08-26 at 06:23 +1000, Grant Coady wrote:
    >> On Fri, 22 Aug 2008 14:56:53 -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

    >> ^^^^^^^^--> 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.
    --
    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
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

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

    On Mon, 25 Aug 2008 18:11:12 -0400, Trond Myklebust wrote:

    >On Tue, 2008-08-26 at 06:23 +1000, Grant Coady wrote:
    >> On Fri, 22 Aug 2008 14:56:53 -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

    >> ^^^^^^^^--> 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
    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/010000000003000D0200000000000024010000060003000D02 000000FE6F0000
    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/010000060003000D02000000676A0000020000000000000002 00000001000000
    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/010000060003000D02000000676A0000020000000000000002 00000001000000 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/010000060003000D02000000676A0000020000000000000002 00000001000000 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/boxe...6.27-rc4-git4a
    http://bugsplatter.id.au/kernel/boxe...6.27-rc4-git4a

    for server:
    http://bugsplatter.id.au/kernel/boxe...g-2.6.24.7a.gz
    http://bugsplatter.id.au/kernel/boxe...g-2.6.24.7a.gz

    Grant.


  12. 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.
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  13. 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 majordomo@vger.kernel.org
    > More majordomo info at http://vger.kernel.org/majordomo-info.html


    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  14. 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

    -----BEGIN PGP SIGNATURE-----
    Version: GnuPG v1.4.9 (GNU/Linux)

    iEYEABECAAYFAki5a50ACgkQM0+0qS9rzVkKVgCffqWaEb2ozX NfneXRttb4Dr1d
    4JEAnRuuBKBw8K0HNcSJU+mr29qgEsjF
    =qFux
    -----END PGP SIGNATURE-----


  15. 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.
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  16. 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.
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  17. 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.

    -----BEGIN PGP SIGNATURE-----
    Version: GnuPG v1.4.9 (GNU/Linux)

    iEYEABECAAYFAki69IIACgkQM0+0qS9rzVnkYgCfWrYh529Bqt 8yNRz176054Y2e
    1d8AoLXxBJLlJph71wmqItVaQ9/hgtg3
    =cHPe
    -----END PGP SIGNATURE-----


  18. 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.


    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  19. 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.
    >>


    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  20. 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

    -----BEGIN PGP SIGNATURE-----
    Version: GnuPG v1.4.9 (GNU/Linux)

    iEYEABECAAYFAki69bkACgkQM0+0qS9rzVklXACgmAYGxBgg2H S6RR/9KRxm0J4K
    W+MAmgNcLUcB5n4Lp33Jy+jGo4SlOtmq
    =+QJm
    -----END PGP SIGNATURE-----


+ Reply to Thread
Page 2 of 3 FirstFirst 1 2 3 LastLast