Netpoll triggers soft lockup

Hi,

While testing a driver against kernel 3.9-rc6 I ran into a soft lockup triggered by sending lots of kernel messages to a remote system via netconsole. This behavior was probably introduced by commit ca99ca14c ("netpoll: protect napi_poll and poll_controller during dev_[open|close]"). That commit introduced a mutex in netpoll_poll_dev(), which can be called from interrupt context. Is there anyone who can tell me whether this is a bug in commit ca99ca14c or in netconsole ?

Bart, this patch should fix your problem. Could you please test it and confirm?

Bart Van Assche recently reported a warning to me:

<IRQ>  [<ffffffff8103d79f>] warn_slowpath_common+0x7f/0xc0
 [<ffffffff8103d7fa>] warn_slowpath_null+0x1a/0x20
 [<ffffffff814761dd>] mutex_trylock+0x16d/0x180
 [<ffffffff813968c9>] netpoll_poll_dev+0x49/0xc30
 [<ffffffff8136a2d2>] ? __alloc_skb+0x82/0x2a0
 [<ffffffff81397715>] netpoll_send_skb_on_dev+0x265/0x410
 [<ffffffff81397c5a>] netpoll_send_udp+0x28a/0x3a0
 [<ffffffffa0541843>] ? write_msg+0x53/0x110 [netconsole]
 [<ffffffffa05418bf>] write_msg+0xcf/0x110 [netconsole]
 [<ffffffff8103eba1>] call_console_drivers.constprop.17+0xa1/0x1c0
 [<ffffffff8103fb76>] console_unlock+0x2d6/0x450
 [<ffffffff8104011e>] vprintk_emit+0x1ee/0x510
 [<ffffffff8146f9f6>] printk+0x4d/0x4f
 [<ffffffffa0004f1d>] scsi_print_command+0x7d/0xe0 [scsi_mod]

This resulted from my commit ca99ca14c which introduced a mutex_trylock operation in a path that could execute in interrupt context. When mutex debugging is enabled, the above warns the user when we are in fact exectuting in interrupt context.

I think this is a false positive however. The check is intended to catch users who might be issuing sleeping calls in irq context, but the use of mutex_trylock here is guaranteed not to sleep.

Quoted 20 lines · On Thursday 11 April 2013 11:18:06 Neil Horman wrote:

Bart, this patch should fix your problem. Could you please test it and confirm?

Bart Van Assche recently reported a warning to me:

<IRQ>  [<ffffffff8103d79f>] warn_slowpath_common+0x7f/0xc0
 [<ffffffff8103d7fa>] warn_slowpath_null+0x1a/0x20
 [<ffffffff814761dd>] mutex_trylock+0x16d/0x180
 [<ffffffff813968c9>] netpoll_poll_dev+0x49/0xc30
 [<ffffffff8136a2d2>] ? __alloc_skb+0x82/0x2a0
 [<ffffffff81397715>] netpoll_send_skb_on_dev+0x265/0x410
 [<ffffffff81397c5a>] netpoll_send_udp+0x28a/0x3a0
 [<ffffffffa0541843>] ? write_msg+0x53/0x110 [netconsole]
 [<ffffffffa05418bf>] write_msg+0xcf/0x110 [netconsole]
 [<ffffffff8103eba1>] call_console_drivers.constprop.17+0xa1/0x1c0
 [<ffffffff8103fb76>] console_unlock+0x2d6/0x450
 [<ffffffff8104011e>] vprintk_emit+0x1ee/0x510
 [<ffffffff8146f9f6>] printk+0x4d/0x4f
 [<ffffffffa0004f1d>] scsi_print_command+0x7d/0xe0 [scsi_mod]

Quoted 8 lines

This resulted from my commit ca99ca14c which introduced a mutex_trylock operation in a path that could execute in interrupt context. When mutex debugging is enabled, the above warns the user when we are in fact exectuting in interrupt context.

I think this is a false positive however. The check is intended to catch users who might be issuing sleeping calls in irq context, but the use of mutex_trylock here is guaranteed not to sleep.

Even if he does not sleep, may we still hit a deadlock like the following:

netpoll_rx_disable() calls mutex_lock(), who ends up in __mutex_lock_common, calling spin_lock_mutex().

Immediatly after that, on the same CPU, the interrupt comes and netpoll_poll_dev calls mutex_trylock and ends up also calling spin_lock_mutex(). Now, it seems to me that we are deadlocked - the interrupt is spinning on the lock, because netpoll_rx_disable() already took it.

