SUNRPC: Change WARN_ON to an warn message in rpc_exit_task

PATCH In review Kinglong Mee 2 participants 3 messages Aug 17, 2015 – Aug 18, 2015

Subsystems (3)

Networking NFS client NFS server

lore

Share & tools

lore

Kinglong Mee

author

2015-08-17 11:09 UTC #0 lore raw

PATCH 1/1 SUNRPC: Change WARN_ON to an warn message in rpc_exit_task

When testing nfs4.0 lock, I get WARN_ON message as below,

[  278.733391] ------------[ cut here ]------------
[  278.734496] WARNING: CPU: 0 PID: 263 at /root/linux-nfs/net/sunrpc/sched.c:692
rpc_exit_task+0x85/0x90 [sunrpc]()
[  278.736771] Modules linked in: nfsv4(OE) nfs(OE) nfsd(E) bnep bluetooth ip6t_rpfilter ip6t_REJECT

xt_conntrack cfg80211 rfkill ebtable_nat ebtable_broute bridge stp llc ebtable_filter ebtables ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw ip6table_filter ip6_tables iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw btrfs ppdev xfs microcode xor serio_raw libcrc32c pcspkr raid6_pq e1000 parport_pc parport i2c_piix4 i2c_core auth_rpcgss nfs_acl lockd sunrpc(OE) ata_generic pata_acpi [last unloaded: nfsd]

[  278.751462] CPU: 0 PID: 263 Comm: kworker/0:4 Tainted: G           OE 3.16.0-rc2+ #28
[  278.753364] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform,
BIOS 6.00 07/31/2013
[  278.755710] Workqueue: rpciod rpc_async_schedule [sunrpc]
[  278.757112]  0000000000000000 00000000f6173352 ffff880072e5fd30 ffffffff816eacfa
[  278.758811]  0000000000000000 ffff880072e5fd68 ffffffff8108bf3d ffff88005997f180
[  278.760527]  ffff88003ae44830 ffffffffa001a860 ffffffffa001a860 0000000000000000
[  278.762271] Call Trace:
[  278.762802]  [<ffffffff816eacfa>] dump_stack+0x45/0x56
[  278.763906]  [<ffffffff8108bf3d>] warn_slowpath_common+0x7d/0xa0
[  278.765419]  [<ffffffffa001a860>] ? rpc_destroy_wait_queue+0x20/0x20 [sunrpc]
[  278.767243]  [<ffffffffa001a860>] ? rpc_destroy_wait_queue+0x20/0x20 [sunrpc]
[  278.768758]  [<ffffffff8108c06a>] warn_slowpath_null+0x1a/0x20
[  278.770080]  [<ffffffffa001a8e5>] rpc_exit_task+0x85/0x90 [sunrpc]
[  278.771439]  [<ffffffffa001b204>] __rpc_execute+0x94/0x420 [sunrpc]
[  278.772829]  [<ffffffffa001b5b6>] rpc_async_schedule+0x26/0x30 [sunrpc]
[  278.774276]  [<ffffffff810a7f95>] process_one_work+0x175/0x430
[  278.775573]  [<ffffffff810a866d>] worker_thread+0x11d/0x530
[  278.776824]  [<ffffffff810a8550>] ? rescuer_thread+0x300/0x300
[  278.778069]  [<ffffffff810aee18>] kthread+0xd8/0xf0
[  278.779114]  [<ffffffff810aed40>] ? insert_kthread_work+0x40/0x40
[  278.780448]  [<ffffffff816f22bc>] ret_from_fork+0x7c/0xb0
[  278.781621]  [<ffffffff810aed40>] ? insert_kthread_work+0x40/0x40
[  278.782972] ---[ end trace 3350394592832e42 ]---

task1 (lock/unlock):
--> call_decode

    --> rpc_exit_task (-10008)
      --> nfs4_release_lockowner_done
        --> rpc_restart_call_prepare
            task->tk_action = call_start;
