nfsv3 client process stuck in rwsem_down_failed_common()

DISCUSSION Frank van Maarseveen 2 participants 12 messages May 14, 2007

Subsystems (2)

NFS client NFS server

lore

Share & tools

lore

Frank van Maarseveen

author

2007-05-14 15:54 UTC #0 lore raw

On a 2.6.21.1 NFSv3 client box multiple processes got stuck with this trace:

[<c02926e5>] rwsem_down_failed_common+0x85/0x180
[<c052a36d>] rwsem_down_read_failed+0x1d/0x30
[<c052a437>] call_rwsem_down_read_failed+0x7/0x10
[<c022622e>] nlmclnt_unlock+0x2e/0xc0
[<c02258da>] nlmclnt_proc+0x29a/0x2d0
[<c01f088e>] nfs3_proc_lock+0xe/0x10
[<c01e3904>] do_unlk+0x44/0x70
[<c01e3a9d>] nfs_lock+0xbd/0x120
[<c017dfd1>] locks_remove_posix+0xb1/0xc0
[<c016dc8d>] filp_close+0x2d/0x70
[<c01248a6>] close_files+0x56/0x70
[<c012490c>] put_files_struct+0x1c/0x50
[<c012533a>] do_exit+0x13a/0x3f0
[<c0125649>] do_group_exit+0x29/0x70
[<c012e73f>] get_signal_to_deliver+0x21f/0x2b0
[<c0103e96>] do_signal+0x56/0x160
[<c0103fde>] do_notify_resume+0x3e/0x40
[<c01041ae>] work_notifysig+0x13/0x25

Two processes had an independent shared read lock on different files and when killing them with ^C they got stuck in state 'D' with above stack trace. I'm not sure what brought then there other than that the server went through a number of unusual reboots for testing purposes.

Signature · 10 lines

Frank