Or maybe I am missing something?

Cheers,
Christoph

Signature · 4 lines

IP Networking Lab --- http://inl.info.ucl.ac.be
MultiPath TCP in the Linux Kernel --- http://multipath-tcp.org
UCLouvain
--

I dont believe the deadlock you describe can happen. The spin_lock_mutex operation disables irqs on the local cpu with local_irq_save, so we won't loose the cpu while we're holding the spinlock. Likewise we don't restore the irq flags until after we release said lock. Once we have the mutex, if we're preempted by another path that goes through the netpoll_poll_dev path, then we hit the trylock api call. The spinlock is either released or held on another cpu (read: no deadlock), and if the mutex is held, then the trylock simply fails.

Bart, this patch should fix your problem. Could you please test it and confirm?

Bart Van Assche recently reported a warning to me:

<IRQ>  [<ffffffff8103d79f>] warn_slowpath_common+0x7f/0xc0
 [<ffffffff8103d7fa>] warn_slowpath_null+0x1a/0x20
 [<ffffffff814761dd>] mutex_trylock+0x16d/0x180
 [<ffffffff813968c9>] netpoll_poll_dev+0x49/0xc30
 [<ffffffff8136a2d2>] ? __alloc_skb+0x82/0x2a0
 [<ffffffff81397715>] netpoll_send_skb_on_dev+0x265/0x410
 [<ffffffff81397c5a>] netpoll_send_udp+0x28a/0x3a0
 [<ffffffffa0541843>] ? write_msg+0x53/0x110 [netconsole]
 [<ffffffffa05418bf>] write_msg+0xcf/0x110 [netconsole]
 [<ffffffff8103eba1>] call_console_drivers.constprop.17+0xa1/0x1c0
 [<ffffffff8103fb76>] console_unlock+0x2d6/0x450
 [<ffffffff8104011e>] vprintk_emit+0x1ee/0x510
 [<ffffffff8146f9f6>] printk+0x4d/0x4f
 [<ffffffffa0004f1d>] scsi_print_command+0x7d/0xe0 [scsi_mod]

This resulted from my commit ca99ca14c which introduced a mutex_trylock operation in a path that could execute in interrupt context. When mutex debugging is enabled, the above warns the user when we are in fact exectuting in interrupt context.

I think this is a false positive however. The check is intended to catch users who might be issuing sleeping calls in irq context, but the use of mutex_trylock here is guaranteed not to sleep.

We could fix this by replacing the DEBUG_LOCK_WARN_ON check in spin_lock_mutex with a __might_sleep call in the appropriate parent mutex operations, but for the sake of effiency (which It seems is why the check was put in the spin lock code only when debug is enabled), lets split the spin_lock_mutex call into two components, where the outer component does the debug checking. Then mutex_trylock can just call the inner part as its callable from irq context safely.

Signed-off-by Neil Horman <[email protected]>

Reported-by Bart Van Assche <[email protected]>

CC Bart Van Assche <[email protected]>

CC David Miller <[email protected]>

CC [email protected]

Quoted 36 lines · Neil Horman

Bart, this patch should fix your problem. Could you please test it and confirm?

Bart Van Assche recently reported a warning to me:

<IRQ>  [<ffffffff8103d79f>] warn_slowpath_common+0x7f/0xc0
 [<ffffffff8103d7fa>] warn_slowpath_null+0x1a/0x20
 [<ffffffff814761dd>] mutex_trylock+0x16d/0x180
 [<ffffffff813968c9>] netpoll_poll_dev+0x49/0xc30
 [<ffffffff8136a2d2>] ? __alloc_skb+0x82/0x2a0
 [<ffffffff81397715>] netpoll_send_skb_on_dev+0x265/0x410
 [<ffffffff81397c5a>] netpoll_send_udp+0x28a/0x3a0
 [<ffffffffa0541843>] ? write_msg+0x53/0x110 [netconsole]
 [<ffffffffa05418bf>] write_msg+0xcf/0x110 [netconsole]
 [<ffffffff8103eba1>] call_console_drivers.constprop.17+0xa1/0x1c0
 [<ffffffff8103fb76>] console_unlock+0x2d6/0x450
 [<ffffffff8104011e>] vprintk_emit+0x1ee/0x510
 [<ffffffff8146f9f6>] printk+0x4d/0x4f
 [<ffffffffa0004f1d>] scsi_print_command+0x7d/0xe0 [scsi_mod]

