Re: __update_max_tr: rcu_read_lock() used illegally while idle!

["Paul E. McKenney" <paulmck@linux.vnet.ibm.com>]

On Tue, Jul 31, 2012 at 09:44:13AM -0400, Steven Rostedt wrote:
> On Tue, 2012-07-31 at 20:10 +0800, Fengguang Wu wrote:
> 
> > 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
> 
> This is caused by the function tracer. Every function can call this
> (even rcu_read_lock itself).
> 
> We use a schedule rcu to reference a structure, and call
> rcu_dereference_raw() to get it.
> 
> Perhaps we should just bypass the check?
> 
> Hmm, looking at this again, perhaps it needs the
> rcu_dereference_sched()? When this was first added (3f379b03)
> rcu_dereference_raw was:
> 
> #define rcu_dereference_raw(p)  ({ \
>                                 typeof(p) _________p1 = ACCESS_ONCE(p); \
>                                 smp_read_barrier_depends(); \
>                                 (_________p1); \
>                                 })
> 
> With no check. In fact, the check called the raw. Now it's reversed. I'm
> thinking that we need a way to not have a check. Function tracing is
> *extremely* invasive. As I said, this gets called *by* rcu_read_lock()!
> I'm not sure we want checks involved here.

???

#define rcu_dereference_raw(p) rcu_dereference_check(p, 1)

#define rcu_dereference_check(p, c) \
	__rcu_dereference_check((p), rcu_read_lock_held() || (c), __rcu)

Which becomes "__rcu_dereference_check(p, 1, __rcu)":

#define __rcu_dereference_check(p, c, space) \
	({ \
		typeof(*p) *_________p1 = (typeof(*p)*__force )ACCESS_ONCE(p); \
		rcu_lockdep_assert(c, "suspicious rcu_dereference_check()" \
				      " usage"); \
		rcu_dereference_sparse(p, space); \
		smp_read_barrier_depends(); \
		((typeof(*p) __force __kernel *)(_________p1)); \
	})

Which should therefore never trigger.  So what is really happening here?

There is also an rcu_dereference_sched_check() as well as
rcu_dereference_sched(), so you could pass "1" in to that, but I would
hope that you are in an environment where rcu_dereference_sched_check()
would validate things correctly.

							Thanx, Paul

> -- Steve
> 
> > [   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
> 
>