lkml.org 
[lkml]   [2012]   [Sep]   [12]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRCU idle CPU detection is broken in linux-next
    Hi Paul,

    While fuzzing using trinity inside a KVM tools guest, I've managed to trigger
    "RCU used illegally from idle CPU!" warnings several times.

    There are a bunch of traces which seem to pop exactly at the same time and from
    different places around the kernel. Here are several of them:

    (1):

    [ 29.006532] ===============================
    [ 29.007033] [ INFO: suspicious RCU usage. ]
    [ 29.007033] 3.6.0-rc5-next-20120912-sasha-00001-gb0c9916-dirty #331 Tainted:
    G W
    [ 29.007033] -------------------------------
    [ 29.007033] include/linux/rcupdate.h:737 rcu_read_lock() used illegally while
    idle!
    [ 29.007033]
    [ 29.007033] other info that might help us debug this:
    [ 29.007033]
    [ 29.007033]
    [ 29.007033] RCU used illegally from idle CPU!
    [ 29.007033] rcu_scheduler_active = 1, debug_locks = 1
    [ 29.007033] RCU used illegally from extended quiescent state!
    [ 29.007033] 2 locks held by rcu_preempt/11:
    [ 29.007033] #0: (&rq->lock){-.-.-.}, at: [<ffffffff83742f50>]
    __schedule+0x180/0x8f0
    [ 29.007033] #1: (rcu_read_lock){.+.+..}, at: [<ffffffff8114ff1e>]
    cpuacct_charge+0xe/0x200
    [ 29.007033]
    [ 29.007033] stack backtrace:
    [ 29.007033] Pid: 11, comm: rcu_preempt Tainted: G W
    3.6.0-rc5-next-20120912-sasha-00001-gb0c9916-dirty #331
    [ 29.007033] Call Trace:
    [ 29.007033] [<ffffffff8117eaeb>] lockdep_rcu_suspicious+0x10b/0x120
    [ 29.007033] [<ffffffff8114ffa0>] cpuacct_charge+0x90/0x200
    [ 29.007033] [<ffffffff8114ff1e>] ? cpuacct_charge+0xe/0x200
    [ 29.007033] [<ffffffff811548a3>] update_curr+0x1a3/0x270
    [ 29.007033] [<ffffffff8115527a>] dequeue_entity+0x2a/0x210
    [ 29.007033] [<ffffffff811556b5>] dequeue_task_fair+0x45/0x130
    [ 29.007033] [<ffffffff81148149>] dequeue_task+0x89/0xa0
    [ 29.007033] [<ffffffff81148ebe>] deactivate_task+0x1e/0x20
    [ 29.007033] [<ffffffff83743649>] __schedule+0x879/0x8f0
    [ 29.007033] [<ffffffff8117a60d>] ? trace_hardirqs_on+0xd/0x10
    [ 29.007033] [<ffffffff83743715>] schedule+0x55/0x60
    [ 29.007033] [<ffffffff811c672d>] rcu_gp_kthread+0xdd/0xed0
    [ 29.007033] [<ffffffff83744ebb>] ? _raw_spin_unlock_irq+0x2b/0x80
    [ 29.007033] [<ffffffff81137210>] ? abort_exclusive_wait+0xb0/0xb0
    [ 29.007033] [<ffffffff811c6650>] ? rcu_gp_fqs+0x80/0x80
    [ 29.007033] [<ffffffff81135e43>] kthread+0xe3/0xf0
    [ 29.007033] [<ffffffff83747a84>] kernel_thread_helper+0x4/0x10
    [ 29.007033] [<ffffffff83745df4>] ? retint_restore_args+0x13/0x13
    [ 29.007033] [<ffffffff81135d60>] ? insert_kthread_work+0x90/0x90
    [ 29.007033] [<ffffffff83747a80>] ? gs_change+0x13/0x13

    (2):

    [ 28.876466] ===============================
    [ 28.876466] [ INFO: suspicious RCU usage. ]
    [ 28.876466] 3.6.0-rc5-next-20120912-sasha-00001-gb0c9916-dirty #331 Tainted:
    G W
    [ 28.876466] -------------------------------
    [ 28.876466] include/linux/rcupdate.h:758 rcu_read_unlock() used illegally
    while idle!
    [ 28.876466]
    [ 28.876466] other info that might help us debug this:
    [ 28.876466]
    [ 28.876466]
    [ 28.876466] RCU used illegally from idle CPU!
    [ 28.876466] rcu_scheduler_active = 1, debug_locks = 1
    [ 28.876466] RCU used illegally from extended quiescent state!
    [ 28.876466] 2 locks held by trinity-child58/5966:
    [ 28.876466] #0: (&(&sighand->siglock)->rlock){-.-...}, at:
    [<ffffffff8111f548>] force_sig_info+0x38/0x100
    [ 28.876466] #1: (rcu_read_lock){.+.+..}, at: [<ffffffff8111d410>]
    __sigqueue_alloc+0x0/0x230
    [ 28.876466]
    [ 28.876466] stack backtrace:
    [ 28.876466] Pid: 5966, comm: trinity-child58 Tainted: G W
    3.6.0-rc5-next-20120912-sasha-00001-gb0c9916-dirty #331
    [ 28.876466] Call Trace:
    [ 28.876466] [<ffffffff8117eaeb>] lockdep_rcu_suspicious+0x10b/0x120
    [ 28.876466] [<ffffffff8111d558>] __sigqueue_alloc+0x148/0x230
    [ 28.876466] [<ffffffff8111d410>] ? check_kill_permission+0x220/0x220
    [ 28.876466] [<ffffffff8111e91a>] __send_signal+0x51a/0x580
    [ 28.876466] [<ffffffff8111f500>] ? do_signal_stop+0x2c0/0x2d0
    [ 28.876466] [<ffffffff8111e9c0>] send_signal+0x40/0x80
    [ 28.876466] [<ffffffff8111f548>] ? force_sig_info+0x38/0x100
    [ 28.876466] [<ffffffff811c38ad>] ? rcu_user_enter+0xed/0x110
    [ 28.876466] [<ffffffff8111f5d3>] force_sig_info+0xc3/0x100
    [ 28.876466] [<ffffffff811203a1>] force_sig+0x11/0x20
    [ 28.876466] [<ffffffff8106da1d>] do_general_protection+0xfd/0x170
    [ 28.876466] [<ffffffff83746075>] general_protection+0x25/0x30

    (3):

    [ 28.876466] ===============================
    [ 28.876466] [ INFO: suspicious RCU usage. ]
    [ 28.876466] 3.6.0-rc5-next-20120912-sasha-00001-gb0c9916-dirty #331 Tainted:
    G W
    [ 28.876466] -------------------------------
    [ 28.876466] kernel/signal.c:366 suspicious rcu_dereference_check() usage!
    [ 28.876466]
    [ 28.876466] other info that might help us debug this:
    [ 28.876466]
    [ 28.876466]
    [ 28.876466] RCU used illegally from idle CPU!
    [ 28.876466] rcu_scheduler_active = 1, debug_locks = 1
    [ 28.876466] RCU used illegally from extended quiescent state!
    [ 28.876466] 2 locks held by trinity-child58/5966:
    [ 28.876466] #0: (&(&sighand->siglock)->rlock){-.-...}, at:
    [<ffffffff8111f548>] force_sig_info+0x38/0x100
    [ 28.876466] #1: (rcu_read_lock){.+.+..}, at: [<ffffffff8111d410>]
    __sigqueue_alloc+0x0/0x230
    [ 28.876466]
    [ 28.876466] stack backtrace:
    [ 28.876466] Pid: 5966, comm: trinity-child58 Tainted: G W
    3.6.0-rc5-next-20120912-sasha-00001-gb0c9916-dirty #331
    [ 28.876466] Call Trace:
    [ 28.876466] [<ffffffff8117eaeb>] lockdep_rcu_suspicious+0x10b/0x120
    [ 28.876466] [<ffffffff8111d50f>] __sigqueue_alloc+0xff/0x230
    [ 28.876466] [<ffffffff8111d410>] ? check_kill_permission+0x220/0x220
    [ 28.876466] [<ffffffff8111e91a>] __send_signal+0x51a/0x580
    [ 28.876466] [<ffffffff8111f500>] ? do_signal_stop+0x2c0/0x2d0
    [ 28.876466] [<ffffffff8111e9c0>] send_signal+0x40/0x80
    [ 28.876466] [<ffffffff8111f548>] ? force_sig_info+0x38/0x100
    [ 28.876466] [<ffffffff811c38ad>] ? rcu_user_enter+0xed/0x110
    [ 28.876466] [<ffffffff8111f5d3>] force_sig_info+0xc3/0x100
    [ 28.876466] [<ffffffff811203a1>] force_sig+0x11/0x20
    [ 28.876466] [<ffffffff8106da1d>] do_general_protection+0xfd/0x170
    [ 28.876466] [<ffffffff83746075>] general_protection+0x25/0x30


    \
     
     \ /
      Last update: 2012-09-12 20:41    [W:4.495 / U:0.324 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site