Messages in this thread | | | Date | Wed, 5 Apr 2017 09:32:07 -0400 | From | Steven Rostedt <> | Subject | [BUG] stack tracing causes: kernel/module.c:271 module_assert_mutex_or_preempt |
| |
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
| |