task2 (umount):
      --> rpc_shutdown_client
        --> rpc_killall_tasks
            rovr->tk_flags |= RPC_TASK_KILLED; (set task1 to KILLED)
task1:
    --> rpc_exit_task
        WARN_ON(RPC_ASSASSINATED(task));

Signed-off-by Kinglong Mee <[email protected]>

---
 net/sunrpc/sched.c | 9 ++++++++-
 1 file changed, 8 insertions(+), 1 deletion(-)

net/sunrpc/sched.c +8 -1

index 337ca85..562db0a 100644
@@ -689,7 +689,14 @@ void rpc_exit_task(struct rpc_task *task)
 	if (task->tk_ops->rpc_call_done != NULL) {
 		task->tk_ops->rpc_call_done(task, task->tk_calldata);
 		if (task->tk_action != NULL) {
-			WARN_ON(RPC_ASSASSINATED(task));
+			/*
+			 * A known case here is,
+			 * The RPC_TASK_KILLED is set in rpc_killall_tasks by
+			 * another process.
+			 */
+			if (RPC_ASSASSINATED(task))
+				printk(KERN_WARNING "RPC: dead task tried to"
+					" walk away.\n");
 			/* Always release the RPC slot and buffer memory */
 			xprt_release(task);
 			rpc_reset_task_statistics(task);

Signature · 1 line

2.4.3

Scott Mayhew

2015-08-17 13:35 UTC #1 lore raw

Quoted 78 lines · Kinglong Mee

When testing nfs4.0 lock, I get WARN_ON message as below,

[  278.733391] ------------[ cut here ]------------
[  278.734496] WARNING: CPU: 0 PID: 263 at /root/linux-nfs/net/sunrpc/sched.c:692
rpc_exit_task+0x85/0x90 [sunrpc]()
[  278.736771] Modules linked in: nfsv4(OE) nfs(OE) nfsd(E) bnep bluetooth ip6t_rpfilter ip6t_REJECT

[  278.751462] CPU: 0 PID: 263 Comm: kworker/0:4 Tainted: G           OE 3.16.0-rc2+ #28
[  278.753364] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform,
BIOS 6.00 07/31/2013
[  278.755710] Workqueue: rpciod rpc_async_schedule [sunrpc]
[  278.757112]  0000000000000000 00000000f6173352 ffff880072e5fd30 ffffffff816eacfa
[  278.758811]  0000000000000000 ffff880072e5fd68 ffffffff8108bf3d ffff88005997f180
[  278.760527]  ffff88003ae44830 ffffffffa001a860 ffffffffa001a860 0000000000000000
[  278.762271] Call Trace:
[  278.762802]  [<ffffffff816eacfa>] dump_stack+0x45/0x56
[  278.763906]  [<ffffffff8108bf3d>] warn_slowpath_common+0x7d/0xa0
[  278.765419]  [<ffffffffa001a860>] ? rpc_destroy_wait_queue+0x20/0x20 [sunrpc]
[  278.767243]  [<ffffffffa001a860>] ? rpc_destroy_wait_queue+0x20/0x20 [sunrpc]
[  278.768758]  [<ffffffff8108c06a>] warn_slowpath_null+0x1a/0x20
[  278.770080]  [<ffffffffa001a8e5>] rpc_exit_task+0x85/0x90 [sunrpc]
[  278.771439]  [<ffffffffa001b204>] __rpc_execute+0x94/0x420 [sunrpc]
[  278.772829]  [<ffffffffa001b5b6>] rpc_async_schedule+0x26/0x30 [sunrpc]
[  278.774276]  [<ffffffff810a7f95>] process_one_work+0x175/0x430
[  278.775573]  [<ffffffff810a866d>] worker_thread+0x11d/0x530
[  278.776824]  [<ffffffff810a8550>] ? rescuer_thread+0x300/0x300
[  278.778069]  [<ffffffff810aee18>] kthread+0xd8/0xf0
[  278.779114]  [<ffffffff810aed40>] ? insert_kthread_work+0x40/0x40
[  278.780448]  [<ffffffff816f22bc>] ret_from_fork+0x7c/0xb0
[  278.781621]  [<ffffffff810aed40>] ? insert_kthread_work+0x40/0x40
[  278.782972] ---[ end trace 3350394592832e42 ]---

task1 (lock/unlock):
--> call_decode

    --> rpc_exit_task (-10008)
      --> nfs4_release_lockowner_done
        --> rpc_restart_call_prepare
            task->tk_action = call_start;
task2 (umount):
      --> rpc_shutdown_client
        --> rpc_killall_tasks
            rovr->tk_flags |= RPC_TASK_KILLED; (set task1 to KILLED)
task1:
    --> rpc_exit_task
        WARN_ON(RPC_ASSASSINATED(task));

Signed-off-by Kinglong Mee <[email protected]>

---
 net/sunrpc/sched.c | 9 ++++++++-
 1 file changed, 8 insertions(+), 1 deletion(-)

net/sunrpc/sched.c +8 -1

index 337ca85..562db0a 100644
@@ -689,7 +689,14 @@ void rpc_exit_task(struct rpc_task *task)
 	if (task->tk_ops->rpc_call_done != NULL) {
 		task->tk_ops->rpc_call_done(task, task->tk_calldata);
 		if (task->tk_action != NULL) {
-			WARN_ON(RPC_ASSASSINATED(task));
+			/*
+			 * A known case here is,
+			 * The RPC_TASK_KILLED is set in rpc_killall_tasks by
+			 * another process.
+			 */
+			if (RPC_ASSASSINATED(task))
+				printk(KERN_WARNING "RPC: dead task tried to"
+					" walk away.\n");
 			/* Always release the RPC slot and buffer memory */
 			xprt_release(task);
 			rpc_reset_task_statistics(task);

Signature · 1 line

2.4.3

If this is going to be changed anyway, could we maybe have some more useful debugging information added to the message? Something like:

        printk(KERN_WARNING "RPC: %s to %s was killed\n", 
                task->tk_msg.rpc_proc->p_name, 
                rpc_peeraddr2str(task->tk_client, RPC_DISPLAY_ADDR));

I recently had a case where this warning was popping several times per minute. The machine was both a client and a server... it turns out that it was actually CB_NULLs that were causing the warning, and the trigger for that was that several clients had the same value for the clientaddr mount option.

Having some more useful info from the warning message would have saved some time there.

-Scott

Kinglong Mee

author

2015-08-18 06:25 UTC #2 lore raw

Quoted 88 lines · Scott Mayhew

Quoted 78 lines · Kinglong Mee

When testing nfs4.0 lock, I get WARN_ON message as below,

[  278.733391] ------------[ cut here ]------------
[  278.734496] WARNING: CPU: 0 PID: 263 at /root/linux-nfs/net/sunrpc/sched.c:692
rpc_exit_task+0x85/0x90 [sunrpc]()
[  278.736771] Modules linked in: nfsv4(OE) nfs(OE) nfsd(E) bnep bluetooth ip6t_rpfilter ip6t_REJECT

[  278.751462] CPU: 0 PID: 263 Comm: kworker/0:4 Tainted: G           OE 3.16.0-rc2+ #28
[  278.753364] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform,
BIOS 6.00 07/31/2013
[  278.755710] Workqueue: rpciod rpc_async_schedule [sunrpc]
[  278.757112]  0000000000000000 00000000f6173352 ffff880072e5fd30 ffffffff816eacfa
[  278.758811]  0000000000000000 ffff880072e5fd68 ffffffff8108bf3d ffff88005997f180
[  278.760527]  ffff88003ae44830 ffffffffa001a860 ffffffffa001a860 0000000000000000
[  278.762271] Call Trace:
[  278.762802]  [<ffffffff816eacfa>] dump_stack+0x45/0x56
[  278.763906]  [<ffffffff8108bf3d>] warn_slowpath_common+0x7d/0xa0
[  278.765419]  [<ffffffffa001a860>] ? rpc_destroy_wait_queue+0x20/0x20 [sunrpc]
[  278.767243]  [<ffffffffa001a860>] ? rpc_destroy_wait_queue+0x20/0x20 [sunrpc]
[  278.768758]  [<ffffffff8108c06a>] warn_slowpath_null+0x1a/0x20
[  278.770080]  [<ffffffffa001a8e5>] rpc_exit_task+0x85/0x90 [sunrpc]
[  278.771439]  [<ffffffffa001b204>] __rpc_execute+0x94/0x420 [sunrpc]
[  278.772829]  [<ffffffffa001b5b6>] rpc_async_schedule+0x26/0x30 [sunrpc]
[  278.774276]  [<ffffffff810a7f95>] process_one_work+0x175/0x430
[  278.775573]  [<ffffffff810a866d>] worker_thread+0x11d/0x530
[  278.776824]  [<ffffffff810a8550>] ? rescuer_thread+0x300/0x300
[  278.778069]  [<ffffffff810aee18>] kthread+0xd8/0xf0
[  278.779114]  [<ffffffff810aed40>] ? insert_kthread_work+0x40/0x40
[  278.780448]  [<ffffffff816f22bc>] ret_from_fork+0x7c/0xb0
[  278.781621]  [<ffffffff810aed40>] ? insert_kthread_work+0x40/0x40
[  278.782972] ---[ end trace 3350394592832e42 ]---

task1 (lock/unlock):
--> call_decode

    --> rpc_exit_task (-10008)
      --> nfs4_release_lockowner_done
        --> rpc_restart_call_prepare
            task->tk_action = call_start;
task2 (umount):
      --> rpc_shutdown_client
        --> rpc_killall_tasks
            rovr->tk_flags |= RPC_TASK_KILLED; (set task1 to KILLED)
task1:
    --> rpc_exit_task
        WARN_ON(RPC_ASSASSINATED(task));

Signed-off-by Kinglong Mee <[email protected]>

---
 net/sunrpc/sched.c | 9 ++++++++-
 1 file changed, 8 insertions(+), 1 deletion(-)

net/sunrpc/sched.c +8 -1

index 337ca85..562db0a 100644
@@ -689,7 +689,14 @@ void rpc_exit_task(struct rpc_task *task)
 	if (task->tk_ops->rpc_call_done != NULL) {
 		task->tk_ops->rpc_call_done(task, task->tk_calldata);
 		if (task->tk_action != NULL) {
-			WARN_ON(RPC_ASSASSINATED(task));
+			/*
+			 * A known case here is,
+			 * The RPC_TASK_KILLED is set in rpc_killall_tasks by
+			 * another process.
+			 */
+			if (RPC_ASSASSINATED(task))
+				printk(KERN_WARNING "RPC: dead task tried to"
+					" walk away.\n");
 			/* Always release the RPC slot and buffer memory */
 			xprt_release(task);
 			rpc_reset_task_statistics(task);

Signature · 1 line

2.4.3

If this is going to be changed anyway, could we maybe have some more useful debugging information added to the message? Something like:

        printk(KERN_WARNING "RPC: %s to %s was killed\n", 
                task->tk_msg.rpc_proc->p_name, 
                rpc_peeraddr2str(task->tk_client, RPC_DISPLAY_ADDR));

Quoted 8 lines

I recently had a case where this warning was popping several times per minute. The machine was both a client and a server... it turns out that it was actually CB_NULLs that were causing the warning, and the trigger for that was that several clients had the same value for the clientaddr mount option.
Having some more useful info from the warning message would have saved some time there.

If it's harmless of this case, remove the WARN_ON directly maybe better. What's your opinion, Trond?

thanks,
Kinglong Mee