This resulted from my commit ca99ca14c which introduced a mutex_trylock operation in a path that could execute in interrupt context. When mutex debugging is enabled, the above warns the user when we are in fact exectuting in interrupt context.

I think this is a false positive however. The check is intended to catch users who might be issuing sleeping calls in irq context, but the use of mutex_trylock here is guaranteed not to sleep.

We could fix this by replacing the DEBUG_LOCK_WARN_ON check in spin_lock_mutex with a __might_sleep call in the appropriate parent mutex operations, but for the sake of effiency (which It seems is why the check was put in the spin lock code only when debug is enabled), lets split the spin_lock_mutex call into two components, where the outer component does the debug checking. Then mutex_trylock can just call the inner part as its callable from irq context safely.

Quoted 5 lines

Signed-off-by Neil Horman <[email protected]>

Reported-by Bart Van Assche <[email protected]>

CC Bart Van Assche <[email protected]>

CC David Miller <[email protected]>

CC [email protected]

Please post your patch to lkml ?

Thanks !

Bart, this patch should fix your problem. Could you please test it and confirm?

Quoted 1 line · Neil Horman

Bart, this patch should fix your problem. Could you please test it and confirm?

The fails to build on my setup after having applied that patch:

kernel/mutex.c: In function ‘__mutex_trylock_slowpath’:
kernel/mutex.c:446:2: error: implicit declaration of function ‘spin_unlock_mutex_raw’ [-Werror=implicit-function-declaration]

Bart.

Quoted 1 line · Neil Horman

Bart, this patch should fix your problem. Could you please test it and confirm?

The fails to build on my setup after having applied that patch:

kernel/mutex.c: In function ‘__mutex_trylock_slowpath’:
kernel/mutex.c:446:2: error: implicit declaration of function ‘spin_unlock_mutex_raw’ [-Werror=implicit-function-declaration]

Bart.

This resulted from my commit ca99ca14c which introduced a mutex_trylock operation in a path that could execute in interrupt context. When mutex debugging is enabled, the above warns the user when we are in fact exectuting in interrupt context.

I think this is a false positive however. The check is intended to catch users who might be issuing sleeping calls in irq context, but the use of mutex_trylock here is guaranteed not to sleep.

We could fix this by replacing the DEBUG_LOCK_WARN_ON check in spin_lock_mutex with a __might_sleep call in the appropriate parent mutex operations, but for the sake of effiency (which It seems is why the check was put in the spin lock code only when debug is enabled), lets split the spin_lock_mutex call into two components, where the outer component does the debug checking. Then mutex_trylock can just call the inner part as its callable from irq context safely.

Quoted 9 lines · Neil Horman

This resulted from my commit ca99ca14c which introduced a mutex_trylock operation in a path that could execute in interrupt context. When mutex debugging is enabled, the above warns the user when we are in fact exectuting in interrupt context.

I think this is a false positive however. The check is intended to catch users who might be issuing sleeping calls in irq context, but the use of mutex_trylock here is guaranteed not to sleep.

Quoted 7 lines

We could fix this by replacing the DEBUG_LOCK_WARN_ON check in spin_lock_mutex with a __might_sleep call in the appropriate parent mutex operations, but for the sake of effiency (which It seems is why the check was put in the spin lock code only when debug is enabled), lets split the spin_lock_mutex call into two components, where the outer component does the debug checking. Then mutex_trylock can just call the inner part as its callable from irq context safely.

Sorry but I'm not yet convinced that it's safe to invoke mutex_trylock() from IRQ context. Please have a look at the implementation of mutex_set_owner(), which is invoked by mutex_trylock(). mutex_set_owner() stores the value of the "current" pointer into lock->owner. The value of "current" does not have a meaning in IRQ context.

Bart.

Quoted 18 lines · Bart Van Assche

Quoted 9 lines · Neil Horman

This resulted from my commit ca99ca14c which introduced a mutex_trylock operation in a path that could execute in interrupt context. When mutex debugging is enabled, the above warns the user when we are in fact exectuting in interrupt context.

I think this is a false positive however. The check is intended to catch users who might be issuing sleeping calls in irq context, but the use of mutex_trylock here is guaranteed not to sleep.

Quoted 7 lines

We could fix this by replacing the DEBUG_LOCK_WARN_ON check in spin_lock_mutex with a __might_sleep call in the appropriate parent mutex operations, but for the sake of effiency (which It seems is why the check was put in the spin lock code only when debug is enabled), lets split the spin_lock_mutex call into two components, where the outer component does the debug checking. Then mutex_trylock can just call the inner part as its callable from irq context safely.

