Re: next-20191108: qemu arm64: WARNING: suspicious RCU usage

From: Paul E. McKenney
Date: Mon Nov 11 2019 - 08:34:50 EST


On Mon, Nov 11, 2019 at 08:59:25AM +0100, Anders Roxell wrote:
> Hi,
>
> I'm seeing the following warning when I'm booting an arm64 allmodconfig
> kernel [1] on linux-next tag next-20191108, is this anything you've seen
> before ?
>
>
> The code seems to have introduced that is f0ad0860d01e ("ipv4: ipmr:
> support multiple tables") in 2010 and the warning was added reacently
> 28875945ba98 ("rcu: Add support for consolidated-RCU reader checking").
>
>
> [ 32.496021][ T1] =============================
> [ 32.497616][ T1] WARNING: suspicious RCU usage
> [ 32.499614][ T1] 5.4.0-rc6-next-20191108-00003-gf74bac957b5c-dirty #2 Not tainted
> [ 32.502018][ T1] -----------------------------
> [ 32.503976][ T1] net/ipv4/ipmr.c:136 RCU-list traversed in non-reader section!!
> [ 32.506746][ T1]
> [ 32.506746][ T1] other info that might help us debug this:
> [ 32.506746][ T1]
> [ 32.509794][ T1]
> [ 32.509794][ T1] rcu_scheduler_active = 2, debug_locks = 1
> [ 32.512661][ T1] 1 lock held by swapper/0/1:
> [ 32.514169][ T1] #0: ffffa000150dd678 (pernet_ops_rwsem){+.+.}, at: register_pernet_subsys+0x24/0x50
> [ 32.517621][ T1]
> [ 32.517621][ T1] stack backtrace:
> [ 32.519930][ T1] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 5.4.0-rc6-next-20191108-00003-gf74bac957b5c-dirty #2
> [ 32.523063][ T1] Hardware name: linux,dummy-virt (DT)
> [ 32.524787][ T1] Call trace:
> [ 32.525946][ T1] dump_backtrace+0x0/0x2d0
> [ 32.527433][ T1] show_stack+0x20/0x30
> [ 32.528811][ T1] dump_stack+0x204/0x2ac
> [ 32.530258][ T1] lockdep_rcu_suspicious+0xf4/0x108
> [ 32.531993][ T1] ipmr_get_table+0xc8/0x170

So this one is invoking ipmr_for_each_table(), which in turn invokes
list_for_each_entry_rcu(), which really does want to be in an
RCU read-side critical section. (But you can pass it an optional
additional lockdep expressions.

> [ 32.533496][ T1] ipmr_new_table+0x48/0xa0

And this does look like update-side code...

> [ 32.535002][ T1] ipmr_net_init+0xe8/0x258

And this one is marked with "__net_init", which turns out to be __init.
So this is being invoked during early boot (see inet_init() below).
Or with RTNL held when invoked at runtime. So, can we make a lockdep
expression for this combination?

The RTNL part is easy, something like this in include/linux/rtnetlink.h:

#ifdef CONFIG_PROVE_LOCKING
extern int lockdep_rtnl_is_held(void);
#else
#define lockdep_rtnl_is_held() 1
#endif

And in net/core/rtnetlink.c:

#ifdef CONFIG_PROVE_LOCKING
int lockdep_rtnl_is_held(void)
{
return lockdep_is_held(&rtnl_mutex);
}
#endif

> [ 32.536465][ T1] ops_init+0x280/0x2d8
> [ 32.537876][ T1] register_pernet_operations+0x210/0x420
> [ 32.539707][ T1] register_pernet_subsys+0x30/0x50
> [ 32.541372][ T1] ip_mr_init+0x54/0x180
> [ 32.542785][ T1] inet_init+0x25c/0x3e8

And this is an fs_initcall(). This is late enough during boot that
RTNL could conceivably be held, but I don't see evidence of that.
One approach would be to hold RTNL across this initialization code.

So the other approach would be to have a global variable in net/ipv4/ipmr.c
whose definition depends on whether lockdep is enabled:

#ifdef CONFIG_PROVE_LOCKING
int ip_mr_initialized;
void ip_mr_now_initialized(void) { ip_mr_initialized = 1; }
#else
const int ip_mr_initialized = 1;
void ip_mr_now_initialized(void) { }
#endif

Then at the end of ip_mr_init():

ip_mr_now_initialized();

And finally change the CONFIG_IP_MROUTE_MULTIPLE_TABLES definition
of ipmr_for_each_table() to be something like:

#define ipmr_for_each_table(mrt, net) \
list_for_each_entry_rcu(mrt, &net->ipv4.mr_tables, list, \
lockdep_rtnl_is_held() || !ip_mr_initialized)

> [ 32.544186][ T1] do_one_initcall+0x4c0/0xad8
> [ 32.545757][ T1] kernel_init_freeable+0x3e0/0x500
> [ 32.547443][ T1] kernel_init+0x14/0x1f0
> [ 32.548875][ T1] ret_from_fork+0x10/0x18

Does that work for you?

Thanx, Paul