Re: [RT] sysrq Z: sleeping function called from invalid context

[Steven Rostedt <rostedt@goodmis.org>]

On Fri, 2011-12-02 at 15:08 -0800, Frank Rowand wrote:
> Hi Steve,
> 
> I get a "sleeping function called from invalid context" when I invoke sysrq Z.
> 
> I get this both with CONFIG_MAGIC_SYSRQ_FORCE_PRINTK enabled and disabled.

Patient:  Hey doctor, it hurts when I do this

Doctor:  Don't do that.


> 
> 3.0.12-rt29
> ARM Pandaboard
> 
> I have not tried this on 3.2-rc4-rt5.
> 
> [  900.963226] SysRq : Dump ftrace buffer
> [  900.967163] Dumping ftrace buffer:
> [  900.970733] BUG: sleeping function called from invalid context at kernel/rtmutex.c:645
> [  900.985137] in_atomic(): 0, irqs_disabled(): 128, pid: 563, name: irq/106-OMAP UA
> [  900.992980] 2 locks held by irq/106-OMAP UA/563:
> [  900.997833]  #0:  (&port_lock_key){+.+...}, at: [<c02d8b14>] serial_omap_irq+0x4c/0x7dc
> [  901.006286]  #1:  (sysrq_key_table_lock){+.+...}, at: [<c02c13a0>] __handle_sysrq+0x20/0x18c
> [  901.015167] irq event stamp: 45345
> [  901.018737] hardirqs last  enabled at (45344): [<c0482f68>] _raw_spin_unlock_irq+0x24/0x4c
> [  901.027435] hardirqs last disabled at (45345): [<c00fb854>] ftrace_dump+0x14/0x23c
> [  901.035400] softirqs last  enabled at (0): [<c009dca8>] copy_process+0x364/0xf84
> [  901.043182] softirqs last disabled at (0): [<  (null)>]   (null)
> [  901.049499] [<c00681b8>] (unwind_backtrace+0x0/0xf0) from [<c04824d0>] (rt_spin_lock+0x24/0x5c)
> [  901.058654] [<c04824d0>] (rt_spin_lock+0x24/0x5c) from [<c00f3b34>] (read_buffer_lock+0x4c/0x6c)
> [  901.067871] [<c00f3b34>] (read_buffer_lock+0x4c/0x6c) from [<c00f5908>] (ring_buffer_empty_cpu+0x50/0x7c)

Grumble. I really don't want to make the read_buffer_lock a real spin
lock. I'll have to see what else is called when its held. I you could
try to make it into a raw_spin_lock() if you want and see if it causes
any more issues.

I guess the other question is, what disabled interrupts?

Oh, it's in the lockdep splat above :-p

It's the ftrace_dump code that disables interrupts.

Oh! looking into the ring_buffer code, could you add this:
(totally untested)

diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index 2467714..2ffbb9d 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -1045,7 +1045,7 @@ static inline int ok_to_lock(void)
 	if (in_nmi())
 		return 0;
 #ifdef CONFIG_PREEMPT_RT_FULL
-	if (in_atomic())
+	if (in_atomic() || irqs_disabled())
 		return 0;
 #endif
 	return 1;


> [  901.077911] [<c00f5908>] (ring_buffer_empty_cpu+0x50/0x7c) from [<c00fa3cc>] (trace_empty+0x58/0xd8)
> [  901.087524] [<c00fa3cc>] (trace_empty+0x58/0xd8) from [<c00fb9f8>] (ftrace_dump+0x1b8/0x23c)
> [  901.096374] [<c00fb9f8>] (ftrace_dump+0x1b8/0x23c) from [<c02c1428>] (__handle_sysrq+0xa8/0x18c)
> [  901.105621] [<c02c1428>] (__handle_sysrq+0xa8/0x18c) from [<c02d90cc>] (serial_omap_irq+0x604/0x7dc)
> [  901.115203] [<c02d90cc>] (serial_omap_irq+0x604/0x7dc) from [<c00eb934>] (irq_forced_thread_fn+0x20/0x40)
> [  901.125244] [<c00eb934>] (irq_forced_thread_fn+0x20/0x40) from [<c00eb7dc>] (irq_thread+0x144/0x1e4)
> [  901.134887] [<c00eb7dc>] (irq_thread+0x144/0x1e4) from [<c00c094c>] (kthread+0x7c/0x84)
> [  901.143310] [<c00c094c>] (kthread+0x7c/0x84) from [<c0061e30>] (kernel_thread_exit+0x0/0x8)
> [  901.152496]    (ftrace buffer empty)
> 
> -Frank