-------------------------------------------------------------------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and take
control of your XML. No limits. Just data. Click to get it now.
http://sourceforge.net/powerbar/db2/
_______________________________________________
NFS maillist  -  [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

Trond Myklebust

2007-05-14 15:59 UTC #1 lore raw

Quoted 22 lines · Frank van Maarseveen

On a 2.6.21.1 NFSv3 client box multiple processes got stuck with this trace:

[<c02926e5>] rwsem_down_failed_common+0x85/0x180
[<c052a36d>] rwsem_down_read_failed+0x1d/0x30
[<c052a437>] call_rwsem_down_read_failed+0x7/0x10
[<c022622e>] nlmclnt_unlock+0x2e/0xc0
[<c02258da>] nlmclnt_proc+0x29a/0x2d0
[<c01f088e>] nfs3_proc_lock+0xe/0x10
[<c01e3904>] do_unlk+0x44/0x70
[<c01e3a9d>] nfs_lock+0xbd/0x120
[<c017dfd1>] locks_remove_posix+0xb1/0xc0
[<c016dc8d>] filp_close+0x2d/0x70
[<c01248a6>] close_files+0x56/0x70
[<c012490c>] put_files_struct+0x1c/0x50
[<c012533a>] do_exit+0x13a/0x3f0
[<c0125649>] do_group_exit+0x29/0x70
[<c012e73f>] get_signal_to_deliver+0x21f/0x2b0
[<c0103e96>] do_signal+0x56/0x160
[<c0103fde>] do_notify_resume+0x3e/0x40
[<c01041ae>] work_notifysig+0x13/0x25

Quoted 4 lines

Two processes had an independent shared read lock on different files and when killing them with ^C they got stuck in state 'D' with above stack trace. I'm not sure what brought then there other than that the server went through a number of unusual reboots for testing purposes.

Are there any processes with a name of the form '<hostname>-reclaim' hanging too?

Trond

-------------------------------------------------------------------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and take control of your XML. No limits. Just data. Click to get it now.
http://sourceforge.net/powerbar/db2/
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

Frank van Maarseveen

author

2007-05-14 16:05 UTC #2 lore raw

Quoted 23 lines · Trond Myklebust

Quoted 22 lines · Frank van Maarseveen

On a 2.6.21.1 NFSv3 client box multiple processes got stuck with this trace:

[<c02926e5>] rwsem_down_failed_common+0x85/0x180
[<c052a36d>] rwsem_down_read_failed+0x1d/0x30
[<c052a437>] call_rwsem_down_read_failed+0x7/0x10
[<c022622e>] nlmclnt_unlock+0x2e/0xc0
[<c02258da>] nlmclnt_proc+0x29a/0x2d0
[<c01f088e>] nfs3_proc_lock+0xe/0x10
[<c01e3904>] do_unlk+0x44/0x70
[<c01e3a9d>] nfs_lock+0xbd/0x120
[<c017dfd1>] locks_remove_posix+0xb1/0xc0
[<c016dc8d>] filp_close+0x2d/0x70
[<c01248a6>] close_files+0x56/0x70
[<c012490c>] put_files_struct+0x1c/0x50
[<c012533a>] do_exit+0x13a/0x3f0
[<c0125649>] do_group_exit+0x29/0x70
[<c012e73f>] get_signal_to_deliver+0x21f/0x2b0
[<c0103e96>] do_signal+0x56/0x160
[<c0103fde>] do_notify_resume+0x3e/0x40
[<c01041ae>] work_notifysig+0x13/0x25

Quoted 7 lines

Quoted 4 lines
Two processes had an independent shared read lock on different files and when killing them with ^C they got stuck in state 'D' with above stack trace. I'm not sure what brought then there other than that the server went through a number of unusual reboots for testing purposes.
Are there any processes with a name of the form '<hostname>-reclaim' hanging too?

yes, two of them, each for a different NFS server (as I would expect). The traces are identical:

[<c0512f1d>] rpc_wait_bit_interruptible+0x1d/0x30
[<c0529114>] __wait_on_bit+0x44/0x70
[<c05291bd>] out_of_line_wait_on_bit+0x7d/0x90
[<c05137f5>] __rpc_execute+0xa5/0x1e0
[<c0513949>] rpc_execute+0x19/0x20
[<c050da56>] rpc_call_sync+0x96/0xa0
[<c0225b17>] nlmclnt_call+0x77/0x1e0
[<c02261ac>] nlmclnt_reclaim+0x6c/0xc0
[<c0225236>] reclaimer+0x106/0x1f0
[<c0105317>] kernel_thread_helper+0x7/0x10

Signature · 10 lines

Frank

-------------------------------------------------------------------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and take
control of your XML. No limits. Just data. Click to get it now.
http://sourceforge.net/powerbar/db2/
_______________________________________________
NFS maillist  -  [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

Trond Myklebust

2007-05-14 16:12 UTC #3 lore raw

Quoted 29 lines · Frank van Maarseveen

Quoted 28 lines · Trond Myklebust
Quoted 26 lines · Frank van Maarseveen
On a 2.6.21.1 NFSv3 client box multiple processes got stuck with this trace:
[<c02926e5>] rwsem_down_failed_common+0x85/0x180
[<c052a36d>] rwsem_down_read_failed+0x1d/0x30
[<c052a437>] call_rwsem_down_read_failed+0x7/0x10
[<c022622e>] nlmclnt_unlock+0x2e/0xc0
[<c02258da>] nlmclnt_proc+0x29a/0x2d0
[<c01f088e>] nfs3_proc_lock+0xe/0x10
[<c01e3904>] do_unlk+0x44/0x70
[<c01e3a9d>] nfs_lock+0xbd/0x120
[<c017dfd1>] locks_remove_posix+0xb1/0xc0
[<c016dc8d>] filp_close+0x2d/0x70
[<c01248a6>] close_files+0x56/0x70
[<c012490c>] put_files_struct+0x1c/0x50
[<c012533a>] do_exit+0x13a/0x3f0
[<c0125649>] do_group_exit+0x29/0x70
[<c012e73f>] get_signal_to_deliver+0x21f/0x2b0
[<c0103e96>] do_signal+0x56/0x160
[<c0103fde>] do_notify_resume+0x3e/0x40
[<c01041ae>] work_notifysig+0x13/0x25
Two processes had an independent shared read lock on different files and when killing them with ^C they got stuck in state 'D' with above stack trace. I'm not sure what brought then there other than that the server went through a number of unusual reboots for testing purposes.

Quoted 4 lines

Quoted 2 lines
Are there any processes with a name of the form '<hostname>-reclaim' hanging too?
yes, two of them, each for a different NFS server (as I would expect).

Are the NFS servers up and running?

Quoted 12 lines

The traces are identical:

[<c0512f1d>] rpc_wait_bit_interruptible+0x1d/0x30
[<c0529114>] __wait_on_bit+0x44/0x70
[<c05291bd>] out_of_line_wait_on_bit+0x7d/0x90
[<c05137f5>] __rpc_execute+0xa5/0x1e0
[<c0513949>] rpc_execute+0x19/0x20
[<c050da56>] rpc_call_sync+0x96/0xa0
[<c0225b17>] nlmclnt_call+0x77/0x1e0
[<c02261ac>] nlmclnt_reclaim+0x6c/0xc0
[<c0225236>] reclaimer+0x106/0x1f0
[<c0105317>] kernel_thread_helper+0x7/0x10

Could you please use 'echo 0 >/proc/sys/sunrpc/rpc_debug' in order to find out on which rpc queue these tasks are sleeping?

Cheers
Trond

Frank van Maarseveen

author

2007-05-14 16:15 UTC #4 lore raw

Quoted 30 lines · Trond Myklebust

Quoted 29 lines · Frank van Maarseveen
Quoted 28 lines · Trond Myklebust
Quoted 26 lines · Frank van Maarseveen
On a 2.6.21.1 NFSv3 client box multiple processes got stuck with this trace:
[<c02926e5>] rwsem_down_failed_common+0x85/0x180
[<c052a36d>] rwsem_down_read_failed+0x1d/0x30
[<c052a437>] call_rwsem_down_read_failed+0x7/0x10
[<c022622e>] nlmclnt_unlock+0x2e/0xc0
[<c02258da>] nlmclnt_proc+0x29a/0x2d0
[<c01f088e>] nfs3_proc_lock+0xe/0x10
[<c01e3904>] do_unlk+0x44/0x70
[<c01e3a9d>] nfs_lock+0xbd/0x120
[<c017dfd1>] locks_remove_posix+0xb1/0xc0
[<c016dc8d>] filp_close+0x2d/0x70
[<c01248a6>] close_files+0x56/0x70
[<c012490c>] put_files_struct+0x1c/0x50
[<c012533a>] do_exit+0x13a/0x3f0
[<c0125649>] do_group_exit+0x29/0x70
[<c012e73f>] get_signal_to_deliver+0x21f/0x2b0
[<c0103e96>] do_signal+0x56/0x160
[<c0103fde>] do_notify_resume+0x3e/0x40
[<c01041ae>] work_notifysig+0x13/0x25
Two processes had an independent shared read lock on different files and when killing them with ^C they got stuck in state 'D' with above stack trace. I'm not sure what brought then there other than that the server went through a number of unusual reboots for testing purposes.

Quoted 6 lines

Quoted 4 lines
Quoted 2 lines
Are there any processes with a name of the form '<hostname>-reclaim' hanging too?
yes, two of them, each for a different NFS server (as I would expect).
Are the NFS servers up and running?

yes, I also ran a tcpdump for one of them but did not see any activity.

Quoted 14 lines

Quoted 13 lines

The traces are identical:

[<c0512f1d>] rpc_wait_bit_interruptible+0x1d/0x30
[<c0529114>] __wait_on_bit+0x44/0x70
[<c05291bd>] out_of_line_wait_on_bit+0x7d/0x90
[<c05137f5>] __rpc_execute+0xa5/0x1e0
[<c0513949>] rpc_execute+0x19/0x20
[<c050da56>] rpc_call_sync+0x96/0xa0
[<c0225b17>] nlmclnt_call+0x77/0x1e0
[<c02261ac>] nlmclnt_reclaim+0x6c/0xc0
[<c0225236>] reclaimer+0x106/0x1f0
[<c0105317>] kernel_thread_helper+0x7/0x10

Quoted 2 lines

Could you please use 'echo 0 >/proc/sys/sunrpc/rpc_debug' in order to find out on which rpc queue these tasks are sleeping?

-pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--
30871 0002 0480 0 c7708614 100021 f43f4000 10000000 xprt_pending c050e4d0 c057f3f4
30873 0002 0480 0 f00b4eb4 100021 cc809000 10000000 xprt_pending c050e4d0 c057f3f4

Signature · 10 lines

Frank

-------------------------------------------------------------------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and take
control of your XML. No limits. Just data. Click to get it now.
http://sourceforge.net/powerbar/db2/
_______________________________________________
NFS maillist  -  [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

Trond Myklebust

2007-05-14 16:33 UTC #5 lore raw

Quoted 6 lines · Frank van Maarseveen

Quoted 2 lines
Could you please use 'echo 0 >/proc/sys/sunrpc/rpc_debug' in order to find out on which rpc queue these tasks are sleeping?
-pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--
30871 0002 0480 0 c7708614 100021 f43f4000 10000000 xprt_pending c050e4d0 c057f3f4
30873 0002 0480 0 f00b4eb4 100021 cc809000 10000000 xprt_pending c050e4d0 c057f3f4

                                                  ^^^^^^^^ Ouch!

That is a pretty massive timeout. What is your value of /proc/sys/fs/nfs/nlm_timeout ?

Cheers
Trond

Frank van Maarseveen

author

2007-05-14 16:39 UTC #6 lore raw

Quoted 11 lines · Trond Myklebust

Quoted 6 lines · Frank van Maarseveen
Quoted 2 lines
Could you please use 'echo 0 >/proc/sys/sunrpc/rpc_debug' in order to find out on which rpc queue these tasks are sleeping?
-pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--
30871 0002 0480 0 c7708614 100021 f43f4000 10000000 xprt_pending c050e4d0 c057f3f4
30873 0002 0480 0 f00b4eb4 100021 cc809000 10000000 xprt_pending c050e4d0 c057f3f4
                                                  ^^^^^^^^ Ouch!
That is a pretty massive timeout. What is your value of /proc/sys/fs/nfs/nlm_timeout ?

Unfortunately it became necessary to reboot the machine :-(. Right now it says 10.

Signature · 10 lines

Frank

-------------------------------------------------------------------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and take
control of your XML. No limits. Just data. Click to get it now.
http://sourceforge.net/powerbar/db2/
_______________________________________________
NFS maillist  -  [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

Trond Myklebust

2007-05-14 16:56 UTC #7 lore raw

Quoted 8 lines · Frank van Maarseveen

Quoted 7 lines · Trond Myklebust
Quoted 6 lines · Frank van Maarseveen
Quoted 2 lines
Could you please use 'echo 0 >/proc/sys/sunrpc/rpc_debug' in order to find out on which rpc queue these tasks are sleeping?
-pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--
30871 0002 0480 0 c7708614 100021 f43f4000 10000000 xprt_pending c050e4d0 c057f3f4
30873 0002 0480 0 f00b4eb4 100021 cc809000 10000000 xprt_pending c050e4d0 c057f3f4

Quoted 6 lines

Quoted 4 lines
                                                  ^^^^^^^^ Ouch!
That is a pretty massive timeout. What is your value of /proc/sys/fs/nfs/nlm_timeout ?
Unfortunately it became necessary to reboot the machine :-(. Right now it says 10.

10 seconds looks like the correct default. I assume that you hadn't changed that value prior to the reboot...

One last question, just in case: what value are you using for CONFIG_HZ?

Trond

Frank van Maarseveen

author

2007-05-14 17:02 UTC #8 lore raw

Quoted 11 lines · Trond Myklebust

Quoted 10 lines · Frank van Maarseveen
Quoted 9 lines · Trond Myklebust
Quoted 6 lines · Frank van Maarseveen
Quoted 2 lines
Could you please use 'echo 0 >/proc/sys/sunrpc/rpc_debug' in order to find out on which rpc queue these tasks are sleeping?
-pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--
30871 0002 0480 0 c7708614 100021 f43f4000 10000000 xprt_pending c050e4d0 c057f3f4
30873 0002 0480 0 f00b4eb4 100021 cc809000 10000000 xprt_pending c050e4d0 c057f3f4
                                                  ^^^^^^^^ Ouch!

Quoted 7 lines

Quoted 4 lines
Quoted 2 lines
That is a pretty massive timeout. What is your value of /proc/sys/fs/nfs/nlm_timeout ?
Unfortunately it became necessary to reboot the machine :-(. Right now it says 10.
10 seconds looks like the correct default. I assume that you hadn't changed that value prior to the reboot...

right, I didn't knew it existed and I'm not aware of any command which can change it. Did some grepping around and it didn't turn up anything.

Quoted 2 lines

One last question, just in case: what value are you using for CONFIG_HZ?

1000

Signature · 10 lines

Frank

-------------------------------------------------------------------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and take
control of your XML. No limits. Just data. Click to get it now.
http://sourceforge.net/powerbar/db2/
_______________________________________________
NFS maillist  -  [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

Frank van Maarseveen

author

2007-05-14 17:05 UTC #9 lore raw

Quoted 20 lines · Frank van Maarseveen

Quoted 11 lines · Trond Myklebust
Quoted 10 lines · Frank van Maarseveen
Quoted 9 lines · Trond Myklebust
Quoted 6 lines · Frank van Maarseveen
Quoted 2 lines
Could you please use 'echo 0 >/proc/sys/sunrpc/rpc_debug' in order to find out on which rpc queue these tasks are sleeping?
-pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--
30871 0002 0480 0 c7708614 100021 f43f4000 10000000 xprt_pending c050e4d0 c057f3f4
30873 0002 0480 0 f00b4eb4 100021 cc809000 10000000 xprt_pending c050e4d0 c057f3f4
                                                  ^^^^^^^^ Ouch!
Quoted 7 lines
Quoted 4 lines
Quoted 2 lines
That is a pretty massive timeout. What is your value of /proc/sys/fs/nfs/nlm_timeout ?
Unfortunately it became necessary to reboot the machine :-(. Right now it says 10.
10 seconds looks like the correct default. I assume that you hadn't changed that value prior to the reboot...

Quoted 7 lines

right, I didn't knew it existed and I'm not aware of any command which can change it. Did some grepping around and it didn't turn up anything.
Quoted 2 lines
One last question, just in case: what value are you using for CONFIG_HZ?
1000

hmm, so the timeout has become 10 * HZ * HZ?

Signature · 10 lines

Frank

-------------------------------------------------------------------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and take
control of your XML. No limits. Just data. Click to get it now.
http://sourceforge.net/powerbar/db2/
_______________________________________________
NFS maillist  -  [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

Trond Myklebust

2007-05-14 17:15 UTC #10 lore raw

Quoted 25 lines · Frank van Maarseveen

Quoted 24 lines · Frank van Maarseveen
Quoted 11 lines · Trond Myklebust
Quoted 10 lines · Frank van Maarseveen
Quoted 9 lines · Trond Myklebust
Quoted 6 lines · Frank van Maarseveen
Quoted 2 lines
Could you please use 'echo 0 >/proc/sys/sunrpc/rpc_debug' in order to find out on which rpc queue these tasks are sleeping?
-pid- proc flgs status -client- -prog- --rqstp- -timeout -rpcwait -action- ---ops--
30871 0002 0480 0 c7708614 100021 f43f4000 10000000 xprt_pending c050e4d0 c057f3f4
30873 0002 0480 0 f00b4eb4 100021 cc809000 10000000 xprt_pending c050e4d0 c057f3f4
                                                  ^^^^^^^^ Ouch!
Quoted 7 lines
Quoted 4 lines
Quoted 2 lines
That is a pretty massive timeout. What is your value of /proc/sys/fs/nfs/nlm_timeout ?
Unfortunately it became necessary to reboot the machine :-(. Right now it says 10.
10 seconds looks like the correct default. I assume that you hadn't changed that value prior to the reboot...
right, I didn't knew it existed and I'm not aware of any command which can change it. Did some grepping around and it didn't turn up anything.
Quoted 1 line

Quoted 5 lines

Quoted 3 lines
Quoted 1 line
One last question, just in case: what value are you using for CONFIG_HZ?
1000
hmm, so the timeout has become 10 * HZ * HZ?

Yeah... nlmsvc_timeout is already in HZ, so the line in fs/lockd/host.c is wrong...

Trond

Trond Myklebust

2007-05-14 17:18 UTC #11 lore raw

Quoted 9 lines · Trond Myklebust

Quoted 6 lines
Quoted 4 lines
Quoted 2 lines
One last question, just in case: what value are you using for CONFIG_HZ?
1000
hmm, so the timeout has become 10 * HZ * HZ?
Yeah... nlmsvc_timeout is already in HZ, so the line in fs/lockd/host.c is wrong...

The following patch should fix it.

Trond

---------------------------------------------
commit 471c10cf35e2743746d9a5f671d9cceeb61393c7

Author: Trond Myklebust <[email protected]>
Date:   Mon May 14 13:16:36 2007 -0400

NLM: Fix locking client timeouts...

nlmsvc_timeout is already in units of HZ...

Signed-off-by Trond Myklebust <[email protected]>

fs/lockd/host.c +1 -1

index ad21c07..96070bf 100644
@@ -221,7 +221,7 @@ nlm_bind_host(struct nlm_host *host)
 					host->h_nextrebind - jiffies);
 		}
 	} else {
-		unsigned long increment = nlmsvc_timeout * HZ;
+		unsigned long increment = nlmsvc_timeout;
 		struct rpc_timeout timeparms = {
 			.to_initval	= increment,
 			.to_increment	= increment,