please take a look
----- Forwarded message from Andrew Dixie <[email protected]> -----
Date: Tue, 5 Feb 2008 12:57:37 +1300 (NZDT)
Subject: nfs hang on 2.6.24
From: Andrew Dixie <[email protected]>
To: [email protected]
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 [email protected]
with a subject of "unsubscribe". Trouble? Contact [email protected]
----- End forwarded message -----
On Tue, 2008-02-05 at 10:01 +0100, maximilian attems wrote:
> please take a look
>
> ----- Forwarded message from Andrew Dixie <[email protected]> -----
>
> Date: Tue, 5 Feb 2008 12:57:37 +1300 (NZDT)
> Subject: nfs hang on 2.6.24
> From: Andrew Dixie <[email protected]>
> To: [email protected]
>
> 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
>
>
>
> 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
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
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 [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
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
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.
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.
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.
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;
> }
>
>
> 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;
}
> 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
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