(fwd) nfs hang on 2.6.24

(fwd) nfs hang on 2.6.24

[maximilian attems]

please take a look

----- Forwarded message from Andrew Dixie <andrew-0FSrDVjkvKm9koe0gwxAeg@public.gmane.org> -----

Date: Tue, 5 Feb 2008 12:57:37 +1300 (NZDT)
Subject: nfs hang on 2.6.24
From: Andrew Dixie <andrew-0FSrDVjkvKm9koe0gwxAeg@public.gmane.org>
To: debian-kernel@lists.debian.org

I've recently updated to 2.6.24 as recommended on bug 463508.

But the new kernel now has nfs hanging problems.
A few times now it has got into a situation such that any process that
touches an nfs mount hangs.

The machine has both nfs3 and nfs4 mounts. My suspicion is that it relates
to putting a heavy load on both nfs3 and nfs4 mounts at the same time.

The machine for the moment is still hung so let me know if there are
further debugging steps I can perform.

There are many other processes but these are the unique call stacks that
involve nfs related functions.

 =======================
nfsv4-delegre S 00000282     0 17156      2
       df8dcd30 00000046 f8c5f813 00000282 f35d4a60 00000000 93c19d62
000008a4
       df8dce98 c180a940 00000000 f35d4b10 0000a296 00000000 f669be00
f8ce9b74
       f8c5f08b 00000246 e6a59f34 00000000 e6a59f3c c18003b0 f8c62e85
