Re: v5.9-rc3-rt3 boot time networking lockdep splat
On Tue, 2020-09-08 at 17:06 +0200, Sebastian Andrzej Siewior wrote: > > This should cure it: It did. -Mike
Re: v5.9-rc3-rt3 boot time networking lockdep splat
On Tue, 2020-09-08 at 14:19 +0200, Sebastian Andrzej Siewior wrote: > > This has nothing to do with the bridge but with the fact that you use a > non standard queue class (something else than pfifo_fast). That must be SUSE, I don't muck about in network land. I downloaded a whole library of RFCs decades ago, but turns out that one of those is all the bedtime story you'll ever need. Huge waste of bandwidth :) -Mike
Re: v5.9-rc3-rt3 boot time networking lockdep splat
On 2020-09-08 16:56:20 [+0200], Mike Galbraith wrote:
> On Tue, 2020-09-08 at 14:19 +0200, Sebastian Andrzej Siewior wrote:
> >
> > This has nothing to do with the bridge but with the fact that you use a
> > non standard queue class (something else than pfifo_fast).
>
> That must be SUSE, I don't muck about in network land. I downloaded a
> whole library of RFCs decades ago, but turns out that one of those is
> all the bedtime story you'll ever need. Huge waste of bandwidth :)
I see.
This should cure it:
Subject: [PATCH] net: Properly annotate the try-lock for the seqlock
In patch
("net/Qdisc: use a seqlock instead seqcount")
the seqcount has been replaced with a seqlock to allow to reader to
boost the preempted writer.
The try_write_seqlock() acquired the lock with a try-lock but the
seqcount annotation was "lock".
Opencode write_seqcount_t_begin() and use the try-lock annotation for
lockdep.
Reported-by: Mike Galbraith
Cc: stable...@vger.kernel.org
Signed-off-by: Sebastian Andrzej Siewior
---
include/net/net_seq_lock.h | 9 -
include/net/sch_generic.h | 10 +-
2 files changed, 9 insertions(+), 10 deletions(-)
diff --git a/include/net/net_seq_lock.h b/include/net/net_seq_lock.h
index 95a497a72e511..67710bace7418 100644
--- a/include/net/net_seq_lock.h
+++ b/include/net/net_seq_lock.h
@@ -6,15 +6,6 @@
# define net_seq_begin(__r)read_seqbegin(__r)
# define net_seq_retry(__r, __s) read_seqretry(__r, __s)
-static inline int try_write_seqlock(seqlock_t *sl)
-{
- if (spin_trylock(>lock)) {
- write_seqcount_begin(>seqcount);
- return 1;
- }
- return 0;
-}
-
#else
# define net_seqlock_t seqcount_t
# define net_seq_begin(__r)read_seqcount_begin(__r)
diff --git a/include/net/sch_generic.h b/include/net/sch_generic.h
index 796ac453d9519..40be4443b6bdb 100644
--- a/include/net/sch_generic.h
+++ b/include/net/sch_generic.h
@@ -168,8 +168,16 @@ static inline bool qdisc_run_begin(struct Qdisc *qdisc)
return false;
}
#ifdef CONFIG_PREEMPT_RT
- if (try_write_seqlock(>running))
+ if (spin_trylock(>running.lock)) {
+ seqcount_t *s = >running.seqcount.seqcount;
+ /*
+* Variant of write_seqcount_t_begin() telling lockdep that a
+* trylock was attempted.
+*/
+ raw_write_seqcount_t_begin(s);
+ seqcount_acquire(>dep_map, 0, 1, _RET_IP_);
return true;
+ }
return false;
#else
/* Variant of write_seqcount_begin() telling lockdep a trylock
--
2.28.0
> -Mike
Sebastian
Re: v5.9-rc3-rt3 boot time networking lockdep splat
On 2020-09-05 07:19:10 [+0200], Mike Galbraith wrote: > Lappy, which does not use bridge, boots clean... but lock leakage > pretty darn quickly inspires lockdep to craps its drawers. > > [ 209.00] BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low! > [ 209.001113] turning off the locking correctness validator. > [ 209.001114] CPU: 2 PID: 3773 Comm: Socket Thread Tainted: G SI E > 5.9.0.gc70672d-rt3-rt #8 > [ 209.001117] Hardware name: HP HP Spectre x360 Convertible/804F, BIOS F.47 > 11/22/2017 > [ 209.001118] Call Trace: > [ 209.001123] dump_stack+0x77/0x9b > [ 209.001129] validate_chain+0xf60/0x1230 I have no idea how to debug this based on this report. Can you narrow it down to something? Is Lappy new, got a new something or has a new config switch? I'm just curious if this something or something that was always there but remained undetected. (Your other report was about something that was previously always "broken".) Sebastian
Re: v5.9-rc3-rt3 boot time networking lockdep splat
On Tue, 2020-09-08 at 17:12 +0200, Sebastian Andrzej Siewior wrote: > On 2020-09-05 07:19:10 [+0200], Mike Galbraith wrote: > > Lappy, which does not use bridge, boots clean... but lock leakage > > pretty darn quickly inspires lockdep to craps its drawers. > > > > [ 209.00] BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low! > > [ 209.001113] turning off the locking correctness validator. > > [ 209.001114] CPU: 2 PID: 3773 Comm: Socket Thread Tainted: G SI E > > 5.9.0.gc70672d-rt3-rt #8 > > [ 209.001117] Hardware name: HP HP Spectre x360 Convertible/804F, BIOS > > F.47 11/22/2017 > > [ 209.001118] Call Trace: > > [ 209.001123] dump_stack+0x77/0x9b > > [ 209.001129] validate_chain+0xf60/0x1230 > > I have no idea how to debug this based on this report. Can you narrow > it down to something? I instrumented what I presume is still this problem once upon a time, structures containing locks are allocated/initialized/freed again and again with no cleanup until we increment into the wall. > Is Lappy new, got a new something or has a new config switch? I'm just > curious if this something or something that was always there but > remained undetected. Nah, this is nothing new. Turn lockdep on in RT, it's just a matter of time before it turns itself off. It's usually just not _that_ quick. -Mike
Re: v5.9-rc3-rt3 boot time networking lockdep splat
On 2020-09-08 17:59:31 [+0200], Mike Galbraith wrote: > > I have no idea how to debug this based on this report. Can you narrow > > it down to something? > > I instrumented what I presume is still this problem once upon a time, > structures containing locks are allocated/initialized/freed again and > again with no cleanup until we increment into the wall. Any idea what it is? > > Is Lappy new, got a new something or has a new config switch? I'm just > > curious if this something or something that was always there but > > remained undetected. > > Nah, this is nothing new. Turn lockdep on in RT, it's just a matter of > time before it turns itself off. It's usually just not _that_ quick. Okay. So I have few boxes which run over the weekend without this splat. > -Mike Sebastian
Re: v5.9-rc3-rt3 boot time networking lockdep splat
On 2020-09-05 06:47:29 [+0200], Mike Galbraith wrote:
> [ 22.024936] ==
> [ 22.024936] WARNING: possible circular locking dependency detected
> [ 22.024937] 5.9.0.gc70672d-rt3-rt #8 Tainted: GE
> [ 22.024938] --
> [ 22.024939] ksoftirqd/0/10 is trying to acquire lock:
> [ 22.024941] 983475521278 (>q.lock){+...}-{0:0}, at:
> sch_direct_xmit+0x81/0x2f0
> [ 22.024947]
>but task is already holding lock:
> [ 22.024947] 9834755212b8 (>seqcount#9){+...}-{0:0}, at:
> br_dev_queue_push_xmit+0x7d/0x180 [bridge]
> [ 22.024959]
>which lock already depends on the new lock.
>
> [ 22.024960]
>the existing dependency chain (in reverse order) is:
> [ 22.024961]
>-> #1 (>seqcount#9){+...}-{0:0}:
> [ 22.024963]lock_acquire+0x92/0x3f0
> [ 22.024967]__dev_queue_xmit+0xce7/0xe30
…
>-> #0 (>q.lock){+...}-{0:0}:
> [ 22.025015]validate_chain+0xa81/0x1230
> [ 22.025016]__lock_acquire+0x880/0xbf0
> [ 22.025017]lock_acquire+0x92/0x3f0
> [ 22.025018]rt_spin_lock+0x78/0xd0
> [ 22.025020]sch_direct_xmit+0x81/0x2f0
…
>other info that might help us debug this:
>
> [ 22.025061] Possible unsafe locking scenario:
>
> [ 22.025061]CPU0CPU1
> [ 22.025061]
> [ 22.025062] lock(>seqcount#9);
> [ 22.025064]lock(>q.lock);
> [ 22.025065]lock(>seqcount#9);
> [ 22.025065] lock(>q.lock);
> [ 22.025066]
> *** DEADLOCK ***
This has nothing to do with the bridge but with the fact that you use a
non standard queue class (something else than pfifo_fast).
The flow in CPU1 is the default flow but the second lock is a trylock.
CPU0 is from sch_direct_xmit() where it drops the the
root_lock/qdisc.lock and re-acquires it. This shouldn't fail because the
CPU1 a try-lock of the seqlock first and then the seqcount is "not
acquired". So if we annotate the seqcount as a try_acquire then it
should not do this anymore.
Sebastian
Re: v5.9-rc3-rt3 boot time networking lockdep splat
On Tue, 2020-09-08 at 17:06 +0200, Sebastian Andrzej Siewior wrote: > On 2020-09-08 16:56:20 [+0200], Mike Galbraith wrote: > > On Tue, 2020-09-08 at 14:19 +0200, Sebastian Andrzej Siewior wrote: > > > > > > This has nothing to do with the bridge but with the fact that you use a > > > non standard queue class (something else than pfifo_fast). > > > > That must be SUSE, I don't muck about in network land. I downloaded a > > whole library of RFCs decades ago, but turns out that one of those is > > all the bedtime story you'll ever need. Huge waste of bandwidth :) > > I see. > This should cure it: I'll give that a go. -Mike
Re: v5.9-rc3-rt3 boot time networking lockdep splat
Lappy, which does not use bridge, boots clean... but lock leakage pretty darn quickly inspires lockdep to craps its drawers. [ 209.00] BUG: MAX_LOCKDEP_CHAIN_HLOCKS too low! [ 209.001113] turning off the locking correctness validator. [ 209.001114] CPU: 2 PID: 3773 Comm: Socket Thread Tainted: G SI E 5.9.0.gc70672d-rt3-rt #8 [ 209.001117] Hardware name: HP HP Spectre x360 Convertible/804F, BIOS F.47 11/22/2017 [ 209.001118] Call Trace: [ 209.001123] dump_stack+0x77/0x9b [ 209.001129] validate_chain+0xf60/0x1230 [ 209.001135] __lock_acquire+0x880/0xbf0 [ 209.001139] lock_acquire+0x92/0x3f0 [ 209.001142] ? rcu_note_context_switch+0x118/0x550 [ 209.001146] ? update_load_avg+0x5cc/0x6d0 [ 209.001150] _raw_spin_lock+0x2f/0x40 [ 209.001153] ? rcu_note_context_switch+0x118/0x550 [ 209.001155] rcu_note_context_switch+0x118/0x550 [ 209.001157] ? lockdep_hardirqs_off+0x6e/0xd0 [ 209.001161] __schedule+0xbe/0xb50 [ 209.001163] ? mark_held_locks+0x2d/0x80 [ 209.001166] preempt_schedule_irq+0x44/0xb0 [ 209.001168] irqentry_exit+0x5b/0x80 [ 209.001170] asm_sysvec_reschedule_ipi+0x12/0x20 [ 209.001173] RIP: 0010:debug_lockdep_rcu_enabled+0x23/0x30 [ 209.001175] Code: 0f 0b e9 6d ff ff ff 8b 05 0a a0 c5 00 85 c0 74 21 8b 05 cc da c5 00 85 c0 74 17 65 48 8b 04 25 c0 91 01 00 8b 80 8c 0a 00 00 <85> c0 0f 94 c0 0f b6 c0 f3 c3 cc cc cc 65 48 8b 04 25 c0 91 01 00 [ 209.001178] RSP: 0018:a00202a0f998 EFLAGS: 0202 [ 209.001179] RAX: RBX: 90a8a6d1da20 RCX: 0001 [ 209.001180] RDX: 0002 RSI: 971308fc RDI: 9710b092 [ 209.001181] RBP: 0048 R08: 0001 R09: 0001 [ 209.001181] R10: 90a8a6d1da38 R11: 0006 R12: 97405280 [ 209.001182] R13: 0008 R14: 97405240 R15: 0100 [ 209.001188] rt_spin_unlock+0x2c/0x90 [ 209.001191] __do_softirq+0xc1/0x5b2 [ 209.001194] ? ip_finish_output2+0x264/0xa10 [ 209.001197] __local_bh_enable_ip+0x230/0x290 [ 209.001200] ip_finish_output2+0x288/0xa10 [ 209.001201] ? rcu_read_lock_held+0x32/0x40 [ 209.001206] ? ip_output+0x70/0x200 [ 209.001207] ip_output+0x70/0x200 [ 209.001210] ? __ip_finish_output+0x320/0x320 [ 209.001212] __ip_queue_xmit+0x1f0/0x5d0 [ 209.001216] __tcp_transmit_skb+0xa7f/0xc70 [ 209.001219] ? __alloc_skb+0x7b/0x1b0 [ 209.001222] ? __kmalloc_node_track_caller+0x252/0x330 [ 209.001230] tcp_rcv_established+0x365/0x6d0 [ 209.001233] tcp_v4_do_rcv+0x7e/0x1b0 [ 209.001236] __release_sock+0x89/0x130 [ 209.001239] release_sock+0x3c/0xd0 [ 209.001241] tcp_recvmsg+0x2b9/0xa90 [ 209.001247] inet_recvmsg+0x6b/0x210 [ 209.001252] __sys_recvfrom+0xb8/0x110 [ 209.001256] ? poll_select_finish+0x1f0/0x1f0 [ 209.001261] ? syscall_enter_from_user_mode+0x37/0x340 [ 209.001263] ? syscall_enter_from_user_mode+0x3c/0x340 [ 209.001265] ? lockdep_hardirqs_on+0x78/0x100 [ 209.001268] __x64_sys_recvfrom+0x24/0x30 [ 209.001269] do_syscall_64+0x33/0x40 [ 209.001271] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 209.001274] RIP: 0033:0x7ff2421a230a [ 209.001276] Code: 7c 24 08 4c 89 14 24 e8 44 f8 ff ff 45 31 c9 89 c3 45 31 c0 4c 8b 14 24 4c 89 e2 48 89 ee 48 8b 7c 24 08 b8 2d 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 32 89 df 48 89 04 24 e8 73 f8 ff ff 48 8b 04 [ 209.001278] RSP: 002b:7ff24243a550 EFLAGS: 0246 ORIG_RAX: 002d [ 209.001279] RAX: ffda RBX: RCX: 7ff2421a230a [ 209.001280] RDX: 34da RSI: 7ff21094fb37 RDI: 006b [ 209.001281] RBP: 7ff21094fb37 R08: R09: [ 209.001282] R10: R11: 0246 R12: 34da [ 209.001283] R13: 7ff21094fb37 R14: R15: 7ff20e8a4000
v5.9-rc3-rt3 boot time networking lockdep splat
[ 22.004225] r8169 :03:00.0 eth0: Link is Up - 1Gbps/Full - flow control
off
[ 22.004450] br0: port 1(eth0) entered blocking state
[ 22.004473] br0: port 1(eth0) entered forwarding state
[ 22.006411] IPv6: ADDRCONF(NETDEV_CHANGE): br0: link becomes ready
[ 22.024936] ==
[ 22.024936] WARNING: possible circular locking dependency detected
[ 22.024937] 5.9.0.gc70672d-rt3-rt #8 Tainted: GE
[ 22.024938] --
[ 22.024939] ksoftirqd/0/10 is trying to acquire lock:
[ 22.024941] 983475521278 (>q.lock){+...}-{0:0}, at:
sch_direct_xmit+0x81/0x2f0
[ 22.024947]
but task is already holding lock:
[ 22.024947] 9834755212b8 (>seqcount#9){+...}-{0:0}, at:
br_dev_queue_push_xmit+0x7d/0x180 [bridge]
[ 22.024959]
which lock already depends on the new lock.
[ 22.024960]
the existing dependency chain (in reverse order) is:
[ 22.024961]
-> #1 (>seqcount#9){+...}-{0:0}:
[ 22.024963]lock_acquire+0x92/0x3f0
[ 22.024967]__dev_queue_xmit+0xce7/0xe30
[ 22.024969]br_dev_queue_push_xmit+0x7d/0x180 [bridge]
[ 22.024974]br_forward_finish+0x10a/0x1b0 [bridge]
[ 22.024980]__br_forward+0x17d/0x300 [bridge]
[ 22.024984]br_dev_xmit+0x442/0x570 [bridge]
[ 22.024990]dev_hard_start_xmit+0xc5/0x3f0
[ 22.024992]__dev_queue_xmit+0x9db/0xe30
[ 22.024993]ip6_finish_output2+0x26a/0x990
[ 22.024995]ip6_output+0x6d/0x260
[ 22.024996]mld_sendpack+0x1d9/0x360
[ 22.024999]mld_ifc_timer_expire+0x1f7/0x370
[ 22.025000]call_timer_fn+0xa0/0x390
[ 22.025003]run_timer_softirq+0x59a/0x720
[ 22.025004]__do_softirq+0xc1/0x5b2
[ 22.025006]run_ksoftirqd+0x47/0x70
[ 22.025007]smpboot_thread_fn+0x266/0x320
[ 22.025009]kthread+0x171/0x190
[ 22.025010]ret_from_fork+0x1f/0x30
[ 22.025013]
-> #0 (>q.lock){+...}-{0:0}:
[ 22.025015]validate_chain+0xa81/0x1230
[ 22.025016]__lock_acquire+0x880/0xbf0
[ 22.025017]lock_acquire+0x92/0x3f0
[ 22.025018]rt_spin_lock+0x78/0xd0
[ 22.025020]sch_direct_xmit+0x81/0x2f0
[ 22.025022]__dev_queue_xmit+0xd38/0xe30
[ 22.025023]br_dev_queue_push_xmit+0x7d/0x180 [bridge]
[ 22.025029]br_forward_finish+0x10a/0x1b0 [bridge]
[ 22.025033]__br_forward+0x17d/0x300 [bridge]
[ 22.025039]br_dev_xmit+0x442/0x570 [bridge]
[ 22.025043]dev_hard_start_xmit+0xc5/0x3f0
[ 22.025044]__dev_queue_xmit+0x9db/0xe30
[ 22.025046]ip6_finish_output2+0x26a/0x990
[ 22.025047]ip6_output+0x6d/0x260
[ 22.025049]mld_sendpack+0x1d9/0x360
[ 22.025050]mld_ifc_timer_expire+0x1f7/0x370
[ 22.025052]call_timer_fn+0xa0/0x390
[ 22.025053]run_timer_softirq+0x59a/0x720
[ 22.025054]__do_softirq+0xc1/0x5b2
[ 22.025055]run_ksoftirqd+0x47/0x70
[ 22.025056]smpboot_thread_fn+0x266/0x320
[ 22.025058]kthread+0x171/0x190
[ 22.025059]ret_from_fork+0x1f/0x30
[ 22.025060]
other info that might help us debug this:
[ 22.025061] Possible unsafe locking scenario:
[ 22.025061]CPU0CPU1
[ 22.025061]
[ 22.025062] lock(>seqcount#9);
[ 22.025064]lock(>q.lock);
[ 22.025065]lock(>seqcount#9);
[ 22.025065] lock(>q.lock);
[ 22.025066]
*** DEADLOCK ***
[ 22.025066] 20 locks held by ksoftirqd/0/10:
[ 22.025067] #0: 9a4c7140 (rcu_read_lock){}-{1:3}, at:
rt_spin_lock+0x5/0xd0
[ 22.025071] #1: 98351ec1a6d0 (per_cpu_ptr(_lock.l.lock,
cpu)){}-{3:3}, at: __local_bh_disable_ip+0xbf/0x230
[ 22.025074] #2: 9a4c7140 (rcu_read_lock){}-{1:3}, at:
__local_bh_disable_ip+0xfb/0x230
[ 22.025077] #3: 9a4c7140 (rcu_read_lock){}-{1:3}, at:
rt_spin_lock+0x5/0xd0
[ 22.025080] #4: 98351ec1b338 (>expiry_lock){+...}-{0:0}, at:
run_timer_softirq+0x3e6/0x720
[ 22.025083] #5: b32e8007bd68 ((>mc_ifc_timer)){+...}-{0:0}, at:
call_timer_fn+0x5/0x390
[ 22.025086] #6: 9a4c7140 (rcu_read_lock){}-{1:3}, at:
mld_sendpack+0x5/0x360
[ 22.025090] #7: 9a4c7140 (rcu_read_lock){}-{1:3}, at:
__local_bh_disable_ip+0xfb/0x230
[ 22.025093] #8: 9a4c7100 (rcu_read_lock_bh){}-{1:3}, at:
ip6_finish_output2+0x73/0x990
[ 22.025096] #9: 9a4c7140 (rcu_read_lock){}-{1:3}, at:
__local_bh_disable_ip+0xfb/0x230
[ 22.025097] #10: 9a4c7100 (rcu_read_lock_bh){}-{1:3}, at:
__dev_queue_xmit+0x63/0xe30
[ 22.025100] #11: 9a4c7140 (rcu_read_lock){}-{1:3}, at:
br_dev_xmit+0x5/0x570
