Re: [linus:master] [rcutorture] a5c095e0e9: WARNING:suspicious_RCU_usage

[Oliver Sang]

Hi Paul,

On Sat, Dec 03, 2022 at 10:56:54AM -0800, Paul E. McKenney wrote:
> On Sat, Dec 03, 2022 at 10:47:47PM +0800, kernel test robot wrote:
> > 
> > Greeting,
> > 
> > FYI, we noticed WARNING:suspicious_RCU_usage due to commit (built with gcc-11):
> > 
> > commit: a5c095e0e9b6fedcffd0907c84f77751128e2a34 ("rcutorture: Abstract read-lock-held checks")
> > https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
> > 
> > in testcase: rcutorture
> 
> This is expected behavior!

Thanks a lot for detailed guidance as below!

> 
> Your dmesg contains "busted_srcud-torture: rcu_torture_reader task started",
> which indicates that you are testing with "busted_srcud".  Searching
> for the string "busted_srcud" (with quotes) gets us this:
> 
> /* As above, but broken due to inappropriate reader extension. */
> static struct rcu_torture_ops busted_srcud_ops = {
> 	.ttype		= SRCU_FLAVOR,
> 	.init		= srcu_torture_init,
> 	.cleanup	= srcu_torture_cleanup,
> 	.readlock	= srcu_torture_read_lock,
> 	.read_delay	= rcu_read_delay,
> 	.readunlock	= srcu_torture_read_unlock,
> 	.readlock_held	= torture_srcu_read_lock_held,
> 	.get_gp_seq	= srcu_torture_completed,
> 	.deferred_free	= srcu_torture_deferred_free,
> 	.sync		= srcu_torture_synchronize,
> 	.exp_sync	= srcu_torture_synchronize_expedited,
> 	.call		= srcu_torture_call,
> 	.cb_barrier	= srcu_torture_barrier,
> 	.stats		= srcu_torture_stats,
> 	.irq_capable	= 1,
> 	.no_pi_lock	= IS_ENABLED(CONFIG_TINY_SRCU),
> 	.extendables	= RCUTORTURE_MAX_EXTEND,
> 	.name		= "busted_srcud"
> };
> 
> That comment says it all.  The point of this test is to make sure that
> rcutorture really does group differeent types of readers together
> when asked.  Since we have torture_srcu_read_lock_held(), we expect
> rcutorture to complain when the reader uses one of the non-SRCU readers,
> such as preemption being disabled.
> 
> So the complaint you got was an indication that rcutorture really will
> complain when as it should when a given RCU flavor's read-side protection
> is broken.
> 
> 							Thanx, Paul
> 
> > [  154.593443][  T500] WARNING: suspicious RCU usage
> > [  154.594126][  T500] 5.13.0-rc1-00008-ga5c095e0e9b6 #1 Not tainted
> > [  154.594990][  T500] -----------------------------
> > [  154.595665][  T500] kernel/rcu/rcutorture.c:1568 suspicious rcu_dereference_check() usage!
> > [  154.596944][  T500]
> > [  154.596944][  T500] other info that might help us debug this:
> > [  154.596944][  T500]
> > [  154.598385][  T500]
> > [  154.598385][  T500] rcu_scheduler_active = 2, debug_locks = 1
> > [  154.599595][  T500] no locks held by rcu_torture_rea/500.
> > [  154.601317][  T500]
> > [  154.601317][  T500] stack backtrace:
> > [  154.602154][  T500] CPU: 1 PID: 500 Comm: rcu_torture_rea Not tainted 5.13.0-rc1-00008-ga5c095e0e9b6 #1
> > [  154.603441][  T500] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.0-debian-1.16.0-4 04/01/2014
> > [  154.604909][  T500] Call Trace:
> > [ 154.605402][ T500] ? dump_stack (??:?) 
> > [ 154.606122][ T500] ? lockdep_rcu_suspicious (??:?) 
> > [ 154.606892][ T500] ? rcu_torture_one_read (rcutorture.c:?) rcutorture
> > [ 154.607813][ T500] ? rcutorture_loop_extend (rcutorture.c:?) rcutorture
> > [ 154.608764][ T500] ? __mod_timer (timer.c:?) 
> > [ 154.609578][ T500] ? do_init_timer (timer.c:?) 
> > [ 154.610282][ T500] ? rcu_torture_reader (rcutorture.c:?) rcutorture
> > [ 154.611202][ T500] ? rcu_torture_read_exit_child (rcutorture.c:?) rcutorture
> > [ 154.612204][ T500] ? __kasan_check_read (??:?) 
> > [ 154.612974][ T500] ? rcu_torture_reader (rcutorture.c:?) rcutorture
> > [ 154.613950][ T500] ? __kasan_check_read (??:?) 
> > [ 154.614673][ T500] ? test_bit (main.c:?) 
> > [ 154.615332][ T500] ? __kthread_parkme (kthread.c:?) 
> > [ 154.616059][ T500] ? kthread (kthread.c:?) 
> > [ 154.616640][ T500] ? rcu_torture_read_exit_child (rcutorture.c:?) rcutorture
> > [ 154.617642][ T500] ? kzalloc (resource.c:?) 
> > [ 154.618361][ T500] ? ret_from_fork (??:?) 
> > [  154.627467][  T483] busted_srcud-torture: Creating torture_shuffle task
> > [  154.629419][  T502] busted_srcud-torture: rcu_torture_stats task started
> > [  154.640374][  T483] busted_srcud-torture: Creating torture_stutter task
> > [  154.644728][  T504] busted_srcud-torture: torture_shuffle task started
> > [  154.645963][  T483] busted_srcud-torture: rcu_torture_fwd_prog_init: Disabled, unsupported by RCU flavor under test
> > [  154.647399][  T483] busted_srcud-torture: Creating rcu_torture_read_exit task
> > [  154.649698][  T505] busted_srcud-torture: torture_stutter task started
> > [ 154.660318][ T483] initcall rcu_torture_init+0x0/0x2b83 [rcutorture] returned 0 after 472073 usecs 
> > [  154.679808][  T507] busted_srcud-torture: rcu_torture_read_exit: Start of test
> > [  160.204160][  T507] busted_srcud-torture: rcu_torture_read_exit: End of episode
> > [  173.852307][  T507] busted_srcud-torture: rcu_torture_read_exit: Start of episode
> > 
> >