c02bc97f
Call Trace:
 [<f8c5f813>] xprt_timer+0x0/0x6f [sunrpc]
 [<f8ce9b74>] nfs4_xdr_enc_delegreturn+0x0/0x84 [nfs]
 [<f8c5f08b>] xprt_release_xprt+0x39/0x66 [sunrpc]
 [<f8c62e85>] rpc_wait_bit_interruptible+0x1a/0x1f [sunrpc]
 [<c02bc97f>] __wait_on_bit+0x33/0x58
 [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
 [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
 [<c02bca07>] out_of_line_wait_on_bit+0x63/0x6b
 [<c013545e>] wake_bit_function+0x0/0x3c
 [<f8c62e19>] __rpc_wait_for_completion_task+0x32/0x39 [sunrpc]
 [<f8ce1352>] nfs4_wait_for_completion_rpc_task+0x1b/0x2f [nfs]
 [<f8ce2336>] nfs4_proc_delegreturn+0x116/0x172 [nfs]
 [<f8ced370>] nfs_do_return_delegation+0xf/0x1d [nfs]
 [<f8ced88a>] recall_thread+0xad/0xc0 [nfs]
 [<f8ced7dd>] recall_thread+0x0/0xc0 [nfs]
 [<c0104b0f>] kernel_thread_helper+0x7/0x10
 =======================
mysqld        S f704db38     0  3156   3110
       df848130 00000082 00000002 f704db38 f704db30 00000000 6369898c
0000052b
       df848298 c1822940 00000003 0163574b f704db5c f7c86000 000000ff
00000000
       00000000 00000000 f704db5c 016359d3 f7459140 000001f4 c02bc84e
00000001
Call Trace:
 [<c02bc84e>] schedule_timeout+0x70/0x8d
 [<c01048c3>] common_interrupt+0x23/0x28
 [<c012c3e2>] process_timeout+0x0/0x5
 [<c02bc849>] schedule_timeout+0x6b/0x8d
 [<c0183476>] do_select+0x365/0x3bc
 [<c0183a60>] __pollwait+0x0/0xac
 [<c011e069>] enqueue_entity+0x2b/0x3d
 [<c0115343>] apic_wait_icr_idle+0xe/0x15
 [<c011e091>] enqueue_task_fair+0x16/0x24
 [<c011d647>] enqueue_task+0x52/0x5d
 [<c011de8a>] resched_task+0x52/0x54
 [<c011f445>] try_to_wake_up+0x2b8/0x2c2
 [<c013543e>] autoremove_wake_function+0x15/0x35
 [<c011d482>] __wake_up_common+0x32/0x5c
 [<c011eeb8>] __wake_up+0x32/0x42
 [<c013540e>] __wake_up_bit+0x2e/0x33
 [<f8c630f5>] __rpc_do_wake_up_task+0x1fb/0x218 [sunrpc]
 [<f8c6003a>] xdr_partial_copy_from_skb+0x32/0x171 [sunrpc]
 [<f8c63148>] rpc_wake_up_task+0x36/0x4a [sunrpc]
 [<f8c61cfd>] xs_tcp_data_recv+0x3d3/0x407 [sunrpc]
 [<f8c6028f>] xdr_skb_read_bits+0x0/0x35 [sunrpc]
 [<c0259bb5>] skb_release_all+0xa3/0xfa
 [<c028484c>] tcp_read_sock+0x15e/0x16a
 [<f8c6192a>] xs_tcp_data_recv+0x0/0x407 [sunrpc]
 [<f8c624a8>] xs_tcp_data_ready+0x55/0x61 [sunrpc]
 [<c012c8ec>] mod_timer+0x19/0x36
 [<c02564e7>] sk_reset_timer+0xc/0x16
 [<c028ba16>] tcp_rcv_established+0x3ae/0x63c
 [<c0290ceb>] tcp_v4_do_rcv+0x2b/0x343
 [<f8a593a5>] ip_vs_in+0xa5/0x220 [ip_vs]
 [<f8a59300>] ip_vs_in+0x0/0x220 [ip_vs]
 [<c0293000>] tcp_v4_rcv+0x80e/0x882
 [<c0183750>] core_sys_select+0x283/0x2a0
 [<c027a934>] ip_local_deliver_finish+0x114/0x1b7
 [<c0259c6b>] __alloc_skb+0x49/0xf7
 [<c0259bb5>] skb_release_all+0xa3/0xfa
 [<f8833e62>] e1000_alloc_rx_buffers+0x1cb/0x295 [e1000]
 [<c02594b1>] __kfree_skb+0x8/0x61
 [<f88301f9>] e1000_unmap_and_free_tx_resource+0x1b/0x23 [e1000]
 [<f8831c09>] e1000_clean_tx_irq+0xbe/0x2c3 [e1000]
 [<f883480e>] e1000_clean_rx_irq+0x419/0x449 [e1000]
 [<f88343f5>] e1000_clean_rx_irq+0x0/0x449 [e1000]
 [<f8832045>] e1000_clean+0x1e9/0x213 [e1000]
 [<c025fe81>] net_rx_action+0x9f/0x198
 [<c0183bb0>] sys_select+0xa4/0x187
 [<c0103e5e>] sysenter_past_esp+0x6b/0xa1
 =======================
sshd          S f74fdc80     0 17157   3065
       df813830 00000086 00000002 f74fdc80 f74fdc78 00000000 f52ac680
f8c634bf
       df813998 c1822940 00000003 015ba1ef 00000000 f7d6fcd0 000000ff
00000000
       00000000 00000000 f74fdcc0 00000000 f74fdcc8 c1800ce0 f8c62e85
c02bc97f
Call Trace:
 [<f8c634bf>] rpc_sleep_on+0x21/0x221 [sunrpc]
 [<f8c62e85>] rpc_wait_bit_interruptible+0x1a/0x1f [sunrpc]
 [<c02bc97f>] __wait_on_bit+0x33/0x58
 [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
 [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
 [<c02bca07>] out_of_line_wait_on_bit+0x63/0x6b
 [<c013545e>] wake_bit_function+0x0/0x3c
 [<f8c62e19>] __rpc_wait_for_completion_task+0x32/0x39 [sunrpc]
 [<f8ce1352>] nfs4_wait_for_completion_rpc_task+0x1b/0x2f [nfs]
 [<f8ce3812>] _nfs4_proc_open+0x75/0x1b4 [nfs]
 [<f8ce3e0c>] nfs4_do_open+0x112/0x23b [nfs]
 [<f8ce50d3>] nfs4_open_revalidate+0x5e/0x11e [nfs]
 [<f8cd25c1>] nfs_open_revalidate+0xc7/0x187 [nfs]
 [<c017e8c4>] do_lookup+0x101/0x140
 [<c01803f0>] __link_path_walk+0x744/0xb4b
 [<c018083b>] link_path_walk+0x44/0xb3
 [<c0176b59>] get_unused_fd_flags+0x4d/0xba
 [<c0180b23>] do_path_lookup+0x162/0x1c4
 [<c01793cc>] get_empty_filp+0x95/0x152
 [<c0181488>] __path_lookup_intent_open+0x45/0x75
 [<c0181527>] path_lookup_open+0x20/0x25
 [<c0181606>] open_namei+0x72/0x558
 [<c0176e00>] do_filp_open+0x25/0x39
 [<c0176b59>] get_unused_fd_flags+0x4d/0xba
 [<c0176e58>] do_sys_open+0x44/0xc0
 [<c0176f0d>] sys_open+0x1c/0x1e
 [<c0103e5e>] sysenter_past_esp+0x6b/0xa1
 =======================
sshd          S f52e4800     0 17199   3065
       df8dd8f0 00000082 f8c63859 f52e4800 f669be00 c02bd82e 8660c63b
000008ce
       df8dda58 c180a940 00000000 c01868b0 0000a690 00000000 c7387ce4
f7699b80
       f7699b80 00000246 e7379cc0 00000000 e7379cc8 c1802c60 f8c62e85
c02bc97f
Call Trace:
 [<f8c63859>] rpc_wake_up_next+0x12c/0x136 [sunrpc]
 [<c02bd82e>] _spin_lock_bh+0x8/0x18
 [<c01868b0>] dput+0x15/0xdc
 [<f8c62e85>] rpc_wait_bit_interruptible+0x1a/0x1f [sunrpc]
 [<c02bc97f>] __wait_on_bit+0x33/0x58
 [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
 [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
 [<c02bca07>] out_of_line_wait_on_bit+0x63/0x6b
 [<c013545e>] wake_bit_function+0x0/0x3c
 [<f8c62e19>] __rpc_wait_for_completion_task+0x32/0x39 [sunrpc]
 [<f8ce1352>] nfs4_wait_for_completion_rpc_task+0x1b/0x2f [nfs]
 [<f8ce3812>] _nfs4_proc_open+0x75/0x1b4 [nfs]
 [<f8ce3e0c>] nfs4_do_open+0x112/0x23b [nfs]
 [<f8ce50d3>] nfs4_open_revalidate+0x5e/0x11e [nfs]
 [<f8cd25c1>] nfs_open_revalidate+0xc7/0x187 [nfs]
 [<c017e8c4>] do_lookup+0x101/0x140
 [<c01803f0>] __link_path_walk+0x744/0xb4b
 [<f8ce2021>] nfs4_proc_getattr+0x31/0x3e [nfs]
 [<f8cd459b>] __nfs_revalidate_inode+0x269/0x276 [nfs]
 [<c018083b>] link_path_walk+0x44/0xb3
 [<c0176b59>] get_unused_fd_flags+0x4d/0xba
 [<c0180b23>] do_path_lookup+0x162/0x1c4
 [<c01793cc>] get_empty_filp+0x95/0x152
 [<c0181488>] __path_lookup_intent_open+0x45/0x75
 [<c0181527>] path_lookup_open+0x20/0x25
 [<c0181606>] open_namei+0x72/0x558
 [<c0176e00>] do_filp_open+0x25/0x39
 [<c0176b59>] get_unused_fd_flags+0x4d/0xba
 [<c0176e58>] do_sys_open+0x44/0xc0
 [<c0176f0d>] sys_open+0x1c/0x1e
 [<c0103e5e>] sysenter_past_esp+0x6b/0xa1
 =======================
sshd          S f5203bf4     0 17252   3065
       f7cd2db0 00000086 00000002 f5203bf4 f5203bec 00000000 ffffffff
f76742c0
       f7cd2f18 c1822940 00000003 015e25d4 015e2abf c017554d 000000ff
00000000
       00000000 00000000 f5203c34 00000000 f5203c3c c1802f30 f8c62e85
c02bc97f
Call Trace:
 [<c017554d>] cache_alloc_refill+0x58/0x477
 [<f8c62e85>] rpc_wait_bit_interruptible+0x1a/0x1f [sunrpc]
 [<c02bc97f>] __wait_on_bit+0x33/0x58
 [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
 [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
 [<c02bca07>] out_of_line_wait_on_bit+0x63/0x6b
 [<c013545e>] wake_bit_function+0x0/0x3c
 [<f8c632cb>] __rpc_execute+0xeb/0x231 [sunrpc]
 [<f8c62ac7>] rpc_set_active+0x3a/0x56 [sunrpc]
 [<f8c5dc5e>] rpc_do_run_task+0x76/0x8f [sunrpc]
 [<f8c5dcf8>] rpc_call_sync+0x21/0x39 [sunrpc]
 [<f8ce2501>] nfs4_proc_access+0x129/0x19e [nfs]
 [<c0176b59>] get_unused_fd_flags+0x4d/0xba
 [<c0176a8e>] fd_install+0x1b/0x41
 [<c025c25c>] scm_detach_fds+0xf4/0x12c
 [<c02b0fe5>] unix_stream_recvmsg+0x48d/0x4bd
 [<c0259c6b>] __alloc_skb+0x49/0xf7
 [<f8cd0d83>] nfs_do_access+0x133/0x2ab [nfs]
 [<f8c63fb0>] rpcauth_lookupcred+0x65/0x8a [sunrpc]
 [<f8cd0fc0>] nfs_permission+0xc5/0x134 [nfs]
 [<c01868b0>] dput+0x15/0xdc
 [<c017e6c1>] __follow_mount+0x1e/0x60
 [<f8cd0efb>] nfs_permission+0x0/0x134 [nfs]
 [<c017e5bc>] permission+0xa3/0xef
 [<c017fdc6>] __link_path_walk+0x11a/0xb4b
 [<c015a9cd>] find_lock_page+0x19/0x7f
 [<c018083b>] link_path_walk+0x44/0xb3
 [<c0259157>] skb_dequeue+0x39/0x3f
 [<c0180b23>] do_path_lookup+0x162/0x1c4
 [<c017fae8>] getname+0x59/0xad
 [<c01812f4>] __user_walk_fd+0x2f/0x40
 [<c017b33f>] vfs_stat_fd+0x19/0x40
 [<c0259157>] skb_dequeue+0x39/0x3f
 [<c017b41b>] sys_stat64+0xf/0x23
 [<c012fe3f>] set_current_groups+0x14d/0x159
 [<c01bd9cf>] security_capable+0x9/0xa
 [<c012aff8>] __capable+0x8/0x1b
 [<c0131894>] sys_setresuid+0x163/0x18e
 [<c01bdc8f>] security_task_post_setuid+0x17/0x1a
 [<c0103e5e>] sysenter_past_esp+0x6b/0xa1



-- 
To UNSUBSCRIBE, email to debian-kernel-REQUEST@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmaster@lists.debian.org


----- End forwarded message -----

Re: (fwd) nfs hang on 2.6.24

[Trond Myklebust]

On Tue, 2008-02-05 at 10:01 +0100, maximilian attems wrote:
> please take a look
> 
> ----- Forwarded message from Andrew Dixie <andrew-0FSrDVjkvKm9koe0gwxAeg@public.gmane.org> -----
> 
> Date: Tue, 5 Feb 2008 12:57:37 +1300 (NZDT)
> Subject: nfs hang on 2.6.24
> From: Andrew Dixie <andrew-0FSrDVjkvKm9koe0gwxAeg@public.gmane.org>
> To: debian-kernel@lists.debian.org
> 
> I've recently updated to 2.6.24 as recommended on bug 463508.
> 
> But the new kernel now has nfs hanging problems.
> A few times now it has got into a situation such that any process that
> touches an nfs mount hangs.
> 
> The machine has both nfs3 and nfs4 mounts. My suspicion is that it relates
> to putting a heavy load on both nfs3 and nfs4 mounts at the same time.
> 
> The machine for the moment is still hung so let me know if there are
> further debugging steps I can perform.
> 
> There are many other processes but these are the unique call stacks that
> involve nfs related functions.
> 
>  =======================
> nfsv4-delegre S 00000282     0 17156      2
>        df8dcd30 00000046 f8c5f813 00000282 f35d4a60 00000000 93c19d62
> 000008a4
>        df8dce98 c180a940 00000000 f35d4b10 0000a296 00000000 f669be00
> f8ce9b74
>        f8c5f08b 00000246 e6a59f34 00000000 e6a59f3c c18003b0 f8c62e85
> c02bc97f
> Call Trace:
>  [<f8c5f813>] xprt_timer+0x0/0x6f [sunrpc]
>  [<f8ce9b74>] nfs4_xdr_enc_delegreturn+0x0/0x84 [nfs]
>  [<f8c5f08b>] xprt_release_xprt+0x39/0x66 [sunrpc]
>  [<f8c62e85>] rpc_wait_bit_interruptible+0x1a/0x1f [sunrpc]
>  [<c02bc97f>] __wait_on_bit+0x33/0x58
>  [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
>  [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
>  [<c02bca07>] out_of_line_wait_on_bit+0x63/0x6b
>  [<c013545e>] wake_bit_function+0x0/0x3c
>  [<f8c62e19>] __rpc_wait_for_completion_task+0x32/0x39 [sunrpc]
>  [<f8ce1352>] nfs4_wait_for_completion_rpc_task+0x1b/0x2f [nfs]
>  [<f8ce2336>] nfs4_proc_delegreturn+0x116/0x172 [nfs]
>  [<f8ced370>] nfs_do_return_delegation+0xf/0x1d [nfs]
>  [<f8ced88a>] recall_thread+0xad/0xc0 [nfs]
>  [<f8ced7dd>] recall_thread+0x0/0xc0 [nfs]
>  [<c0104b0f>] kernel_thread_helper+0x7/0x10

The fact that the delegreturn call appears to have hit xprt_timer is
interesting. Under normal circumstances, timeouts should never occur
under NFSv4. Could you tell us what mount options you're using here?

Also please could you confirm for us that the server is still up and
responding to requests from other clients.

Cheers
  Trond

>  =======================
> mysqld        S f704db38     0  3156   3110
>        df848130 00000082 00000002 f704db38 f704db30 00000000 6369898c
> 0000052b
>        df848298 c1822940 00000003 0163574b f704db5c f7c86000 000000ff
> 00000000
>        00000000 00000000 f704db5c 016359d3 f7459140 000001f4 c02bc84e
> 00000001
> Call Trace:
>  [<c02bc84e>] schedule_timeout+0x70/0x8d
>  [<c01048c3>] common_interrupt+0x23/0x28
>  [<c012c3e2>] process_timeout+0x0/0x5
>  [<c02bc849>] schedule_timeout+0x6b/0x8d
>  [<c0183476>] do_select+0x365/0x3bc
>  [<c0183a60>] __pollwait+0x0/0xac
>  [<c011e069>] enqueue_entity+0x2b/0x3d
>  [<c0115343>] apic_wait_icr_idle+0xe/0x15
>  [<c011e091>] enqueue_task_fair+0x16/0x24
>  [<c011d647>] enqueue_task+0x52/0x5d
>  [<c011de8a>] resched_task+0x52/0x54
>  [<c011f445>] try_to_wake_up+0x2b8/0x2c2
>  [<c013543e>] autoremove_wake_function+0x15/0x35
>  [<c011d482>] __wake_up_common+0x32/0x5c
>  [<c011eeb8>] __wake_up+0x32/0x42
>  [<c013540e>] __wake_up_bit+0x2e/0x33
>  [<f8c630f5>] __rpc_do_wake_up_task+0x1fb/0x218 [sunrpc]
>  [<f8c6003a>] xdr_partial_copy_from_skb+0x32/0x171 [sunrpc]
>  [<f8c63148>] rpc_wake_up_task+0x36/0x4a [sunrpc]
>  [<f8c61cfd>] xs_tcp_data_recv+0x3d3/0x407 [sunrpc]
>  [<f8c6028f>] xdr_skb_read_bits+0x0/0x35 [sunrpc]
>  [<c0259bb5>] skb_release_all+0xa3/0xfa
>  [<c028484c>] tcp_read_sock+0x15e/0x16a
>  [<f8c6192a>] xs_tcp_data_recv+0x0/0x407 [sunrpc]
>  [<f8c624a8>] xs_tcp_data_ready+0x55/0x61 [sunrpc]
>  [<c012c8ec>] mod_timer+0x19/0x36
>  [<c02564e7>] sk_reset_timer+0xc/0x16
>  [<c028ba16>] tcp_rcv_established+0x3ae/0x63c
>  [<c0290ceb>] tcp_v4_do_rcv+0x2b/0x343
>  [<f8a593a5>] ip_vs_in+0xa5/0x220 [ip_vs]
>  [<f8a59300>] ip_vs_in+0x0/0x220 [ip_vs]
>  [<c0293000>] tcp_v4_rcv+0x80e/0x882
>  [<c0183750>] core_sys_select+0x283/0x2a0
>  [<c027a934>] ip_local_deliver_finish+0x114/0x1b7
>  [<c0259c6b>] __alloc_skb+0x49/0xf7
>  [<c0259bb5>] skb_release_all+0xa3/0xfa
>  [<f8833e62>] e1000_alloc_rx_buffers+0x1cb/0x295 [e1000]
>  [<c02594b1>] __kfree_skb+0x8/0x61
>  [<f88301f9>] e1000_unmap_and_free_tx_resource+0x1b/0x23 [e1000]
>  [<f8831c09>] e1000_clean_tx_irq+0xbe/0x2c3 [e1000]
>  [<f883480e>] e1000_clean_rx_irq+0x419/0x449 [e1000]
>  [<f88343f5>] e1000_clean_rx_irq+0x0/0x449 [e1000]
>  [<f8832045>] e1000_clean+0x1e9/0x213 [e1000]
>  [<c025fe81>] net_rx_action+0x9f/0x198
>  [<c0183bb0>] sys_select+0xa4/0x187
>  [<c0103e5e>] sysenter_past_esp+0x6b/0xa1
>  =======================
> sshd          S f74fdc80     0 17157   3065
>        df813830 00000086 00000002 f74fdc80 f74fdc78 00000000 f52ac680
> f8c634bf
>        df813998 c1822940 00000003 015ba1ef 00000000 f7d6fcd0 000000ff
> 00000000
>        00000000 00000000 f74fdcc0 00000000 f74fdcc8 c1800ce0 f8c62e85
> c02bc97f
> Call Trace:
>  [<f8c634bf>] rpc_sleep_on+0x21/0x221 [sunrpc]
>  [<f8c62e85>] rpc_wait_bit_interruptible+0x1a/0x1f [sunrpc]
>  [<c02bc97f>] __wait_on_bit+0x33/0x58
>  [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
>  [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
>  [<c02bca07>] out_of_line_wait_on_bit+0x63/0x6b
>  [<c013545e>] wake_bit_function+0x0/0x3c
>  [<f8c62e19>] __rpc_wait_for_completion_task+0x32/0x39 [sunrpc]
>  [<f8ce1352>] nfs4_wait_for_completion_rpc_task+0x1b/0x2f [nfs]
>  [<f8ce3812>] _nfs4_proc_open+0x75/0x1b4 [nfs]
>  [<f8ce3e0c>] nfs4_do_open+0x112/0x23b [nfs]
>  [<f8ce50d3>] nfs4_open_revalidate+0x5e/0x11e [nfs]
>  [<f8cd25c1>] nfs_open_revalidate+0xc7/0x187 [nfs]
>  [<c017e8c4>] do_lookup+0x101/0x140
>  [<c01803f0>] __link_path_walk+0x744/0xb4b
>  [<c018083b>] link_path_walk+0x44/0xb3
>  [<c0176b59>] get_unused_fd_flags+0x4d/0xba
>  [<c0180b23>] do_path_lookup+0x162/0x1c4
>  [<c01793cc>] get_empty_filp+0x95/0x152
>  [<c0181488>] __path_lookup_intent_open+0x45/0x75
>  [<c0181527>] path_lookup_open+0x20/0x25
>  [<c0181606>] open_namei+0x72/0x558
>  [<c0176e00>] do_filp_open+0x25/0x39
>  [<c0176b59>] get_unused_fd_flags+0x4d/0xba
>  [<c0176e58>] do_sys_open+0x44/0xc0
>  [<c0176f0d>] sys_open+0x1c/0x1e
>  [<c0103e5e>] sysenter_past_esp+0x6b/0xa1
>  =======================
> sshd          S f52e4800     0 17199   3065
>        df8dd8f0 00000082 f8c63859 f52e4800 f669be00 c02bd82e 8660c63b
> 000008ce
>        df8dda58 c180a940 00000000 c01868b0 0000a690 00000000 c7387ce4
> f7699b80
>        f7699b80 00000246 e7379cc0 00000000 e7379cc8 c1802c60 f8c62e85
> c02bc97f
> Call Trace:
>  [<f8c63859>] rpc_wake_up_next+0x12c/0x136 [sunrpc]
>  [<c02bd82e>] _spin_lock_bh+0x8/0x18
>  [<c01868b0>] dput+0x15/0xdc
>  [<f8c62e85>] rpc_wait_bit_interruptible+0x1a/0x1f [sunrpc]
>  [<c02bc97f>] __wait_on_bit+0x33/0x58
>  [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
>  [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
>  [<c02bca07>] out_of_line_wait_on_bit+0x63/0x6b
>  [<c013545e>] wake_bit_function+0x0/0x3c
>  [<f8c62e19>] __rpc_wait_for_completion_task+0x32/0x39 [sunrpc]
>  [<f8ce1352>] nfs4_wait_for_completion_rpc_task+0x1b/0x2f [nfs]
>  [<f8ce3812>] _nfs4_proc_open+0x75/0x1b4 [nfs]
>  [<f8ce3e0c>] nfs4_do_open+0x112/0x23b [nfs]
>  [<f8ce50d3>] nfs4_open_revalidate+0x5e/0x11e [nfs]
>  [<f8cd25c1>] nfs_open_revalidate+0xc7/0x187 [nfs]
>  [<c017e8c4>] do_lookup+0x101/0x140
>  [<c01803f0>] __link_path_walk+0x744/0xb4b
>  [<f8ce2021>] nfs4_proc_getattr+0x31/0x3e [nfs]
>  [<f8cd459b>] __nfs_revalidate_inode+0x269/0x276 [nfs]
>  [<c018083b>] link_path_walk+0x44/0xb3
>  [<c0176b59>] get_unused_fd_flags+0x4d/0xba
>  [<c0180b23>] do_path_lookup+0x162/0x1c4
>  [<c01793cc>] get_empty_filp+0x95/0x152
>  [<c0181488>] __path_lookup_intent_open+0x45/0x75
>  [<c0181527>] path_lookup_open+0x20/0x25
>  [<c0181606>] open_namei+0x72/0x558
>  [<c0176e00>] do_filp_open+0x25/0x39
>  [<c0176b59>] get_unused_fd_flags+0x4d/0xba
>  [<c0176e58>] do_sys_open+0x44/0xc0
>  [<c0176f0d>] sys_open+0x1c/0x1e
>  [<c0103e5e>] sysenter_past_esp+0x6b/0xa1
>  =======================
> sshd          S f5203bf4     0 17252   3065
>        f7cd2db0 00000086 00000002 f5203bf4 f5203bec 00000000 ffffffff
> f76742c0
>        f7cd2f18 c1822940 00000003 015e25d4 015e2abf c017554d 000000ff
> 00000000
>        00000000 00000000 f5203c34 00000000 f5203c3c c1802f30 f8c62e85
> c02bc97f
> Call Trace:
>  [<c017554d>] cache_alloc_refill+0x58/0x477
>  [<f8c62e85>] rpc_wait_bit_interruptible+0x1a/0x1f [sunrpc]
>  [<c02bc97f>] __wait_on_bit+0x33/0x58
>  [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
>  [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
>  [<c02bca07>] out_of_line_wait_on_bit+0x63/0x6b
>  [<c013545e>] wake_bit_function+0x0/0x3c
>  [<f8c632cb>] __rpc_execute+0xeb/0x231 [sunrpc]
>  [<f8c62ac7>] rpc_set_active+0x3a/0x56 [sunrpc]
>  [<f8c5dc5e>] rpc_do_run_task+0x76/0x8f [sunrpc]
>  [<f8c5dcf8>] rpc_call_sync+0x21/0x39 [sunrpc]
>  [<f8ce2501>] nfs4_proc_access+0x129/0x19e [nfs]
>  [<c0176b59>] get_unused_fd_flags+0x4d/0xba
>  [<c0176a8e>] fd_install+0x1b/0x41
>  [<c025c25c>] scm_detach_fds+0xf4/0x12c
>  [<c02b0fe5>] unix_stream_recvmsg+0x48d/0x4bd
>  [<c0259c6b>] __alloc_skb+0x49/0xf7
>  [<f8cd0d83>] nfs_do_access+0x133/0x2ab [nfs]
>  [<f8c63fb0>] rpcauth_lookupcred+0x65/0x8a [sunrpc]
>  [<f8cd0fc0>] nfs_permission+0xc5/0x134 [nfs]
>  [<c01868b0>] dput+0x15/0xdc
>  [<c017e6c1>] __follow_mount+0x1e/0x60
>  [<f8cd0efb>] nfs_permission+0x0/0x134 [nfs]
>  [<c017e5bc>] permission+0xa3/0xef
>  [<c017fdc6>] __link_path_walk+0x11a/0xb4b
>  [<c015a9cd>] find_lock_page+0x19/0x7f
>  [<c018083b>] link_path_walk+0x44/0xb3
>  [<c0259157>] skb_dequeue+0x39/0x3f
>  [<c0180b23>] do_path_lookup+0x162/0x1c4
>  [<c017fae8>] getname+0x59/0xad
>  [<c01812f4>] __user_walk_fd+0x2f/0x40
>  [<c017b33f>] vfs_stat_fd+0x19/0x40
>  [<c0259157>] skb_dequeue+0x39/0x3f
>  [<c017b41b>] sys_stat64+0xf/0x23
>  [<c012fe3f>] set_current_groups+0x14d/0x159
>  [<c01bd9cf>] security_capable+0x9/0xa
>  [<c012aff8>] __capable+0x8/0x1b
>  [<c0131894>] sys_setresuid+0x163/0x18e
>  [<c01bdc8f>] security_task_post_setuid+0x17/0x1a
>  [<c0103e5e>] sysenter_past_esp+0x6b/0xa1
> 
> 
> 

Re: (fwd) nfs hang on 2.6.24

[Andrew Dixie]

> The fact that the delegreturn call appears to have hit xprt_timer is
> interesting. Under normal circumstances, timeouts should never occur
> under NFSv4. Could you tell us what mount options you're using here?
>
> Also please could you confirm for us that the server is still up and
> responding to requests from other clients.

The mount options were defaults:
i.e. mount -t nfs4 server:/mnt /mnt
sshd has died. I will confrim exactly what is in /proc/mounts when I get 
physical access.

The server is still up serving active nfsv3 clients. I mounted nfsv4 on 
another client and that worked too.

The following appears in the server logs:
Feb  4 08:28:01 devfile kernel: NFSD: setclientid: string in use by 
client(clientid 47945499/00001c88)
Feb  4 08:34:18 devfile kernel: NFSD: setclientid: string in use by 
client(clientid 47945499/00001c8d)
Feb  4 08:38:02 devfile kernel: NFSD: setclientid: string in use by 
client(clientid 47945499/00001c8f)
Feb  4 10:01:02 devfile kernel: NFSD: setclientid: string in use by 
client(clientid 47a627bd/00000002)
Feb  4 10:07:37 devfile kernel: NFSD: setclientid: string in use by 
client(clientid 47a627bd/00000005)
Feb  4 10:17:02 devfile kernel: NFSD: setclientid: string in use by 
client(clientid 47a627bd/0000019e)
Feb  5 07:59:58 devfile kernel: NFSD: setclientid: string in use by 
client(clientid 47a627bd/000003f2)
Feb  5 08:01:02 devfile kernel: NFSD: setclientid: string in use by 
client(clientid 47a627bd/000003f3)

These are not close to the times that it hung.
Prior to Feb 4 it occurs 10 to 50 times a day (from when the client was 
running 2.6.18 kernel)
There is only one nfsv4 client.

Thanks,
Andrew 

Re: (fwd) nfs hang on 2.6.24

[Trond Myklebust]

On Wed, 2008-02-06 at 19:24 +1300, Andrew Dixie wrote:
> > The fact that the delegreturn call appears to have hit xprt_timer is
> > interesting. Under normal circumstances, timeouts should never occur
> > under NFSv4. Could you tell us what mount options you're using here?
> >
> > Also please could you confirm for us that the server is still up and
> > responding to requests from other clients.
> 
> The mount options were defaults:
> i.e. mount -t nfs4 server:/mnt /mnt
> sshd has died. I will confrim exactly what is in /proc/mounts when I get 
> physical access.
> 
> The server is still up serving active nfsv3 clients. I mounted nfsv4 on 
> another client and that worked too.

Thanks. My other questions are:

  What is rpciod doing while the machine hangs?
  Does 'netstat -t' show an active tcp connection to the server?
  Does tcpdump show any traffic going on the wire?
  What server are you running against? From the error messages below, I
see it is a Linux machine, but which kernel is it running?

> The following appears in the server logs:
> Feb  4 08:28:01 devfile kernel: NFSD: setclientid: string in use by 
> client(clientid 47945499/00001c88)
> Feb  4 08:34:18 devfile kernel: NFSD: setclientid: string in use by 
> client(clientid 47945499/00001c8d)
> Feb  4 08:38:02 devfile kernel: NFSD: setclientid: string in use by 
> client(clientid 47945499/00001c8f)
> Feb  4 10:01:02 devfile kernel: NFSD: setclientid: string in use by 
> client(clientid 47a627bd/00000002)
> Feb  4 10:07:37 devfile kernel: NFSD: setclientid: string in use by 
> client(clientid 47a627bd/00000005)
> Feb  4 10:17:02 devfile kernel: NFSD: setclientid: string in use by 
> client(clientid 47a627bd/0000019e)
> Feb  5 07:59:58 devfile kernel: NFSD: setclientid: string in use by 
> client(clientid 47a627bd/000003f2)
> Feb  5 08:01:02 devfile kernel: NFSD: setclientid: string in use by 
> client(clientid 47a627bd/000003f3)
> 
> These are not close to the times that it hung.

Yep. The above is entirely expected, and is not actually a bug. I keep
asking Bruce to remove that warning...

> Prior to Feb 4 it occurs 10 to 50 times a day (from when the client was 
> running 2.6.18 kernel)
> There is only one nfsv4 client.

OK...

Thanks
  Trond

Re: (fwd) nfs hang on 2.6.24

[J. Bruce Fields]

On Wed, Feb 06, 2008 at 10:00:21AM -0500, Trond Myklebust wrote:
> 
> On Wed, 2008-02-06 at 19:24 +1300, Andrew Dixie wrote:
> > The following appears in the server logs:
> > Feb  4 08:28:01 devfile kernel: NFSD: setclientid: string in use by 
> > client(clientid 47945499/00001c88)
> > Feb  4 08:34:18 devfile kernel: NFSD: setclientid: string in use by 
> > client(clientid 47945499/00001c8d)
> > Feb  4 08:38:02 devfile kernel: NFSD: setclientid: string in use by 
> > client(clientid 47945499/00001c8f)
> > Feb  4 10:01:02 devfile kernel: NFSD: setclientid: string in use by 
> > client(clientid 47a627bd/00000002)
> > Feb  4 10:07:37 devfile kernel: NFSD: setclientid: string in use by 
> > client(clientid 47a627bd/00000005)
> > Feb  4 10:17:02 devfile kernel: NFSD: setclientid: string in use by 
> > client(clientid 47a627bd/0000019e)
> > Feb  5 07:59:58 devfile kernel: NFSD: setclientid: string in use by 
> > client(clientid 47a627bd/000003f2)
> > Feb  5 08:01:02 devfile kernel: NFSD: setclientid: string in use by 
> > client(clientid 47a627bd/000003f3)
> > 
> > These are not close to the times that it hung.
> 
> Yep. The above is entirely expected, and is not actually a bug. I keep
> asking Bruce to remove that warning...

That went into 2.6.22:

	21315edd4877b593d5bf.. "[PATCH] knfsd: nfsd4: demote "clientid
	in use" printk to a dprintk"

It may suggest a problem if this is happening a lot, though, right?

--b.

> 
> > Prior to Feb 4 it occurs 10 to 50 times a day (from when the client was 
> > running 2.6.18 kernel)
> > There is only one nfsv4 client.
> 
> OK...
> 
> Thanks
>   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

Re: (fwd) nfs hang on 2.6.24

[Trond Myklebust]

On Wed, 2008-02-06 at 10:07 -0500, J. Bruce Fields wrote:

> That went into 2.6.22:
> 
> 	21315edd4877b593d5bf.. "[PATCH] knfsd: nfsd4: demote "clientid
> 	in use" printk to a dprintk"
> 
> It may suggest a problem if this is happening a lot, though, right?

The client should always be able to generate a new unique clientid if
this happens.

Trond

Re: (fwd) nfs hang on 2.6.24

[J. Bruce Fields]

On Wed, Feb 06, 2008 at 10:15:23AM -0500, Trond Myklebust wrote:
> 
> On Wed, 2008-02-06 at 10:07 -0500, J. Bruce Fields wrote:
> 
> > That went into 2.6.22:
> > 
> > 	21315edd4877b593d5bf.. "[PATCH] knfsd: nfsd4: demote "clientid
> > 	in use" printk to a dprintk"
> > 
> > It may suggest a problem if this is happening a lot, though, right?
> 
> The client should always be able to generate a new unique clientid if
> this happens.

And then the client may fail to reclaim its state on the next server
reboot, or mistakenly prevent some other client from reclaiming state,
since it's not recording the new clientid in stable storage.  So if it's
happening a lot then we I suppose we should figure out better ways to
generate client id's.

--b.

Re: (fwd) nfs hang on 2.6.24

[Trond Myklebust]

On Wed, 2008-02-06 at 12:23 -0500, J. Bruce Fields wrote:
> On Wed, Feb 06, 2008 at 10:15:23AM -0500, Trond Myklebust wrote:
> > 
> > On Wed, 2008-02-06 at 10:07 -0500, J. Bruce Fields wrote:
> > 
> > > That went into 2.6.22:
> > > 
> > > 	21315edd4877b593d5bf.. "[PATCH] knfsd: nfsd4: demote "clientid
> > > 	in use" printk to a dprintk"
> > > 
> > > It may suggest a problem if this is happening a lot, though, right?
> > 
> > The client should always be able to generate a new unique clientid if
> > this happens.
> 
> And then the client may fail to reclaim its state on the next server
> reboot, or mistakenly prevent some other client from reclaiming state,
> since it's not recording the new clientid in stable storage.  So if it's
> happening a lot then we I suppose we should figure out better ways to
> generate client id's.

Huh?

If the server reboots, the client will try to reclaim state using the
_same_ client identifier string.

Two clients should _not_ be able to generate the same clientid unless
they're also sharing the same IP address and a number of other
properties that we include in the client identifier.

Re: (fwd) nfs hang on 2.6.24

[J. Bruce Fields]

On Wed, Feb 06, 2008 at 12:52:17PM -0500, Trond Myklebust wrote:
> 
> On Wed, 2008-02-06 at 12:23 -0500, J. Bruce Fields wrote:
> > On Wed, Feb 06, 2008 at 10:15:23AM -0500, Trond Myklebust wrote:
> > > 
> > > On Wed, 2008-02-06 at 10:07 -0500, J. Bruce Fields wrote:
> > > 
> > > > That went into 2.6.22:
> > > > 
> > > > 	21315edd4877b593d5bf.. "[PATCH] knfsd: nfsd4: demote "clientid
> > > > 	in use" printk to a dprintk"
> > > > 
> > > > It may suggest a problem if this is happening a lot, though, right?
> > > 
> > > The client should always be able to generate a new unique clientid if
> > > this happens.
> > 
> > And then the client may fail to reclaim its state on the next server
> > reboot, or mistakenly prevent some other client from reclaiming state,
> > since it's not recording the new clientid in stable storage.  So if it's
> > happening a lot then we I suppose we should figure out better ways to
> > generate client id's.
> 
> Huh?
> 
> If the server reboots, the client will try to reclaim state using the
> _same_ client identifier string.

Oh, right, I was confusing client and server reboot and assuming the
client would forget the uniquifier on server reboot.  That's obviously
wrong!  The client will forget its own uniquifier on client reboot, but
that's alright since it's happy enough just to let that old state time
out at that point.  So the only possible problem is suboptimal behavior
when the client reboot time is less than the lease time.

> Two clients should _not_ be able to generate the same clientid unless
> they're also sharing the same IP address and a number of other
> properties that we include in the client identifier.

Or unless two client implementations just happen to have clashing
clientid generation algorithms, but we hope that's unlikely.

(Except that older Linux clients were prone to produce the same
clientid, if I remember right.  But the more likely explanation may be
that these are the result of a single client destroying and then
creating state on the server within a lease period, and the server being
stubborn and refusing to let go of the old state (even though no opens
are associated with it any more) until the end of a lease period.  I
think that's a server bug.)

--b.

Re: (fwd) nfs hang on 2.6.24

[Andrew Dixie]

> Oh, right, I was confusing client and server reboot and assuming the
> client would forget the uniquifier on server reboot.  That's obviously
> wrong!  The client will forget its own uniquifier on client reboot, but
> that's alright since it's happy enough just to let that old state time
> out at that point.  So the only possible problem is suboptimal behavior
> when the client reboot time is less than the lease time.

There is one client, a stable connection between client and server, and
neither client or server are being rebooted.
Are the "string in use by client" messages still expected?

Below is a program that attempts to open a file that is contained in a
directory that has been deleted by another client.

I'm not sure these are conditions that are normally occuring, it's just
something I encountered trying to reproduce the hang.

This reliably reproduces:
Feb  7 09:55:01 devfile kernel: NFSD: preprocess_seqid_op: bad seqid
(expected 20, got 22)

And about 1 in 10 times it also reproduces:
Feb  7 09:55:01 devfile kernel: NFSD: setclientid: string in use by
client(clientid 47a627bd/0000044b)

The server is 2.6.18-5 from debian.

---

#include <string.h>
#include <stdio.h>
#include <unistd.h>
#include <errno.h>
#include <fcntl.h>
#include <sys/stat.h>
#include <stdlib.h>

#define ASSERT(x) \
        if (!(x)) { fprintf(stderr, "%s:%i:assert:" #x "\n", __FILE__,
__LINE__); abort(); }

#define testdir "/home/andrewd/testdir"
#define testfile testdir "/fred"

int main(int argc, char *argv[])
{
        int fd;
        int rv;

        rv = mkdir(testdir,0777);
        ASSERT(rv == 0 || errno == EEXIST);

        fd = open(testfile, O_CREAT|O_WRONLY);
        ASSERT(fd != -1);
        rv = write(fd, "stuff\n", 6);
        ASSERT(rv == 6);
        close(fd);

        rv = access(testfile, 0);
        ASSERT(rv == 0);

        // Remove directory via another client (nfsv3)
        system("ssh devlin7 rm -r "testdir);

        // Try to open file
        fd = open(testfile, O_RDONLY);
        printf("got fd:%i errno:%i\n", fd, errno);
        // fd == -1, errno = ENOENT
        // This is expected, error on nfs server is not.
        return 0;
}

Re: (fwd) nfs hang on 2.6.24

[J. Bruce Fields]

On Thu, Feb 07, 2008 at 10:19:06AM +1300, Andrew Dixie wrote:
> 
> > Oh, right, I was confusing client and server reboot and assuming the
> > client would forget the uniquifier on server reboot.  That's obviously
> > wrong!  The client will forget its own uniquifier on client reboot, but
> > that's alright since it's happy enough just to let that old state time
> > out at that point.  So the only possible problem is suboptimal behavior
> > when the client reboot time is less than the lease time.
> 
> There is one client, a stable connection between client and server, and
> neither client or server are being rebooted.
> Are the "string in use by client" messages still expected?

Assuming the client creates and destroys clientid's on demand, as
they're needed for opens, and uses whatever user credential it has at
hand to do so, then I think a sequence of alternating opens and closes
as different users could produce this.

But no, it doesn't indicate any real problem on its own.

> Below is a program that attempts to open a file that is contained in a
> directory that has been deleted by another client.
> 
> I'm not sure these are conditions that are normally occuring, it's just
> something I encountered trying to reproduce the hang.
> 
> This reliably reproduces:
> Feb  7 09:55:01 devfile kernel: NFSD: preprocess_seqid_op: bad seqid
> (expected 20, got 22)

That's a bug though, either on the client or server side.

--b.

> 
> And about 1 in 10 times it also reproduces:
> Feb  7 09:55:01 devfile kernel: NFSD: setclientid: string in use by
> client(clientid 47a627bd/0000044b)
> 
> The server is 2.6.18-5 from debian.
> 
> ---
> 
> #include <string.h>
> #include <stdio.h>
> #include <unistd.h>
> #include <errno.h>
> #include <fcntl.h>
> #include <sys/stat.h>
> #include <stdlib.h>
> 
> #define ASSERT(x) \
>         if (!(x)) { fprintf(stderr, "%s:%i:assert:" #x "\n", __FILE__,
> __LINE__); abort(); }
> 
> #define testdir "/home/andrewd/testdir"
> #define testfile testdir "/fred"
> 
> int main(int argc, char *argv[])
> {
>         int fd;
>         int rv;
> 
>         rv = mkdir(testdir,0777);
>         ASSERT(rv == 0 || errno == EEXIST);
> 
>         fd = open(testfile, O_CREAT|O_WRONLY);
>         ASSERT(fd != -1);
>         rv = write(fd, "stuff\n", 6);
>         ASSERT(rv == 6);
>         close(fd);
> 
>         rv = access(testfile, 0);
>         ASSERT(rv == 0);
> 
>         // Remove directory via another client (nfsv3)
>         system("ssh devlin7 rm -r "testdir);
> 
>         // Try to open file
>         fd = open(testfile, O_RDONLY);
>         printf("got fd:%i errno:%i\n", fd, errno);
>         // fd == -1, errno = ENOENT
>         // This is expected, error on nfs server is not.
>         return 0;
> }
> 
> 

Re: (fwd) nfs hang on 2.6.24

[Andrew Dixie]

>   What is rpciod doing while the machine hangs?
>   Does 'netstat -t' show an active tcp connection to the server?
>   Does tcpdump show any traffic going on the wire?
>   What server are you running against? From the error messages below, I
> see it is a Linux machine, but which kernel is it running?

Server is 2.6.18-5 from debian.

>From /proc/mounts:

server1:/files /files nfs
rw,vers=3,rsize=8192,wsize=8192,hard,nointr,proto=tcp,timeo=600,retrans=2,sec=sys,addr=10.64.2.90
0 0
devfile:/srv/linshared_srv /srv nfs
rw,vers=3,rsize=32768,wsize=32768,hard,nointr,proto=tcp,timeo=600,retrans=2,sec=sys,addr=10.64.2.21
0 0
devfile:/home /home nfs4
rw,vers=4,rsize=32768,wsize=32768,hard,intr,proto=tcp,timeo=600,retrans=3,sec=sys,addr=10.64.2.21
0 0

The nfs connections went into CLOSE_WAIT:
tcp        0      0 10.64.2.25:888          10.64.2.21:2049        
CLOSE_WAIT
tcp        0      0 10.64.2.25:974          10.64.2.21:2049        
CLOSE_WAIT

I can't see any traffic for it attempting to reconnect.

Below are the rpciod stacktraces from the previous hang.
Also rpc.idmap looks to be in the middle of something.

Cheers,
Andrew

rpciod/0      S f76f9e7c     0  2663      2
       f7d7c1f0 00000046 00000002 f76f9e7c f76f9e74 00000000 00000286
f669bc00
       f7d7c358 c180a940 00000000 015b37db f669bc00 dfbc8c80 000000ff
00000000
       00000000 00000000 f76f9ebc 00000000 f76f9ec4 c180284c f8c62e85
c02bc97f
Call Trace:
 [<f8c62e85>] rpc_wait_bit_interruptible+0x1a/0x1f [sunrpc]
 [<c02bc97f>] __wait_on_bit+0x33/0x58
 [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
 [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
 [<c02bca07>] out_of_line_wait_on_bit+0x63/0x6b
 [<c013545e>] wake_bit_function+0x0/0x3c
 [<f8c62e19>] __rpc_wait_for_completion_task+0x32/0x39 [sunrpc]
 [<f8ce1352>] nfs4_wait_for_completion_rpc_task+0x1b/0x2f [nfs]
 [<f8ce2336>] nfs4_proc_delegreturn+0x116/0x172 [nfs]
 [<f8c63411>] rpc_async_schedule+0x0/0xa [sunrpc]
 [<f8ced370>] nfs_do_return_delegation+0xf/0x1d [nfs]
 [<f8cd135f>] nfs_dentry_iput+0xd/0x49 [nfs]
 [<c01865d2>] dentry_iput+0x74/0x93
 [<c018666d>] d_kill+0x2d/0x46
 [<c0186970>] dput+0xd5/0xdc
 [<f8ce4016>] nfs4_free_closedata+0x26/0x41 [nfs]
 [<f8c62c8d>] rpc_release_calldata+0x16/0x20 [sunrpc]
 [<c013220d>] run_workqueue+0x7d/0x109
 [<c0132a83>] worker_thread+0x0/0xc5
 [<c0132b3d>] worker_thread+0xba/0xc5
 [<c0135429>] autoremove_wake_function+0x0/0x35
 [<c0135362>] kthread+0x38/0x5e
 [<c013532a>] kthread+0x0/0x5e
 [<c0104b0f>] kernel_thread_helper+0x7/0x10

rpciod/1-3 identical:
       df848710 00000046 00000002 f76fbfa0 f76fbf98 00000000 f8c633fd
00000572
       df848878 c1812940 00000001 015b36d3 df9abc08 f8c63411 000000ff
00000000
       00000000 00000000 f776a840 c0132a83 f76fbfd0 00000000 c0132b0b
00000000
Call Trace:
 [<f8c633fd>] __rpc_execute+0x21d/0x231 [sunrpc]
 [<f8c63411>] rpc_async_schedule+0x0/0xa [sunrpc]
 [<c0132a83>] worker_thread+0x0/0xc5
 [<c0132b0b>] worker_thread+0x88/0xc5
 [<c0135429>] autoremove_wake_function+0x0/0x35
 [<c0135362>] kthread+0x38/0x5e
 [<c013532a>] kthread+0x0/0x5e
 [<c0104b0f>] kernel_thread_helper+0x7/0x10
 =======================
rpc.idmapd    S f777ff10     0  2687      1
       f7cea610 00000086 00000002 f777ff10 f777ff08 00000000 00000000
00000000
       f7cea778 c1822940 00000003 015d5741 00000000 00000000 000000ff
00000000
       00000000 00000000 7fffffff f75e2b00 080536e8 00000286 c02bc7f1
00000000
Call Trace:
 [<c01355e8>] add_wait_queue+0x12/0x32
 [<c017d287>] pipe_poll+0x24/0x7d
 [<c0183476>] do_select+0x365/0x3bc
 [<c0183a60>] __pollwait+0x0/0xac
 [<c011f44f>] default_wake_function+0x0/0x8
message repeated 10 times
 [<c0259bb5>] skb_release_all+0xa3/0xfa
 [<c025e590>] dev_hard_start_xmit+0x20c/0x277
 [<c026d227>] __qdisc_run+0x9e/0x164
 [<c02564e7>] sk_reset_timer+0xc/0x16
 [<c0260758>] dev_queue_xmit+0x288/0x2b0
 [<c026b72e>] eth_header+0x0/0xb6
 [<c0264fe5>] neigh_resolve_output+0x203/0x235
 [<c027dd59>] ip_finish_output+0x0/0x208
 [<c027df29>] ip_finish_output+0x1d0/0x208
 [<c027edd1>] ip_output+0x7d/0x92
 [<c01e240c>] number+0x147/0x215
 [<c0183750>] core_sys_select+0x283/0x2a0
 [<c01e2d23>] vsnprintf+0x440/0x47c
 [<c0187123>] d_lookup+0x1b/0x3b
 [<c01a5fe3>] proc_flush_task+0x12b/0x235
 [<c0135a53>] posix_cpu_timers_exit_group+0x4a/0x50
 [<c0108472>] convert_fxsr_from_user+0x15/0xd5
 [<c0183be2>] sys_select+0xd6/0x187
 [<c018a6ce>] mntput_no_expire+0x11/0x66
 [<c0176b05>] filp_close+0x51/0x58
 [<c012743f>] sys_wait4+0x31/0x34
 [<c0103e5e>] sysenter_past_esp+0x6b/0xa1

Re: (fwd) nfs hang on 2.6.24

[Trond Myklebust]

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


On Thu, 2008-02-07 at 11:40 +1300, Andrew Dixie wrote:
> >   What is rpciod doing while the machine hangs?
> >   Does 'netstat -t' show an active tcp connection to the server?
> >   Does tcpdump show any traffic going on the wire?
> >   What server are you running against? From the error messages below, I
> > see it is a Linux machine, but which kernel is it running?
> 
> Server is 2.6.18-5 from debian.
> 
> >From /proc/mounts:
> 
> server1:/files /files nfs
> rw,vers=3,rsize=8192,wsize=8192,hard,nointr,proto=tcp,timeo=600,retrans=2,sec=sys,addr=10.64.2.90
> 0 0
> devfile:/srv/linshared_srv /srv nfs
> rw,vers=3,rsize=32768,wsize=32768,hard,nointr,proto=tcp,timeo=600,retrans=2,sec=sys,addr=10.64.2.21
> 0 0
> devfile:/home /home nfs4
> rw,vers=4,rsize=32768,wsize=32768,hard,intr,proto=tcp,timeo=600,retrans=3,sec=sys,addr=10.64.2.21
> 0 0
> 
> The nfs connections went into CLOSE_WAIT:
> tcp        0      0 10.64.2.25:888          10.64.2.21:2049        
> CLOSE_WAIT
> tcp        0      0 10.64.2.25:974          10.64.2.21:2049        
> CLOSE_WAIT
> 
> I can't see any traffic for it attempting to reconnect.
> 
> Below are the rpciod stacktraces from the previous hang.
> Also rpc.idmap looks to be in the middle of something.
> 
> Cheers,
> Andrew
> 
> rpciod/0      S f76f9e7c     0  2663      2
>        f7d7c1f0 00000046 00000002 f76f9e7c f76f9e74 00000000 00000286
> f669bc00
>        f7d7c358 c180a940 00000000 015b37db f669bc00 dfbc8c80 000000ff
> 00000000
>        00000000 00000000 f76f9ebc 00000000 f76f9ec4 c180284c f8c62e85
> c02bc97f
> Call Trace:
>  [<f8c62e85>] rpc_wait_bit_interruptible+0x1a/0x1f [sunrpc]
>  [<c02bc97f>] __wait_on_bit+0x33/0x58
>  [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
>  [<f8c62e6b>] rpc_wait_bit_interruptible+0x0/0x1f [sunrpc]
>  [<c02bca07>] out_of_line_wait_on_bit+0x63/0x6b
>  [<c013545e>] wake_bit_function+0x0/0x3c
>  [<f8c62e19>] __rpc_wait_for_completion_task+0x32/0x39 [sunrpc]
>  [<f8ce1352>] nfs4_wait_for_completion_rpc_task+0x1b/0x2f [nfs]
>  [<f8ce2336>] nfs4_proc_delegreturn+0x116/0x172 [nfs]
>  [<f8c63411>] rpc_async_schedule+0x0/0xa [sunrpc]
>  [<f8ced370>] nfs_do_return_delegation+0xf/0x1d [nfs]
>  [<f8cd135f>] nfs_dentry_iput+0xd/0x49 [nfs]
>  [<c01865d2>] dentry_iput+0x74/0x93
>  [<c018666d>] d_kill+0x2d/0x46
>  [<c0186970>] dput+0xd5/0xdc
>  [<f8ce4016>] nfs4_free_closedata+0x26/0x41 [nfs]
>  [<f8c62c8d>] rpc_release_calldata+0x16/0x20 [sunrpc]
>  [<c013220d>] run_workqueue+0x7d/0x109
>  [<c0132a83>] worker_thread+0x0/0xc5
>  [<c0132b3d>] worker_thread+0xba/0xc5
>  [<c0135429>] autoremove_wake_function+0x0/0x35
>  [<c0135362>] kthread+0x38/0x5e
>  [<c013532a>] kthread+0x0/0x5e
>  [<c0104b0f>] kernel_thread_helper+0x7/0x10

That's the bug right there. rpciod should never be calling a
synchrounous RPC call.

I've already got a fix for this bug against 2.6.24. Could you see if it
applies to your kernel too?

Cheers
  Trond

[-- Attachment #2: linux-2.6.24-116-make_asynchronous_delegreturn.dif --]
[-- Type: message/rfc822, Size: 7195 bytes --]

From: Trond Myklebust <Trond.Myklebust@netapp.com>
Subject: No Subject
Date: Thu, 24 Jan 2008 18:14:34 -0500
Message-ID: <1202338699.8549.43.camel-rJ7iovZKK19ZJLDQqaL3InhyD016LWXt@public.gmane.org>

Otherwise, there is a potential deadlock if the last dput() from an NFSv4
close() or other asynchronous operation leads to nfs_clear_inode calling
the synchronous delegreturn.

Signed-off-by: Trond Myklebust <Trond.Myklebust@netapp.com>
---

 fs/nfs/delegation.c |   29 +++++++++++++++++++++++++----
 fs/nfs/delegation.h |    3 ++-
 fs/nfs/dir.c        |    1 -
 fs/nfs/inode.c      |    2 +-
 fs/nfs/nfs4proc.c   |   22 +++++++++++++---------
 5 files changed, 41 insertions(+), 16 deletions(-)

diff --git a/fs/nfs/delegation.c b/fs/nfs/delegation.c
index b03dcd8..2dead8d 100644
--- a/fs/nfs/delegation.c
+++ b/fs/nfs/delegation.c
@@ -174,11 +174,11 @@ int nfs_inode_set_delegation(struct inode *inode, struct rpc_cred *cred, struct
 	return status;
 }
 
-static int nfs_do_return_delegation(struct inode *inode, struct nfs_delegation *delegation)
+static int nfs_do_return_delegation(struct inode *inode, struct nfs_delegation *delegation, int issync)
 {
 	int res = 0;
 
-	res = nfs4_proc_delegreturn(inode, delegation->cred, &delegation->stateid);
+	res = nfs4_proc_delegreturn(inode, delegation->cred, &delegation->stateid, issync);
 	nfs_free_delegation(delegation);
 	return res;
 }
@@ -208,7 +208,7 @@ static int __nfs_inode_return_delegation(struct inode *inode, struct nfs_delegat
 	up_read(&clp->cl_sem);
 	nfs_msync_inode(inode);
 
-	return nfs_do_return_delegation(inode, delegation);
+	return nfs_do_return_delegation(inode, delegation, 1);
 }
 
 static struct nfs_delegation *nfs_detach_delegation_locked(struct nfs_inode *nfsi, const nfs4_stateid *stateid)
@@ -228,6 +228,27 @@ nomatch:
 	return NULL;
 }
 
+/*
+ * This function returns the delegation without reclaiming opens
+ * or protecting against delegation reclaims.
+ * It is therefore really only safe to be called from
+ * nfs4_clear_inode()
+ */
+void nfs_inode_return_delegation_noreclaim(struct inode *inode)
+{
+	struct nfs_client *clp = NFS_SERVER(inode)->nfs_client;
+	struct nfs_inode *nfsi = NFS_I(inode);
+	struct nfs_delegation *delegation;
+
+	if (rcu_dereference(nfsi->delegation) != NULL) {
+		spin_lock(&clp->cl_lock);
+		delegation = nfs_detach_delegation_locked(nfsi, NULL);
+		spin_unlock(&clp->cl_lock);
+		if (delegation != NULL)
+			nfs_do_return_delegation(inode, delegation, 0);
+	}
+}
+
 int nfs_inode_return_delegation(struct inode *inode)
 {
 	struct nfs_client *clp = NFS_SERVER(inode)->nfs_client;
@@ -388,7 +409,7 @@ static int recall_thread(void *data)
 	nfs_msync_inode(inode);
 
 	if (delegation != NULL)
-		nfs_do_return_delegation(inode, delegation);
+		nfs_do_return_delegation(inode, delegation, 1);
 	iput(inode);
 	module_put_and_exit(0);
 }
diff --git a/fs/nfs/delegation.h b/fs/nfs/delegation.h
index 5874ce7..f1c5e2a 100644
--- a/fs/nfs/delegation.h
+++ b/fs/nfs/delegation.h
@@ -29,6 +29,7 @@ int nfs_inode_set_delegation(struct inode *inode, struct rpc_cred *cred, struct
 void nfs_inode_reclaim_delegation(struct inode *inode, struct rpc_cred *cred, struct nfs_openres *res);
 int nfs_inode_return_delegation(struct inode *inode);
 int nfs_async_inode_return_delegation(struct inode *inode, const nfs4_stateid *stateid);
+void nfs_inode_return_delegation_noreclaim(struct inode *inode);
 
 struct inode *nfs_delegation_find_inode(struct nfs_client *clp, const struct nfs_fh *fhandle);
 void nfs_return_all_delegations(struct super_block *sb);
@@ -39,7 +40,7 @@ void nfs_delegation_mark_reclaim(struct nfs_client *clp);
 void nfs_delegation_reap_unclaimed(struct nfs_client *clp);
 
 /* NFSv4 delegation-related procedures */
-int nfs4_proc_delegreturn(struct inode *inode, struct rpc_cred *cred, const nfs4_stateid *stateid);
+int nfs4_proc_delegreturn(struct inode *inode, struct rpc_cred *cred, const nfs4_stateid *stateid, int issync);
 int nfs4_open_delegation_recall(struct nfs_open_context *ctx, struct nfs4_state *state, const nfs4_stateid *stateid);
 int nfs4_lock_delegation_recall(struct nfs4_state *state, struct file_lock *fl);
 int nfs4_copy_delegation_stateid(nfs4_stateid *dst, struct inode *inode);
diff --git a/fs/nfs/dir.c b/fs/nfs/dir.c
index c578d94..5ca762d 100644
--- a/fs/nfs/dir.c
+++ b/fs/nfs/dir.c
@@ -864,7 +864,6 @@ static int nfs_dentry_delete(struct dentry *dentry)
  */
 static void nfs_dentry_iput(struct dentry *dentry, struct inode *inode)
 {
-	nfs_inode_return_delegation(inode);
 	if (S_ISDIR(inode->i_mode))
 		/* drop any readdir cache as it could easily be old */
 		NFS_I(inode)->cache_validity |= NFS_INO_INVALID_DATA;
diff --git a/fs/nfs/inode.c b/fs/nfs/inode.c
index 5d381cf..3f332e5 100644
--- a/fs/nfs/inode.c
+++ b/fs/nfs/inode.c
@@ -1145,7 +1145,7 @@ static int nfs_update_inode(struct inode *inode, struct nfs_fattr *fattr)
 void nfs4_clear_inode(struct inode *inode)
 {
 	/* If we are holding a delegation, return it! */
-	nfs_inode_return_delegation(inode);
+	nfs_inode_return_delegation_noreclaim(inode);
 	/* First call standard NFS clear_inode() code */
 	nfs_clear_inode(inode);
 }
diff --git a/fs/nfs/nfs4proc.c b/fs/nfs/nfs4proc.c
index 89efbcd..5c189bd 100644
--- a/fs/nfs/nfs4proc.c
+++ b/fs/nfs/nfs4proc.c
@@ -2991,7 +2991,7 @@ static const struct rpc_call_ops nfs4_delegreturn_ops = {
 	.rpc_release = nfs4_delegreturn_release,
 };
 
-static int _nfs4_proc_delegreturn(struct inode *inode, struct rpc_cred *cred, const nfs4_stateid *stateid)
+static int _nfs4_proc_delegreturn(struct inode *inode, struct rpc_cred *cred, const nfs4_stateid *stateid, int issync)
 {
 	struct nfs4_delegreturndata *data;
 	struct nfs_server *server = NFS_SERVER(inode);
@@ -3006,7 +3006,7 @@ static int _nfs4_proc_delegreturn(struct inode *inode, struct rpc_cred *cred, co
 		.callback_ops = &nfs4_delegreturn_ops,
 		.flags = RPC_TASK_ASYNC,
 	};
-	int status;
+	int status = 0;
 
 	data = kmalloc(sizeof(*data), GFP_KERNEL);
 	if (data == NULL)
@@ -3028,23 +3028,27 @@ static int _nfs4_proc_delegreturn(struct inode *inode, struct rpc_cred *cred, co
 	task = rpc_run_task(&task_setup_data);
 	if (IS_ERR(task))
 		return PTR_ERR(task);
+	if (!issync)
+		goto out;
 	status = nfs4_wait_for_completion_rpc_task(task);
-	if (status == 0) {
-		status = data->rpc_status;
-		if (status == 0)
-			nfs_refresh_inode(inode, &data->fattr);
-	}
+	if (status != 0)
+		goto out;
+	status = data->rpc_status;
+	if (status != 0)
+		goto out;
+	nfs_refresh_inode(inode, &data->fattr);
+out:
 	rpc_put_task(task);
 	return status;
 }
 
-int nfs4_proc_delegreturn(struct inode *inode, struct rpc_cred *cred, const nfs4_stateid *stateid)
+int nfs4_proc_delegreturn(struct inode *inode, struct rpc_cred *cred, const nfs4_stateid *stateid, int issync)
 {
 	struct nfs_server *server = NFS_SERVER(inode);
 	struct nfs4_exception exception = { };
 	int err;
 	do {
-		err = _nfs4_proc_delegreturn(inode, cred, stateid);
+		err = _nfs4_proc_delegreturn(inode, cred, stateid, issync);
 		switch (err) {
 			case -NFS4ERR_STALE_STATEID:
 			case -NFS4ERR_EXPIRED:

Re: (fwd) nfs hang on 2.6.24

[Andrew Dixie]

> I've already got a fix for this bug against 2.6.24. Could you see if it
> applies to your kernel too?

Thanks for this.

My client is 2.6.24 so it obviously applies.
I don't believe the bug is in 2.6.18; and 2.6.22 crashes due to other
problems before I can reproduce this hang.

You didn't specifically ask me to test, and with other obligations over
the next few weeks I'm just happy to know a fix is in the pipeline.

Please let me know if there is anything more you would like from me.

Cheers,
Andrew