[BUG] stack tracing causes: kernel/module.c:271 module_assert_mutex_or_preempt

Steven Rostedt
2017-04-05T13:33:22Z

Hi Paul,

My tests are triggering the following when I have lockdep enabled and
running the stack tracer:

------------[ cut here ]------------
WARNING: CPU: 0 PID: 0 at /work/autotest/nobackup/linux-test.git/kernel/module.c:271 module_assert_mutex_or_preempt+0x4f/0x51
Modules linked in: ppdev parport_pc parport [last unloaded: trace_events_sample]
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.11.0-rc3-test+ #48
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
Call Trace:

===============================
[ ERR: suspicious RCU usage. ]
4.11.0-rc3-test+ #48 Not tainted
-------------------------------
/work/autotest/nobackup/linux-test.git/include/linux/rcupdate.h:837 rcu_read_lock() used illegally while idle!

other info that might help us debug this:

RCU used illegally from idle CPU!
rcu_scheduler_active = 2, debug_locks = 0
RCU used illegally from extended quiescent state!
1 lock held by swapper/0/0:
#0: (rcu_read_lock){......}, at: [<ffffffff810ebee3>] rcu_read_lock+0x0/0x61

stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.11.0-rc3-test+ #48
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
Call Trace:
dump_stack+0x68/0x92
__warn+0xc2/0xdd
? 0xffffffffa0026077
warn_slowpath_null+0x1d/0x1f
module_assert_mutex_or_preempt+0x4f/0x51
__module_address+0x2a/0xac
? 0xffffffffa0026077
__module_text_address+0x12/0x59
? 0xffffffffa0026077
is_module_text_address+0xe/0x16
__kernel_text_address+0x2b/0x80
? 0xffffffffa0026077
unwind_get_return_address+0x50/0x5c
__save_stack_trace+0x76/0xbf
? rcu_eqs_enter_common.constprop.71+0x5/0x108
save_stack_trace+0x1b/0x1d
check_stack+0xec/0x24a
stack_trace_call+0x40/0x53 <<-- This is the start of the stack tracer
0xffffffffa0026077
? ftrace_graph_caller+0x78/0xa8
? trace_hardirqs_off+0xd/0xf
? rcu_eqs_enter_common.constprop.71+0x5/0x108
rcu_eqs_enter_common.constprop.71+0x5/0x108 <<-- It appears to be testing the rcu internal code
rcu_idle_enter+0x51/0x72
? rcu_eqs_enter_common.constprop.71+0x5/0x108
? rcu_idle_enter+0x51/0x72
do_idle+0xbb/0x1e5
cpu_startup_entry+0x1f/0x21
rest_init+0x127/0x12d
start_kernel+0x3f5/0x402
x86_64_start_reservations+0x2f/0x31
x86_64_start_kernel+0x17f/0x192
start_cpu+0x14/0x14
? start_cpu+0x14/0x14
---[ end trace eeaad31bc52457e7 ]---

Now the check_stack() function in kernel/trace/trace_stack.c has the
following:

/*
* RCU may not be watching, make it see us.
* The stack trace code uses rcu_sched.
*/
rcu_irq_enter();

What I'm guessing, is that because it is tracing the internals of the
rcu code, and checking its stack, the stack trace triggered in a
location where calling rcu_irq_enter() isn't sufficient to have rcu
become watchable.

I may add code to check if rcu is indeed watching after the
rcu_irq_enter() call, and if it still isn't to simply exit out.

Thoughts?

-- Steve