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

Oliver Sang
2022-12-07T01:40:00Z

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