Quoted 6 lines

Sorry but I'm not yet convinced that it's safe to invoke mutex_trylock() from IRQ context. Please have a look at the implementation of mutex_set_owner(), which is invoked by mutex_trylock(). mutex_set_owner() stores the value of the "current" pointer into lock->owner. The value of "current" does not have a meaning in IRQ context.

Thats irrelevant, at least as far as deadlock safety is concerned. current will be set to the process that was running when we were interrupted, but it won't change during the course of the irq handler, which is all that matters. The lock->owner field is used for optimistic spinning. The worst that will happen is, if CONFIG_MUTEX_SPIN_ON_OWNER is configured, another process may wait on this mutex, spinning on the wrong task to release it (see mutex_spin_on_owner). Thats not efficient, but its not deadlock prone, and its not even that inefficient, when you consider that the critical path in the netpoll code is relatively short. And using the trylock here is certainly preferable to the memory corruption that was possible previously.

Quoted 26 lines · Neil Horman

Quoted 18 lines · Bart Van Assche

Quoted 9 lines · Neil Horman

This resulted from my commit ca99ca14c which introduced a mutex_trylock operation in a path that could execute in interrupt context. When mutex debugging is enabled, the above warns the user when we are in fact exectuting in interrupt context.

I think this is a false positive however. The check is intended to catch users who might be issuing sleeping calls in irq context, but the use of mutex_trylock here is guaranteed not to sleep.

Quoted 7 lines

We could fix this by replacing the DEBUG_LOCK_WARN_ON check in spin_lock_mutex with a __might_sleep call in the appropriate parent mutex operations, but for the sake of effiency (which It seems is why the check was put in the spin lock code only when debug is enabled), lets split the spin_lock_mutex call into two components, where the outer component does the debug checking. Then mutex_trylock can just call the inner part as its callable from irq context safely.

Quoted 6 lines

Sorry but I'm not yet convinced that it's safe to invoke mutex_trylock() from IRQ context. Please have a look at the implementation of mutex_set_owner(), which is invoked by mutex_trylock(). mutex_set_owner() stores the value of the "current" pointer into lock->owner. The value of "current" does not have a meaning in IRQ context.

Quoted 10 lines

Thats irrelevant, at least as far as deadlock safety is concerned. current will be set to the process that was running when we were interrupted, but it won't change during the course of the irq handler, which is all that matters. The lock->owner field is used for optimistic spinning. The worst that will happen is, if CONFIG_MUTEX_SPIN_ON_OWNER is configured, another process may wait on this mutex, spinning on the wrong task to release it (see mutex_spin_on_owner). Thats not efficient, but its not deadlock prone, and its not even that inefficient, when you consider that the critical path in the netpoll code is relatively short. And using the trylock here is certainly preferable to the memory corruption that was possible previously.

I think there is another issue with invoking mutex_trylock() and mutex_unlock() from IRQ context: as far as I can see if CONFIG_DEBUG_MUTEXES is disabled __mutex_unlock_common_slowpath() uses spin_lock() to lock mutex.wait_lock and hence invoking mutex_unlock() from both non-IRQ and IRQ context is not safe. Any thoughts about that ?

With v2 of your patch and CONFIG_DEBUG_MUTEXES enabled I get the warning below:

Quoted 7 lines · Bart Van Assche

On 04/12/13 13:32, Neil Horman wrote:
I think there is another issue with invoking mutex_trylock() and mutex_unlock() from IRQ context: as far as I can see if CONFIG_DEBUG_MUTEXES is disabled __mutex_unlock_common_slowpath() uses spin_lock() to lock mutex.wait_lock and hence invoking mutex_unlock() from both non-IRQ and IRQ context is not safe. Any thoughts about that ?

