From: Eric Dumazet <hidden> Date: 2012-03-31 20:59:17
On Sat, 2012-03-31 at 19:51 +0200, Sasha Levin wrote:
Hi all,
It appears that a hang may occur when destroying an ipv6 tunnel, which
I've reproduced several times in a KVM vm.
The pattern in the stack dump below is consistent with unregistering a
kobject when holding multiple locks. Unregistering a kobject usually
leads to an exit back to userspace with call_usermodehelper_exec().
Yes but this userspace call is done asynchronously and we dont have to
wait its done.
The userspace code may access sysfs files which in turn will require
locking within the kernel, leading to a deadlock since those locks are
already held by kernel.
Something is wrong here, call_usermodehelper_exec ( ... UMH_WAIT_EXEC)
should not block forever. Its not like UMH_WAIT_PROC
Cc Oleg Nesterov [off-list ref]
On Sat, 2012-03-31 at 19:51 +0200, Sasha Levin wrote:
quoted
Hi all,
It appears that a hang may occur when destroying an ipv6 tunnel, which
I've reproduced several times in a KVM vm.
kernel version?
quoted
[ 1561.564172] INFO: task kworker/u:2:3140 blocked for more than 120 seconds.
And nobody else?
It would be nice to know what sysrq-t says, in particular the trace
of khelper thread is interesting.
Something is wrong here, call_usermodehelper_exec ( ... UMH_WAIT_EXEC)
should not block forever.
Yes, unless it triggers another request_module()...
Tetsuo, could you please take a look? Unlikely, but may be this
is fixed by your kmod-avoid-deadlock-by-recursive-kmod-call.patch
in -mm ?
Oleg.
On Sat, Mar 31, 2012 at 11:34 PM, Oleg Nesterov [off-list ref] wrote:
On 03/31, Eric Dumazet wrote:
quoted
On Sat, 2012-03-31 at 19:51 +0200, Sasha Levin wrote:
quoted
Hi all,
It appears that a hang may occur when destroying an ipv6 tunnel, which
I've reproduced several times in a KVM vm.
kernel version?
latest linux-next
quoted
quoted
[ 1561.564172] INFO: task kworker/u:2:3140 blocked for more than 120 seconds.
And nobody else?
Some more messages follow a bit later which get stuck in vfs related code.
It would be nice to know what sysrq-t says, in particular the trace
of khelper thread is interesting.
Sure, I'll get one when it happens again.
quoted
Something is wrong here, call_usermodehelper_exec ( ... UMH_WAIT_EXEC)
should not block forever.
Yes, unless it triggers another request_module()...
Tetsuo, could you please take a look? Unlikely, but may be this
is fixed by your kmod-avoid-deadlock-by-recursive-kmod-call.patch
in -mm ?
Oleg.
While it seems that 9p is the culprit, I have to point out that this
bug is easily reproducible, and it happens each time due to a
call_usermode_helper() call. Other than that 9p behaves perfectly and
I'd assume that I'd be seeing other things break besides
call_usermode_helper() related ones.
I think one of below two patches can catch the bug if this is a usermodehelper
related bug. Please try.
----- Patch 1 -----
@@ -571,7 +571,7 @@ int call_usermodehelper_exec(struct subprocess_info *sub_info, int wait)*flag,forkhelperthreadisalreadywaitingforthethreadat*wait_for_completion()indo_fork().*/-if(wait!=UMH_NO_WAIT&¤t==kmod_thread_locker){+if(WARN_ON(wait!=UMH_NO_WAIT&¤t==kmod_thread_locker)){retval=-EBUSY;gotoout;}-----Patch2-----
@@ -48,10 +48,10 @@ static inline int request_module_nowait(const char *name, ...) { return -ENOSYS;structcred;structfile;-#define UMH_NO_WAIT 0 /* don't wait at all */-#define UMH_WAIT_EXEC 1 /* wait for the exec, but not the process */-#define UMH_WAIT_PROC 2 /* wait for the process to complete */-#define UMH_KILLABLE 4 /* wait for EXEC/PROC killable */+#define UMH_NO_WAIT 0x10 /* don't wait at all */+#define UMH_WAIT_EXEC 0x11 /* wait for the exec, but not the process */+#define UMH_WAIT_PROC 0x12 /* wait for the process to complete */+#define UMH_KILLABLE 0x04 /* wait for EXEC/PROC killable */structsubprocess_info{structwork_structwork;
@@ -483,6 +483,18 @@ int call_usermodehelper_exec(struct subprocess_info *sub_info, int wait)DECLARE_COMPLETION_ONSTACK(done);intretval=0;+if(unlikely(wait==-1||wait==0||wait==1)){+WARN(1,"Requesting for usermode helper with hardcoded wait "+"flag. Change to use UMH_* symbols and recompile, or "+"this request will fail on Linux 3.4.\n");+if(wait==-1)+wait=UMH_NO_WAIT;+elseif(wait==0)+wait=UMH_WAIT_EXEC;+else+wait=UMH_WAIT_PROC;+}+helper_lock();if(sub_info->path[0]=='\0')gotoout;
From: Eric Dumazet <hidden> Date: 2012-04-01 05:07:56
On Sun, 2012-04-01 at 01:26 +0200, Sasha Levin wrote:
On Sat, Mar 31, 2012 at 11:43 PM, Sasha Levin [off-list ref] wrote:
quoted
On Sat, Mar 31, 2012 at 11:34 PM, Oleg Nesterov [off-list ref] wrote:
quoted
On 03/31, Eric Dumazet wrote:
quoted
On Sat, 2012-03-31 at 19:51 +0200, Sasha Levin wrote:
quoted
Hi all,
It appears that a hang may occur when destroying an ipv6 tunnel, which
I've reproduced several times in a KVM vm.
kernel version?
latest linux-next
quoted
quoted
quoted
[ 1561.564172] INFO: task kworker/u:2:3140 blocked for more than 120 seconds.
And nobody else?
Some more messages follow a bit later which get stuck in vfs related code.
quoted
It would be nice to know what sysrq-t says, in particular the trace
of khelper thread is interesting.
Sure, I'll get one when it happens again.
So here's the stack of the usermode thread:
[ 336.614015] kworker/u:2 S ffff880062c13000 5176 4539 3031 0x00000000
[ 336.614015] ffff880062fb38d0 0000000000000082 ffff880062fb3860
0000000000000001
[ 336.614015] ffff880062fb3fd8 00000000001d4580 ffff880062fb2010
00000000001d4580
[ 336.614015] 00000000001d4580 00000000001d4580 ffff880062fb3fd8
00000000001d4580
[ 336.614015] Call Trace:
[ 336.614015] [<ffffffff826a8e54>] schedule+0x24/0x70
[ 336.614015] [<ffffffff825fd66d>] p9_client_rpc+0x13d/0x360
[ 336.614015] [<ffffffff810d7850>] ? wake_up_bit+0x40/0x40
[ 336.614015] [<ffffffff810e3671>] ? get_parent_ip+0x11/0x50
[ 336.614015] [<ffffffff810e399d>] ? sub_preempt_count+0x9d/0xd0
[ 336.614015] [<ffffffff825ff5ff>] p9_client_walk+0x8f/0x220
[ 336.614015] [<ffffffff815a8e3b>] v9fs_vfs_lookup+0xab/0x1c0
[ 336.614015] [<ffffffff811ee0c0>] d_alloc_and_lookup+0x40/0x80
[ 336.614015] [<ffffffff811fdea0>] ? d_lookup+0x30/0x50
[ 336.614015] [<ffffffff811f0aea>] do_lookup+0x28a/0x3b0
[ 336.614015] [<ffffffff817c9117>] ? security_inode_permission+0x17/0x20
[ 336.614015] [<ffffffff811f1c07>] link_path_walk+0x167/0x420
[ 336.614015] [<ffffffff811ee630>] ? generic_readlink+0xb0/0xb0
[ 336.614015] [<ffffffff81896d88>] ? __raw_spin_lock_init+0x38/0x70
[ 336.614015] [<ffffffff811f24da>] path_openat+0xba/0x500
[ 336.614015] [<ffffffff81057253>] ? sched_clock+0x13/0x20
[ 336.614015] [<ffffffff810ed805>] ? sched_clock_local+0x25/0x90
[ 336.614015] [<ffffffff810ed940>] ? sched_clock_cpu+0xd0/0x120
[ 336.614015] [<ffffffff811f2a34>] do_filp_open+0x44/0xa0
[ 336.614015] [<ffffffff81119acd>] ? __lock_release+0x8d/0x1d0
[ 336.614015] [<ffffffff810e3671>] ? get_parent_ip+0x11/0x50
[ 336.614015] [<ffffffff810e399d>] ? sub_preempt_count+0x9d/0xd0
[ 336.614015] [<ffffffff826aa7f0>] ? _raw_spin_unlock+0x30/0x60
[ 336.614015] [<ffffffff811ea74d>] open_exec+0x2d/0xf0
[ 336.614015] [<ffffffff811eb888>] do_execve_common+0x128/0x320
[ 336.614015] [<ffffffff811ebb05>] do_execve+0x35/0x40
[ 336.614015] [<ffffffff810589e5>] sys_execve+0x45/0x70
[ 336.614015] [<ffffffff826acc28>] kernel_execve+0x68/0xd0
[ 336.614015] [<ffffffff810cd6a6>] ? ____call_usermodehelper+0xf6/0x130
[ 336.614015] [<ffffffff810cd6f9>] call_helper+0x19/0x20
[ 336.614015] [<ffffffff826acbb4>] kernel_thread_helper+0x4/0x10
[ 336.614015] [<ffffffff810e3f80>] ? finish_task_switch+0x80/0x110
[ 336.614015] [<ffffffff826aaeb4>] ? retint_restore_args+0x13/0x13
[ 336.614015] [<ffffffff810cd6e0>] ? ____call_usermodehelper+0x130/0x130
[ 336.614015] [<ffffffff826acbb0>] ? gs_change+0x13/0x13
While it seems that 9p is the culprit, I have to point out that this
bug is easily reproducible, and it happens each time due to a
call_usermode_helper() call. Other than that 9p behaves perfectly and
I'd assume that I'd be seeing other things break besides
call_usermode_helper() related ones.
OK then there is a third process (might be a 9p related one trying to
serve this RPC request) blocking on one of the mutex hold by your first
process (the one invoking call_usermodehelper())
Maybe kobject_uevent_env() should not use UMH_WAIT_EXEC to get a non
blocking guarantee.
It would be nice to know what sysrq-t says, in particular the trace
of khelper thread is interesting.
Sure, I'll get one when it happens again.
So here's the stack of the usermode thread:
Great, thanks, this is even better than khelper's trace,
[ 336.614015] [<ffffffff826a8e54>] schedule+0x24/0x70
[ 336.614015] [<ffffffff825fd66d>] p9_client_rpc+0x13d/0x360
[ 336.614015] [<ffffffff810d7850>] ? wake_up_bit+0x40/0x40
[ 336.614015] [<ffffffff810e3671>] ? get_parent_ip+0x11/0x50
[ 336.614015] [<ffffffff810e399d>] ? sub_preempt_count+0x9d/0xd0
[ 336.614015] [<ffffffff825ff5ff>] p9_client_walk+0x8f/0x220
[ 336.614015] [<ffffffff815a8e3b>] v9fs_vfs_lookup+0xab/0x1c0
[ 336.614015] [<ffffffff811ee0c0>] d_alloc_and_lookup+0x40/0x80
[ 336.614015] [<ffffffff811fdea0>] ? d_lookup+0x30/0x50
[ 336.614015] [<ffffffff811f0aea>] do_lookup+0x28a/0x3b0
[ 336.614015] [<ffffffff817c9117>] ? security_inode_permission+0x17/0x20
[ 336.614015] [<ffffffff811f1c07>] link_path_walk+0x167/0x420
[ 336.614015] [<ffffffff811ee630>] ? generic_readlink+0xb0/0xb0
[ 336.614015] [<ffffffff81896d88>] ? __raw_spin_lock_init+0x38/0x70
[ 336.614015] [<ffffffff811f24da>] path_openat+0xba/0x500
[ 336.614015] [<ffffffff81057253>] ? sched_clock+0x13/0x20
[ 336.614015] [<ffffffff810ed805>] ? sched_clock_local+0x25/0x90
[ 336.614015] [<ffffffff810ed940>] ? sched_clock_cpu+0xd0/0x120
[ 336.614015] [<ffffffff811f2a34>] do_filp_open+0x44/0xa0
[ 336.614015] [<ffffffff81119acd>] ? __lock_release+0x8d/0x1d0
[ 336.614015] [<ffffffff810e3671>] ? get_parent_ip+0x11/0x50
[ 336.614015] [<ffffffff810e399d>] ? sub_preempt_count+0x9d/0xd0
[ 336.614015] [<ffffffff826aa7f0>] ? _raw_spin_unlock+0x30/0x60
[ 336.614015] [<ffffffff811ea74d>] open_exec+0x2d/0xf0
[ 336.614015] [<ffffffff811eb888>] do_execve_common+0x128/0x320
[ 336.614015] [<ffffffff811ebb05>] do_execve+0x35/0x40
[ 336.614015] [<ffffffff810589e5>] sys_execve+0x45/0x70
[ 336.614015] [<ffffffff826acc28>] kernel_execve+0x68/0xd0
[ 336.614015] [<ffffffff810cd6a6>] ? ____call_usermodehelper+0xf6/0x130
[ 336.614015] [<ffffffff810cd6f9>] call_helper+0x19/0x20
[ 336.614015] [<ffffffff826acbb4>] kernel_thread_helper+0x4/0x10
[ 336.614015] [<ffffffff810e3f80>] ? finish_task_switch+0x80/0x110
[ 336.614015] [<ffffffff826aaeb4>] ? retint_restore_args+0x13/0x13
[ 336.614015] [<ffffffff810cd6e0>] ? ____call_usermodehelper+0x130/0x130
[ 336.614015] [<ffffffff826acbb0>] ? gs_change+0x13/0x13
While it seems that 9p is the culprit, I have to point out that this
bug is easily reproducible, and it happens each time due to a
call_usermode_helper() call. Other than that 9p behaves perfectly and
I'd assume that I'd be seeing other things break besides
call_usermode_helper() related ones.
Of course I do not know what happens, but at least this obviously
explains why UMH_WAIT_EXEC hangs, I think call_usermodehelper_exec()
itself is innocent.
Oleg.
On Sun, Apr 1, 2012 at 5:21 AM, Tetsuo Handa
[off-list ref] wrote:
quoted hunk
Sasha Levin wrote:
quoted
While it seems that 9p is the culprit, I have to point out that this
bug is easily reproducible, and it happens each time due to a
call_usermode_helper() call. Other than that 9p behaves perfectly and
I'd assume that I'd be seeing other things break besides
call_usermode_helper() related ones.
I think one of below two patches can catch the bug if this is a usermodehelper
related bug. Please try.
----- Patch 1 -----
@@ -571,7 +571,7 @@ int call_usermodehelper_exec(struct subprocess_info *sub_info, int wait)
* flag, for khelper thread is already waiting for the thread at
* wait_for_completion() in do_fork().
*/
- if (wait != UMH_NO_WAIT && current == kmod_thread_locker) {
+ if (WARN_ON(wait != UMH_NO_WAIT && current == kmod_thread_locker)) {
retval = -EBUSY;
goto out;
}
----- Patch 2 -----
struct cred;
struct file;
-#define UMH_NO_WAIT 0 /* don't wait at all */
-#define UMH_WAIT_EXEC 1 /* wait for the exec, but not the process */
-#define UMH_WAIT_PROC 2 /* wait for the process to complete */
-#define UMH_KILLABLE 4 /* wait for EXEC/PROC killable */
+#define UMH_NO_WAIT 0x10 /* don't wait at all */
+#define UMH_WAIT_EXEC 0x11 /* wait for the exec, but not the process */
+#define UMH_WAIT_PROC 0x12 /* wait for the process to complete */
+#define UMH_KILLABLE 0x04 /* wait for EXEC/PROC killable */
struct subprocess_info {
struct work_struct work;
@@ -309,7 +309,7 @@ int kobject_uevent_env(struct kobject *kobj, enum
kobject_action action,
goto exit;
retval = call_usermodehelper(argv[0], argv,
- env->envp, UMH_WAIT_EXEC);
+ env->envp, UMH_NO_WAIT);
}
exit:
Not sure if that info helps any, but just in case.
@@ -740,10 +740,18 @@c->status=Disconnected;gotoreterr;}+again:/* Wait for the response */err=wait_event_interruptible(*req->wq,req->status>=REQ_STATUS_RCVD);+if((err==-ERESTARTSYS)&&(c->status==Connected)+&&(type==P9_TFLUSH)){+sigpending=1;+clear_thread_flag(TIF_SIGPENDING);+gotoagain;+}+
I think this loop is bad with regard to response to SIGKILL.
If wait_event_interruptible() was interrupted by SIGKILL, it will
spin until req->status >= REQ_STATUS_RCVD becomes true.
Rather,
if ((c->status == Connected) && (type == P9_TFLUSH))
err = wait_event_killable(*req->wq,
req->status >= REQ_STATUS_RCVD);
else
err = wait_event_interruptible(*req->wq,
req->status >= REQ_STATUS_RCVD);
would be safer.
Does that work? What prevents p9_client_rpc() from recursing via
p9_client_flush() on receipt of SIGKILL?
quoted
error:
/*
* Fid is not valid even after a failed clunk
+ * If interrupted, retry once then give up and
+ * leak fid until umount.
*/
- p9_fid_destroy(fid);
+ if (err == -ERESTARTSYS) {
+ if (retries++ == 0)
+ goto again;
I think it is possible that the process is interrupted again upon retrying.
I suspect the handling of err == -ERESTARTSYS case when retries != 0.
It is returning without calling p9_fid_destroy(), which will be
unexpected behaviour for the various callers.
Yes but in the unlikely event that this happens, the effect is a small
memory leak for the duration of the mount. On the other hand if the
fid is destroyed without successfully informing the server, then
subsequent operations that involve new file references will fail
when that fid number is reused, and the mount becomes unusable.
Maybe commit a314f274 "net/9p: don't allow Tflush to be interrupted" or nearby.
By the way, have you already tried 3.4-rc1?
In my environment, there is no difference between linux-next and 3.4-rc1.
# diff -ur linux-3.4.0-rc1/net/9p/ linux-next/net/9p/
# diff -ur linux-3.4.0-rc1/drivers/virtio/ linux-next/drivers/virtio/
# diff -ur linux-3.4.0-rc1/fs/9p/ linux-next/fs/9p/
Good. -512 is -ERESTARTSYS, and this hang occurs after -ERESTARTSYS is
returned. It indicates that c->trans_mod->request() is interrupted by signal.
Since c->trans_mod->request is pointing at p9_virtio_request, the location
returning that error would be
@@ -740,10 +740,18 @@c->status=Disconnected;gotoreterr;}+again:/* Wait for the response */err=wait_event_interruptible(*req->wq,req->status>=REQ_STATUS_RCVD);+if((err==-ERESTARTSYS)&&(c->status==Connected)+&&(type==P9_TFLUSH)){+sigpending=1;+clear_thread_flag(TIF_SIGPENDING);+gotoagain;+}+
I think this loop is bad with regard to response to SIGKILL.
If wait_event_interruptible() was interrupted by SIGKILL, it will
spin until req->status >= REQ_STATUS_RCVD becomes true.
Rather,
if ((c->status == Connected) && (type == P9_TFLUSH))
err = wait_event_killable(*req->wq,
req->status >= REQ_STATUS_RCVD);
else
err = wait_event_interruptible(*req->wq,
req->status >= REQ_STATUS_RCVD);
would be safer.
error:
/*
* Fid is not valid even after a failed clunk
+ * If interrupted, retry once then give up and
+ * leak fid until umount.
*/
- p9_fid_destroy(fid);
+ if (err == -ERESTARTSYS) {
+ if (retries++ == 0)
+ goto again;
I think it is possible that the process is interrupted again upon retrying.
I suspect the handling of err == -ERESTARTSYS case when retries != 0.
It is returning without calling p9_fid_destroy(), which will be
unexpected behaviour for the various callers.
I think this loop is bad with regard to response to SIGKILL.
If wait_event_interruptible() was interrupted by SIGKILL, it will
spin until req->status >= REQ_STATUS_RCVD becomes true.
Rather,
if ((c->status == Connected) && (type == P9_TFLUSH))
err = wait_event_killable(*req->wq,
req->status >= REQ_STATUS_RCVD);
else
err = wait_event_interruptible(*req->wq,
req->status >= REQ_STATUS_RCVD);
would be safer.
Does that work? What prevents p9_client_rpc() from recursing via
p9_client_flush() on receipt of SIGKILL?
Sorry, I'm not a 9p user and I can't test whether that works or not.
But at least, continuing the loop even after SIGKILL is not good.
If you have to wait for req->status >= REQ_STATUS_RCVD becomes true, can you
use a kernel thread that waits req->status >= REQ_STATUS_RCVD to become true
and delegate the job of notifying the server from a userspace task to the
kernel thread?
Yes but in the unlikely event that this happens, the effect is a small
memory leak for the duration of the mount. On the other hand if the
fid is destroyed without successfully informing the server, then
subsequent operations that involve new file references will fail
when that fid number is reused, and the mount becomes unusable.
I don't know whether Sasha's problem is caused by this patch or not.
But p9_client_clunk() is called from many functions in fs/9p/ directory.
They are assuming that p9_client_clunk() will call p9_fid_destroy() but
this patch is breaking that assumption. I think this is the cause of hang which
Sasha is experiencing because Sasha's trace shows that call_usermodehelper() is
blocked by functions in fs/9p/ directory. Seems inconsistency state problem.
Yes but in the unlikely event that this happens, the effect is a small
memory leak for the duration of the mount. On the other hand if the
fid is destroyed without successfully informing the server, then
subsequent operations that involve new file references will fail
when that fid number is reused, and the mount becomes unusable.
I don't know whether Sasha's problem is caused by this patch or not.
But p9_client_clunk() is called from many functions in fs/9p/ directory.
They are assuming that p9_client_clunk() will call p9_fid_destroy() but
this patch is breaking that assumption. I think this is the cause of hang which
Sasha is experiencing because Sasha's trace shows that call_usermodehelper() is
blocked by functions in fs/9p/ directory. Seems inconsistency state problem.
I'd be happy to try out any other patches or help debugging this issue.
Which behavior did this patch fix exactly? can I just revert it and
try running without it?