lkml.org 
[lkml]   [2017]   [Apr]   [5]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    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

    \
     
     \ /
      Last update: 2017-04-05 15:36    [W:2.381 / U:0.120 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site