Yeah, its ugly, but in this specific case, its ok. the netpoll code (in netpoll_send_skb disables irq on the local cpu before entering the netpoll code path any further, so whenver we frob this mutex from the local cpu, we're guaranteed not to get pre-empted by an irq.

Quoted 8 lines · Neil Horman

Quoted 7 lines · Bart Van Assche

On 04/12/13 13:32, Neil Horman wrote:
I think there is another issue with invoking mutex_trylock() and mutex_unlock() from IRQ context: as far as I can see if CONFIG_DEBUG_MUTEXES is disabled __mutex_unlock_common_slowpath() uses spin_lock() to lock mutex.wait_lock and hence invoking mutex_unlock() from both non-IRQ and IRQ context is not safe. Any thoughts about that ?

Quoted 4 lines

Yeah, its ugly, but in this specific case, its ok. the netpoll code (in netpoll_send_skb disables irq on the local cpu before entering the netpoll code path any further, so whenver we frob this mutex from the local cpu, we're guaranteed not to get pre-empted by an irq.

As far as I know it is neither allowed nor safe to call netpoll_rx_disable() with IRQs disabled. But that function can lock

the dev_lock mutex. What do you think will happen with CONFIG_DEBUG_MUTEXES=n if an interrupt occurs during the mutex_lock(&ni->dev_lock) call, that mutex_lock() call has already locked the mutex-internal spin lock via spin_lock() and mutex_trylock() is invoked from inside the interrupt ? Can that result in anything else than deadlock and "CPU stuck" messages ?

Quoted 8 lines · Neil Horman

Quoted 7 lines · Bart Van Assche

On 04/12/13 13:32, Neil Horman wrote:
I think there is another issue with invoking mutex_trylock() and mutex_unlock() from IRQ context: as far as I can see if CONFIG_DEBUG_MUTEXES is disabled __mutex_unlock_common_slowpath() uses spin_lock() to lock mutex.wait_lock and hence invoking mutex_unlock() from both non-IRQ and IRQ context is not safe. Any thoughts about that ?

Quoted 4 lines

Yeah, its ugly, but in this specific case, its ok. the netpoll code (in netpoll_send_skb disables irq on the local cpu before entering the netpoll code path any further, so whenver we frob this mutex from the local cpu, we're guaranteed not to get pre-empted by an irq.

As far as I know it is neither allowed nor safe to call netpoll_rx_disable() with IRQs disabled. But that function can lock the dev_lock mutex. What do you think will happen with CONFIG_DEBUG_MUTEXES=n if an interrupt occurs during the mutex_lock(&ni->dev_lock) call, that mutex_lock() call has already locked the mutex-internal spin lock via spin_lock() and mutex_trylock() is invoked from inside the interrupt ? Can that result in anything else than deadlock and "CPU stuck" messages ?

Thanks,

Bart.

Quoted 39 lines · Neil Horman

So I've been doing some reading over the weekend, and as a result I've been developing some concerns about how mutex_trylock works. I'm still convinced its
safe to use with the changes we're discussing here, but all the documentation
regarding mutex_trylock seems to say it simply shouldn't be used in interrupt
context (though it never goes into detail as to why). As near as I can tell,
its because the spin locks that mutexes use are locked without disabling interrupts (the implication being that, as we see in the patch we're looking at
here), you're safe if you disable irqs independently). Ironically, Ingo patched
the mutex debug variants back in 2006 in commit 1fb00c6cbd8356f43b46322742f3c01c2a1f02da to disable irqs to work around a bug,
the result being that the debug variant gives you a WARNING about using mutex_trylock in interrupts, when its actually safe, while the non-debug variant
provides no warning, but is actually prone to deadlock.

There are a few other use cases in the kernel in which mutex_trylock may be used
in an interrupt context (crash_kexec being the most notable, as its used for the
same purposes that we're using it in netpoll, and where I got the inspiration
for my previous netpoll changes.

The more I look at this, the more I'm starting to think that, in addition to the
debug changes I've got proposed here, we should additionally convert the non-debug spin_lock_mutex variants to disable irqs while manipulating the mutexes. That would make mutex_trylock safe, and give us a nice mechanism to
create exclusion between sleepable paths that should not run atomically and interrupt context paths.

Quoted 3 lines

Ingo, can you comment on these thoughts above please. I'd like to get your opinion on this prior to spinning up a new patch if I could please.

How about introducing a second type of mutex, and only using changing the spin_lock() into spin_lock_irq() for that new type of mutex ? That way no performance penalty would be introduced for existing mutex users and mutex_trylock() could be made safe for use inside IRQ-context for the new mutex type only.

Bart.

Well, I guess Ingo doesn't have time to respond here. Given that, I've been looking at other ways of adressing this problem (as the more I think about it, the more I think changing mutex semantics, even to be more accepting, is going to be met with lots of friction). I've come up with the below change, and it works well for me (I've hammered it with ifup/downs while sending messages over netconsole for 24 hours now without any incident). I'm not sure I like all the details yet (I modified the rx_flag field to be a gneral flags field that uses test/set/clear_bit, which I don't think is necessecary, but it seems saner to me). the meat of the change though is that instead of a mutex, we use two flags that, respectively, inhibit netpoll usage, and indicate when we're in a netpoll service path. Using these two flags, in conjunction with a wait_queue, we can signal to executors in the netpoll path that we're inhibiting its use and expect to any user in the path to complete and wake up any contexts in the inhibiting path. Seems to work well for me. Let me know what you think, and I'll make any desired changes and post an official patch.

Best
Neil

Quoted 4 lines · Neil Horman

Bart, any testing/thoughts here? i'd like to get this fixed in the next few
days, but I'd like to get any feedback you might have first.

Sorry but I haven't been able to run any tests during the past eight days since I'm traveling and because of that I do not have access to my regular test setup.

Bart.

Quoted 4 lines · Neil Horman

Copy that. I can propose this change based on my own testing, or wait for you
to get back. Do you have a preference?

It will take until next week before I can run more tests. It depends on whether a fix can wait that long ?

Bart.

Dave, how do you feel about it? I'm comfortable with the wait queue change I've proposed, but I've not received any reports of actual netpoll deadlocks (i.e. the mutex solution is reporting a warning, but no actual problems). So I think its safe to wait a bit longer, unless you just want this squared away now.

From: Neil Horman <[email protected]>
Date: Tue, 23 Apr 2013 09:44:43 -0400

Quoted 4 lines

Dave, how do you feel about it? I'm comfortable with the wait queue change I've proposed, but I've not received any reports of actual netpoll deadlocks (i.e. the mutex solution is reporting a warning, but no actual problems). So I think its safe to wait a bit longer, unless you just want this squared away now.

If it's just a warning and people aren't actually hitting the potential deadlock, it can wait.

Quoted 8 lines · David Miller

From: Neil Horman <[email protected]>
Date: Tue, 23 Apr 2013 09:44:43 -0400

Quoted 4 lines

Dave, how do you feel about it? I'm comfortable with the wait queue change I've proposed, but I've not received any reports of actual netpoll deadlocks (i.e. the mutex solution is reporting a warning, but no actual problems). So I think its safe to wait a bit longer, unless you just want this squared away now.

Quoted 3 lines

If it's just a warning and people aren't actually hitting the potential deadlock, it can wait.

Copy that. Bart, I'll wait till you get back then.

Quoted 9 lines · Neil Horman

Quoted 8 lines · David Miller

From: Neil Horman <[email protected]>
Date: Tue, 23 Apr 2013 09:44:43 -0400

Quoted 4 lines

Dave, how do you feel about it? I'm comfortable with the wait queue change I've proposed, but I've not received any reports of actual netpoll deadlocks (i.e. the mutex solution is reporting a warning, but no actual problems). So I think its safe to wait a bit longer, unless you just want this squared away now.

Quoted 4 lines

Quoted 3 lines

If it's just a warning and people aren't actually hitting the potential deadlock, it can wait.

Copy that. Bart, I'll wait till you get back then.

(Just arrived home)

Sorry Neil, but I can still trigger the CPU stuck messages with kernel v3.9-rc8-24-gd7d7271:

kernel: BUG: soft lockup - CPU#0 stuck for 22s! [rs:main Q:Reg:601]
kernel: irq event stamp: 1999192
kernel: hardirqs last enabled at (1999191): [<ffffffff8103e89d>] console_unlock+0x41d/0x450
kernel: hardirqs last disabled at (1999192): [<ffffffff8143e96a>] apic_timer_interrupt+0x6a/0x80
kernel: softirqs last enabled at (1999188): [<ffffffff81044e26>] __do_softirq+0x196/0x280
kernel: softirqs last disabled at (1999181): [<ffffffff810450c5>] irq_exit+0xb5/0xc0
kernel: CPU 0
kernel: Pid: 601, comm: rs:main Q:Reg Tainted: G O 3.9.0-rc8-debug+ #1 System manufacturer P5Q DELUXE/P5Q DELUXE
kernel: RIP: 0010:[<ffffffff8103e8a0>] [<ffffffff8103e8a0>] console_unlock+0x420/0x450
kernel: Call Trace:
kernel: [<ffffffff812bbf37>] do_con_write.part.19+0x887/0x2040
kernel: [<ffffffff812a52b7>] ? process_output+0x37/0x70
kernel: [<ffffffff814316fc>] ? mutex_lock_nested+0x28c/0x350
kernel: [<ffffffff812a52b7>] ? process_output+0x37/0x70
kernel: [<ffffffff812bd764>] con_write+0x34/0x50
kernel: [<ffffffff812a51e9>] do_output_char+0x179/0x210
kernel: [<ffffffff812a52cd>] process_output+0x4d/0x70
kernel: [<ffffffff812a59d0>] n_tty_write+0x210/0x480
kernel: [<ffffffff81072710>] ? try_to_wake_up+0x2e0/0x2e0
kernel: [<ffffffff812a2839>] tty_write+0x159/0x300
kernel: [<ffffffff8109326f>] ? lock_release_holdtime.part.22+0xf/0x180
kernel: [<ffffffff812a57c0>] ? n_tty_poll+0x1c0/0x1c0
kernel: [<ffffffff81151a3b>] vfs_write+0xab/0x170
kernel: [<ffffffff81151ea5>] sys_write+0x55/0xa0
kernel: [<ffffffff8143dd82>] system_call_fastpath+0x16/0x1b

Bart.

Quoted 19 lines · Bart Van Assche

Sorry Neil, but I can still trigger the CPU stuck messages with kernel v3.9-rc8-24-gd7d7271:

kernel: BUG: soft lockup - CPU#0 stuck for 22s! [rs:main Q:Reg:601]
kernel: irq event stamp: 1999192
kernel: hardirqs last enabled at (1999191): [<ffffffff8103e89d>] console_unlock+0x41d/0x450
kernel: hardirqs last disabled at (1999192): [<ffffffff8143e96a>] apic_timer_interrupt+0x6a/0x80
kernel: softirqs last enabled at (1999188): [<ffffffff81044e26>] __do_softirq+0x196/0x280
kernel: softirqs last disabled at (1999181): [<ffffffff810450c5>] irq_exit+0xb5/0xc0
kernel: CPU 0
kernel: Pid: 601, comm: rs:main Q:Reg Tainted: G O 3.9.0-rc8-debug+ #1 System manufacturer P5Q DELUXE/P5Q DELUXE
kernel: RIP: 0010:[<ffffffff8103e8a0>] [<ffffffff8103e8a0>] console_unlock+0x420/0x450
kernel: Call Trace:
kernel: [<ffffffff812bbf37>] do_con_write.part.19+0x887/0x2040
kernel: [<ffffffff812a52b7>] ? process_output+0x37/0x70
kernel: [<ffffffff814316fc>] ? mutex_lock_nested+0x28c/0x350
kernel: [<ffffffff812a52b7>] ? process_output+0x37/0x70
kernel: [<ffffffff812bd764>] con_write+0x34/0x50
kernel: [<ffffffff812a51e9>] do_output_char+0x179/0x210
kernel: [<ffffffff812a52cd>] process_output+0x4d/0x70

Quoted 8 lines

kernel: [<ffffffff812a59d0>] n_tty_write+0x210/0x480
kernel: [<ffffffff81072710>] ? try_to_wake_up+0x2e0/0x2e0
kernel: [<ffffffff812a2839>] tty_write+0x159/0x300
kernel: [<ffffffff8109326f>] ? lock_release_holdtime.part.22+0xf/0x180
kernel: [<ffffffff812a57c0>] ? n_tty_poll+0x1c0/0x1c0
kernel: [<ffffffff81151a3b>] vfs_write+0xab/0x170
kernel: [<ffffffff81151ea5>] sys_write+0x55/0xa0
kernel: [<ffffffff8143dd82>] system_call_fastpath+0x16/0x1b

So, looking at this, I'm not 100% sure whats going on. console_unlock has the ability to detect the need for rescheduling when we call raw_spin_unlock_irqrestore at the bottom of the function, so there should be no reason that we don't give the per-cpu watchdog task a chance to run. About the only case I see in which we might be in trouble would be if somehow got into an infinite loop if every message in the log buffer had LOG_NOCONS set, in which case we would spin in this loop without ever scheduling or re-enabling interrupts. But for that to happen I think you would have to be flooding the log with messages that were bigger than the default message buffer size (about 1000 bytes without a newline). You're not doing that are you?

Bart Van Assche recently reported a warning to me:

This resulted from my commit ca99ca14c which introduced a mutex_trylock operation in a path that could execute in interrupt context. When mutex debugging is enabled, the above warns the user when we are in fact exectuting in interrupt context
interrupt context.

After some discussion, It seems that a semaphore is the proper mechanism to use here. While mutexes are defined to be unusable in interrupt context, no such condition exists for semaphores (save for the fact that the non blocking api calls, like up and down_trylock must be used when in irq context).

Signed-off-by Neil Horman <[email protected]>

Reported-by Bart Van Assche <[email protected]>

From: Neil Horman <[email protected]>
Date: Tue, 30 Apr 2013 11:35:05 -0400

Quoted 1 line

Bart Van Assche recently reported a warning to me:

...

Quoted 11 lines

This resulted from my commit ca99ca14c which introduced a mutex_trylock operation in a path that could execute in interrupt context. When mutex debugging is enabled, the above warns the user when we are in fact exectuting in interrupt context
interrupt context.

After some discussion, It seems that a semaphore is the proper mechanism to use here. While mutexes are defined to be unusable in interrupt context, no such condition exists for semaphores (save for the fact that the non blocking api calls, like up and down_trylock must be used when in irq context).

Quoted 2 lines

Signed-off-by Neil Horman <[email protected]>

Reported-by Bart Van Assche <[email protected]>

Neil this looks good to me so I'm going to toss it into my tree and queue it up for -stable too, thanks!

WARNING: at kernel/mutex.c:313 __mutex_unlock_slowpath+0x157/0x160()
Pid: 181, comm: kworker/0:1H Tainted: G           O 3.9.0-rc6-debug+ #1
Call Trace:
<IRQ>  [<ffffffff8103c3ef>] warn_slowpath_common+0x7f/0xc0
[<ffffffff8103c44a>] warn_slowpath_null+0x1a/0x20
[<ffffffff81432047>] __mutex_unlock_slowpath+0x157/0x160
[<ffffffff8143205e>] mutex_unlock+0xe/0x10
[<ffffffff8136d031>] netpoll_poll_dev+0x111/0x9a0
[<ffffffff81345f32>] ? __alloc_skb+0x82/0x2a0
[<ffffffff8136dac5>] netpoll_send_skb_on_dev+0x205/0x3b0

[<ffffffff8136e00a>] netpoll_send_udp+0x28a/0x3a0
[<ffffffffa0524843>] ? write_msg+0x53/0x110 [netconsole]
[<ffffffffa05248bf>] write_msg+0xcf/0x110 [netconsole]
[<ffffffff8103d7f1>] call_console_drivers.constprop.16+0xa1/0x120
[<ffffffff8103e848>] console_unlock+0x3f8/0x450
[<ffffffff8103ecce>] vprintk_emit+0x1ee/0x510
[<ffffffff812d1f2c>] dev_vprintk_emit+0x5c/0x70
[<ffffffff810ff047>] ? mempool_free_slab+0x17/0x20

Quoted 10 lines · Bart Van Assche

WARNING: at kernel/mutex.c:313 __mutex_unlock_slowpath+0x157/0x160()
Pid: 181, comm: kworker/0:1H Tainted: G           O 3.9.0-rc6-debug+ #1
Call Trace:
<IRQ>  [<ffffffff8103c3ef>] warn_slowpath_common+0x7f/0xc0
[<ffffffff8103c44a>] warn_slowpath_null+0x1a/0x20
[<ffffffff81432047>] __mutex_unlock_slowpath+0x157/0x160
[<ffffffff8143205e>] mutex_unlock+0xe/0x10
[<ffffffff8136d031>] netpoll_poll_dev+0x111/0x9a0
[<ffffffff81345f32>] ? __alloc_skb+0x82/0x2a0
[<ffffffff8136dac5>] netpoll_send_skb_on_dev+0x205/0x3b0

Quoted 8 lines

[<ffffffff8136e00a>] netpoll_send_udp+0x28a/0x3a0
[<ffffffffa0524843>] ? write_msg+0x53/0x110 [netconsole]
[<ffffffffa05248bf>] write_msg+0xcf/0x110 [netconsole]
[<ffffffff8103d7f1>] call_console_drivers.constprop.16+0xa1/0x120
[<ffffffff8103e848>] console_unlock+0x3f8/0x450
[<ffffffff8103ecce>] vprintk_emit+0x1ee/0x510
[<ffffffff812d1f2c>] dev_vprintk_emit+0x5c/0x70
[<ffffffff810ff047>] ? mempool_free_slab+0x17/0x20

I *really* think that using a mutex from a low level debug interface like netpoll is a mistake. We want such interfaces to be as atomic and as self-contained as
possible: using spinlocks, which could possibly be converted to raw spinlocks, etc.

mutexes should be used when there's an expectation of possibly long blocking time. That's not really the case for netpoll, we either are able to generate the skb right then and send it off, or we are in trouble, right?

Thanks,

Ingo