On Tue, Jul 31, 2012 at 08:05:56PM +0800, Fengguang Wu wrote:
> On Mon, Jul 30, 2012 at 11:39:12AM -0400, Steven Rostedt wrote:
> > On Tue, 2012-07-24 at 17:03 +0800, Fengguang Wu wrote:
> > > Hi Steven,
> > 
> > Hi Fengguang,
> > 
> > Just an FYI, It's best to send email to my rostedt@goodmis.org account.
> > I don't check my redhat account every day.
> 
> OK, sorry for forgetting about that!
> 
> > > 
> > > This looks like some old bug, so I directly report to you w/o trying
> > > to bisect it. It only happens on the attached i386 randconfig and
> > > happens in about half of the kvm boots.
> > > 
> > > [    1.380369] Testing tracer irqsoff: [    1.524917] 
> > > [    1.525217] ===============================
> > > [    1.525868] [ INFO: suspicious RCU usage. ]
> > > [    1.526556] 3.5.0+ #1289 Not tainted
> > > [    1.527124] -------------------------------
> > > [    1.527799] /c/kernel-tests/src/linux/include/linux/rcupdate.h:730 rcu_read_lock() used illegally while idle!
> > > [    1.529375] 
> > > [    1.529375] other info that might help us debug this:
> > > [    1.529375] 
> > > [    1.530667] 
> > > [    1.530667] RCU used illegally from idle CPU!
> > > [    1.530667] rcu_scheduler_active = 1, debug_locks = 1
> > > [    1.532383] RCU used illegally from extended quiescent state!
> > > [    1.533297] 2 locks held by swapper/0/0:
> > > 
> > > [    1.533924]  #0: [    1.534271]  (max_trace_lock){......}, at: [<410e9d67>] check_critical_timing+0x67/0x1b0
> > > [    1.534883]  #1:  (rcu_read_lock){.+.+..}, at: [<410e1ea0>] __update_max_tr+0x0/0x200
> > > 
> > > [    1.534883] stack backtrace:
> > > [    1.534883] Pid: 0, comm: swapper/0 Not tainted 3.5.0+ #1289
> > > [    1.534883] Call Trace:
> > > [    1.534883]  [<41093a76>] lockdep_rcu_suspicious+0xc6/0x100
> > > [    1.534883]  [<410e2071>] __update_max_tr+0x1d1/0x200
> > 
> > This is very weird because __update_max_tr does not use rcu_read lock().
> > If you still have the kernel around (or can reproduce it), can you show
> > the objdump of the __update_max_tr function. I wonder if some debug
> > option requires RCU usage somewhere there.
> 
> Here is part of trace.s, where lockdep_rcu_suspicious shows up in 3
> places:

Another note: the above __update_max_tr back trace only appear accasionally.
The more typical error messages look like this:

[   16.195315] Running tests on trace events:
[   16.196586] Testing event kfree_skb: [   16.200404] ------------[ cut here ]------------
[   16.201428] WARNING: at /c/wfg/linux/kernel/lockdep.c:3506 check_flags+0x125/0x154()
[   16.203036] Hardware name: Bochs
[   16.203763] Pid: 44, comm: rcu_torture_wri Not tainted 3.5.0+ #82
[   16.205067] Call Trace:

[   16.205640]  [<c102a9f8>] warn_slowpath_common+0x63/0x78
[   16.206842]  [<c10644ed>] ? check_flags+0x125/0x154
[   16.207865]  [<c102aaa7>] warn_slowpath_null+0x14/0x18
[   16.208939]  [<c10644ed>] check_flags+0x125/0x154
[   16.210009]  [<c106522b>] lock_is_held+0x28/0x82
[   16.210023]  [<c1031849>] ? _local_bh_enable_ip+0x9e/0x166
[   16.210023]  [<c107d0ac>] rcu_read_lock_held+0x26/0x2c
[   16.210023]  [<c107d59d>] ftrace_ops_list_func+0x82/0xca
[   16.210023]  [<c1050ce8>] ? sub_preempt_count+0x5/0xf1
[   16.210023]  [<c13e5699>] trace+0x13/0x1b
[   16.210023]  [<c10318ec>] ? _local_bh_enable_ip+0x141/0x166
[   16.210023]  [<c1050ced>] ? sub_preempt_count+0xa/0xf1
[   16.210023]  [<c1031849>] _local_bh_enable_ip+0x9e/0x166
[   16.210023]  [<c1077fea>] ? rcu_torture_writer+0xa1/0x1c5
[   16.220592]  [<c1031bc4>] local_bh_enable_ip+0xd/0xf
[   16.220592]  [<c13e3ff9>] _raw_spin_unlock_bh+0x34/0x37
[   16.220592]  [<c1077fea>] rcu_torture_writer+0xa1/0x1c5
[   16.220592]  [<c104544f>] kthread+0x6c/0x71
[   16.220592]  [<c1077f49>] ? rcu_torture_barrier_cbs+0x199/0x199
[   16.220592]  [<c10453e3>] ? insert_kthread_work+0xa8/0xa8
[   16.220592]  [<c13e5662>] kernel_thread_helper+0x6/0x10

Thanks,
Fengguang