Hi Ying, It seems the mail server I am using to send out patches is down at the moment, so I will just paste my own solution into the mail browser. See below. This patch works, and the warning disappears, but we are still violating the restriction that rhashtable_walk_enter() should not be called in interrupt context. The alternative is to launch the net_finalize() call into the system work queue, but that is far from any 'elegant' solution in my view.
///jon >From c18f89cb99c9d5f9a950b031acebfaf0751fa488 Mon Sep 17 00:00:00 2001 From: Jon Maloy <[email protected]> Date: Mon, 5 Nov 2018 01:30:04 +0100 Subject: [net 1/1] tipc: fix lockdep warning We get the following warning: [ 47.926140] 32-bit node address hash set to 2010a0a [ 47.927202] [ 47.927433] ================================ [ 47.928050] WARNING: inconsistent lock state [ 47.928661] 4.19.0+ #37 Tainted: G E [ 47.929346] -------------------------------- [ 47.929954] inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage. [ 47.930116] swapper/3/0 [HC0[0]:SC1[3]:HE1:SE0] takes: [ 47.930116] 00000000af8bc31e (&(&ht->lock)->rlock){+.?.}, at: rhashtable_walk_enter+0x36/0xb0 [ 47.930116] {SOFTIRQ-ON-W} state was registered at: [ 47.930116] _raw_spin_lock+0x29/0x60 [ 47.930116] rht_deferred_worker+0x556/0x810 [ 47.930116] process_one_work+0x1f5/0x540 [ 47.930116] worker_thread+0x64/0x3e0 [ 47.930116] kthread+0x112/0x150 [ 47.930116] ret_from_fork+0x3a/0x50 [ 47.930116] irq event stamp: 14044 [ 47.930116] hardirqs last enabled at (14044): [<ffffffff9a07fbba>] __local_bh_enable_ip+0x7a/0xf0 [ 47.938117] hardirqs last disabled at (14043): [<ffffffff9a07fb81>] __local_bh_enable_ip+0x41/0xf0 [ 47.938117] softirqs last enabled at (14028): [<ffffffff9a0803ee>] irq_enter+0x5e/0x60 [ 47.938117] softirqs last disabled at (14029): [<ffffffff9a0804a5>] irq_exit+0xb5/0xc0 [ 47.938117] [ 47.938117] other info that might help us debug this: [ 47.938117] Possible unsafe locking scenario: [ 47.938117] [ 47.938117] CPU0 [ 47.938117] ---- [ 47.938117] lock(&(&ht->lock)->rlock); [ 47.938117] <Interrupt> [ 47.938117] lock(&(&ht->lock)->rlock); [ 47.938117] [ 47.938117] *** DEADLOCK *** [ 47.938117] [ 47.938117] 2 locks held by swapper/3/0: [ 47.938117] #0: 0000000062c64f90 ((&d->timer)){+.-.}, at: call_timer_fn+0x5/0x280 [ 47.938117] #1: 00000000ee39619c (&(&d->lock)->rlock){+.-.}, at: tipc_disc_timeout+0xc8/0x540 [tipc] [ 47.938117] [ 47.938117] stack backtrace: [ 47.938117] CPU: 3 PID: 0 Comm: swapper/3 Tainted: G E 4.19.0+ #37 [ 47.938117] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011 [ 47.938117] Call Trace: [ 47.938117] <IRQ> [ 47.938117] dump_stack+0x5e/0x8b [ 47.938117] print_usage_bug+0x1ed/0x1ff [ 47.938117] mark_lock+0x5b5/0x630 [ 47.938117] __lock_acquire+0x4c0/0x18f0 [ 47.938117] ? lock_acquire+0xa6/0x180 [ 47.938117] lock_acquire+0xa6/0x180 [ 47.938117] ? rhashtable_walk_enter+0x36/0xb0 [ 47.938117] _raw_spin_lock+0x29/0x60 [ 47.938117] ? rhashtable_walk_enter+0x36/0xb0 [ 47.938117] rhashtable_walk_enter+0x36/0xb0 [ 47.938117] tipc_sk_reinit+0xb0/0x410 [tipc] [ 47.938117] ? mark_held_locks+0x6f/0x90 [ 47.938117] ? __local_bh_enable_ip+0x7a/0xf0 [ 47.938117] ? lockdep_hardirqs_on+0x20/0x1a0 [ 47.938117] tipc_net_finalize+0xbf/0x180 [tipc] [ 47.938117] tipc_disc_timeout+0x509/0x540 [tipc] [ 47.938117] ? call_timer_fn+0x5/0x280 [ 47.938117] ? tipc_disc_msg_xmit.isra.19+0xa0/0xa0 [tipc] [ 47.938117] ? tipc_disc_msg_xmit.isra.19+0xa0/0xa0 [tipc] [ 47.938117] call_timer_fn+0xa1/0x280 [ 47.938117] ? tipc_disc_msg_xmit.isra.19+0xa0/0xa0 [tipc] [ 47.938117] run_timer_softirq+0x1f2/0x4d0 [ 47.938117] __do_softirq+0xfc/0x413 [ 47.938117] irq_exit+0xb5/0xc0 [ 47.938117] smp_apic_timer_interrupt+0xac/0x210 [ 47.938117] apic_timer_interrupt+0xf/0x20 [ 47.938117] </IRQ> [ 47.938117] RIP: 0010:default_idle+0x1c/0x140 [ 47.938117] Code: 90 90 90 90 90 90 90 90 90 90 90 90 90 90 0f 1f 44 00 00 41 54 55 53 65 8b 2d d8 2b 74 65 0f 1f 44 00 00 e8 c6 2c 8b ff fb f4 <65> 8b 2d c5 2b 74 65 0f 1f 44 00 00 5b 5d 41 5c c3 65 8b 05 b4 2b [ 47.938117] RSP: 0018:ffffaf6ac0207ec8 EFLAGS: 00000206 ORIG_RAX: ffffffffffffff13 [ 47.938117] RAX: ffff8f5b3735e200 RBX: 0000000000000003 RCX: 0000000000000001 [ 47.938117] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffff8f5b3735e200 [ 47.938117] RBP: 0000000000000003 R08: 0000000000000001 R09: 0000000000000000 [ 47.938117] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000 [ 47.938117] R13: 0000000000000000 R14: ffff8f5b3735e200 R15: ffff8f5b3735e200 [ 47.938117] ? default_idle+0x1a/0x140 [ 47.938117] do_idle+0x1bc/0x280 [ 47.938117] cpu_startup_entry+0x19/0x20 [ 47.938117] start_secondary+0x187/0x1c0 [ 47.938117] secondary_startup_64+0xa4/0xb0 The reason seems to be that tipc_net_finalize()->tipc_sk_reinit() is calling the function rhashtable_walk_enter() within a timer interrupt with dicoverer::lock set. It is safe to release this lock before we call tipc_net_finalize(), so that is what we do. Signed-off-by: Jon Maloy <[email protected]> --- net/tipc/discover.c | 17 +++++++++-------- 1 file changed, 9 insertions(+), 8 deletions(-) diff --git a/net/tipc/discover.c b/net/tipc/discover.c index 2830709..5fff91c 100644 --- a/net/tipc/discover.c +++ b/net/tipc/discover.c @@ -167,6 +167,7 @@ static bool tipc_disc_addr_trial_msg(struct tipc_discoverer *d, /* Apply trial address if we just left trial period */ if (!trial && !self) { tipc_net_finalize(net, tn->trial_addr); + msg_set_prevnode(buf_msg(d->skb), tn->trial_addr); msg_set_type(buf_msg(d->skb), DSC_REQ_MSG); } @@ -300,14 +301,12 @@ static void tipc_disc_timeout(struct timer_list *t) goto exit; } - /* Trial period over ? */ - if (!time_before(jiffies, tn->addr_trial_end)) { - /* Did we just leave it ? */ - if (!tipc_own_addr(net)) - tipc_net_finalize(net, tn->trial_addr); - - msg_set_type(buf_msg(d->skb), DSC_REQ_MSG); - msg_set_prevnode(buf_msg(d->skb), tipc_own_addr(net)); + /* Did we just leave trial period ? */ + if (!time_before(jiffies, tn->addr_trial_end) && !tipc_own_addr(net)) { + mod_timer(&d->timer, jiffies + TIPC_DISC_INIT); + spin_unlock_bh(&d->lock); + tipc_net_finalize(net, tn->trial_addr); + return; } /* Adjust timeout interval according to discovery phase */ @@ -319,6 +318,8 @@ static void tipc_disc_timeout(struct timer_list *t) d->timer_intv = TIPC_DISC_SLOW; else if (!d->num_nodes && d->timer_intv > TIPC_DISC_FAST) d->timer_intv = TIPC_DISC_FAST; + msg_set_type(buf_msg(d->skb), DSC_REQ_MSG); + msg_set_prevnode(buf_msg(d->skb), tn->trial_addr); } mod_timer(&d->timer, jiffies + d->timer_intv); -- 2.1.4 > -----Original Message----- > From: Ying Xue <[email protected]> > Sent: 5-Nov-18 06:34 > To: Jon Maloy <[email protected]> > Subject: Re: Deadlock warning > > FYI: I have found its root cause. Now I am figuring out how to a bit elegantly > solve it. > > On 10/17/2018 10:36 AM, Jon Maloy wrote: > > Hi Ying, > > > > I sometimes get the following deadlock warning. As I understand it the > > reason is that we are calling rhashtable_walk_enter() in a tmer, i.e., > > in an SW interrupt, something that is not permitted. Do you agree with > > this interpretation? Since you have worked more with these hash tables > > than I have, can you see any easy solution to it. I would hate to > > introduce a work queue to solve this. > > > > > > > > ///jon > > > > > > > > > > > > > > > > [346769.617370] ================================ > > > > [346769.618331] WARNING: inconsistent lock state > > > > [346769.619187] 4.19.0-rc6+ #27 Tainted: G E > > > > [346769.619651] -------------------------------- > > > > [346769.619651] inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage. > > > > [346769.619651] swapper/3/0 [HC0[0]:SC1[3]:HE1:SE0] takes: > > > > [346769.619651] 000000009e3eefe1 (&(&ht->lock)->rlock){+.?.}, at: > > rhashtable_walk_enter+0x36/0xb0 > > > > [346769.619651] {SOFTIRQ-ON-W} state was registered at: > > > > [346769.619651] _raw_spin_lock+0x29/0x60 > > > > [346769.619651] rht_deferred_worker+0x556/0x810 > > > > [346769.619651] process_one_work+0x1f5/0x540 > > > > [346769.619651] worker_thread+0x64/0x3e0 > > > > [346769.619651] kthread+0x112/0x150 > > > > [346769.619651] ret_from_fork+0x3a/0x50 > > > > [346769.619651] irq event stamp: 8581694 > > > > [346769.619651] hardirqs last enabled at (8581694): > > [<ffffffff9107f290>] __local_bh_enable_ip+0x80 /0x100 > > > > [346769.619651] hardirqs last disabled at (8581693): > > [<ffffffff9107f257>] __local_bh_enable_ip+0x47 /0x100 > > > > [346769.619651] softirqs last enabled at (8581678): > > [<ffffffff9107fa1e>] irq_enter+0x5e/0x60 > > > > [346769.619651] softirqs last disabled at (8581679): > > [<ffffffff9107fadb>] irq_exit+0xbb/0xc0 > > > > [346769.619651] > > > > [346769.619651] other info that might help us debug this: > > > > [346769.619651] Possible unsafe locking scenario: > > > > [346769.619651] > > > > [346769.619651] CPU0 > > > > [346769.619651] ---- > > > > [346769.619651] lock(&(&ht->lock)->rlock); > > > > [346769.619651] <Interrupt> > > > > [346769.619651] lock(&(&ht->lock)->rlock); > > > > [346769.619651] > > > > [346769.619651] *** DEADLOCK *** > > > > [346769.619651] > > > > [346769.619651] 2 locks held by swapper/3/0: > > > > [346769.619651] #0: 00000000d9e59d74 ((&d->timer)){+.-.}, at: > > call_timer_fn+0x5/0x280 > > > > [346769.619651] #1: 000000000bf452d8 (&(&d->lock)->rlock){+.-.}, at: > > tipc_disc_timeout+0xc8/0x540 [tipc] > > > > [346769.619651] > > > > [346769.619651] stack backtrace: > > > > [346769.619651] CPU: 3 PID: 0 Comm: swapper/3 Tainted: G E > > 4.19.0-rc6+ #27 > > > > [346769.619651] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011 > > > > [346769.619651] Call Trace: > > > > [346769.619651] <IRQ> > > > > [346769.619651] dump_stack+0x78/0xb3 > > > > [346769.619651] print_usage_bug+0x1ed/0x20b > > > > [346769.619651] mark_lock+0x5ca/0x640 > > > > [346769.619651] __lock_acquire+0x41f/0x1b10 > > > > [346769.619651] ? sched_clock_local+0x12/0x80 > > > > [346769.619651] ? lock_acquire+0xb3/0x190 > > > > [346769.619651] lock_acquire+0xb3/0x190 > > > > [346769.619651] ? rhashtable_walk_enter+0x36/0xb0 > > > > [346769.651609] _raw_spin_lock+0x29/0x60 > > > > [346769.651609] ? rhashtable_walk_enter+0x36/0xb0 > > > > [346769.651609] rhashtable_walk_enter+0x36/0xb0 > > > > [346769.651609] tipc_sk_reinit+0xb0/0x410 [tipc] > > > > [346769.651609] ? mark_held_locks+0x6f/0x90 > > > > [346769.651609] ? __local_bh_enable_ip+0x80/0x100 > > > > [346769.651609] ? debug_show_all_locks+0x170/0x190 > > > > [346769.651609] tipc_net_finalize+0xbf/0x180 [tipc] > > > > [346769.651609] tipc_disc_timeout+0x509/0x540 [tipc] > > _______________________________________________ tipc-discussion mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/tipc-discussion
