From mboxrd@z Thu Jan 1 00:00:00 1970 From: Eric Dumazet Subject: Re: LOCKDEP complaints in l2tp_xmit_skb() Date: Thu, 28 Jun 2012 08:56:12 +0200 Message-ID: <1340866572.26242.312.camel@edumazet-glaptop> References: <20120627111152.GA2531@raven> Mime-Version: 1.0 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: 7bit Cc: netdev To: Tom Parkin Return-path: Received: from mail-bk0-f46.google.com ([209.85.214.46]:36771 "EHLO mail-bk0-f46.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754370Ab2F1G4R (ORCPT ); Thu, 28 Jun 2012 02:56:17 -0400 Received: by bkcji2 with SMTP id ji2so1667781bkc.19 for ; Wed, 27 Jun 2012 23:56:16 -0700 (PDT) In-Reply-To: <20120627111152.GA2531@raven> Sender: netdev-owner@vger.kernel.org List-ID: On Wed, 2012-06-27 at 12:11 +0100, Tom Parkin wrote: > In testing L2TP ethernet pseudowires I have observed some complaints > from lockdep due to circular/recursive locking in l2tp_xmit_skb(). > > I'm testing the -net tree, which includes Eric's recent patches to > squash another lockdep error by converting l2tp to LLTX. Git hash > d7ffde35e31a811. > > My test setup consists of two AMD64 boxes, both running 32bit kernels. > One box is SMP, the other UP. My test procedure consists of creating > an L2TP tunnel containing N ethernet pseudowires. I then run N iperf > sessions across the N pseudowires. The simplest configuration is: > > > [On HOST A] > ip l2tp add tunnel \ > tunnel_id 1 \ > peer_tunnel_id 1 \ > local \ > remote \ > udp_sport 9999 \ > udp_dport 9999 > ip add session \ > tunnel_id 1 \ > session_id 1 \ > peer_session_id 1 > ip addr add 172.16.0.1 \ > peer 172.16.0.2/24 \ > broadcast 172.16.0.255 \ > dev l2tpeth0 > ip link set l2tpeth0 up > iperf -s -B 172.16.0.1 > > [On HOST B] > ip l2tp add tunnel \ > tunnel_id 1 \ > peer_tunnel_id 1 \ > local \ > remote \ > udp_sport 9999 \ > udp_dport 9999 > ip add session \ > tunnel_id 1 \ > session_id 1 \ > peer_session_id 1 > ip addr add 172.16.0.2 \ > peer 172.16.0.1/24 \ > broadcast 172.16.0.255 \ > dev l2tpeth0 > ip link set l2tpeth0 up > iperf -c 172.16.0.1 > > > If I run four concurrent iperf sessions across four pseudowires I > see lockdep complaints on both SMP and UP boxes. > > Lockdep output for the AMD64 SMP machine: > > ====================================================== > [ INFO: possible circular locking dependency detected ] > 3.5.0-rc2-net-lockdep-u64-sync-006-+ #2 Not tainted > ------------------------------------------------------- > swapper/1/0 is trying to acquire lock: > (slock-AF_INET){+.-...}, at: [] l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core] > > but task is already holding lock: > (&(&sch->busylock)->rlock){+.-...}, at: [] dev_queue_xmit+0xb42/0xbd0 > > which lock already depends on the new lock. > > > the existing dependency chain (in reverse order) is: > > -> #1 (&(&sch->busylock)->rlock){+.-...}: > [] lock_acquire+0x88/0x120 > [] _raw_spin_lock+0x3b/0x70 > [] __inet_hash_nolisten+0xb8/0x140 > [] __inet_hash_connect+0x267/0x2c0 > [] inet_hash_connect+0x40/0x50 > [] tcp_v4_connect+0x2c4/0x510 > [] inet_stream_connect+0x1ff/0x380 > [] sys_connect+0xc1/0xe0 > [] sys_socketcall+0xe3/0x2e0 > [] sysenter_do_call+0x12/0x38 > > -> #0 (slock-AF_INET){+.-...}: > [] __lock_acquire+0xaec/0x17d0 > [] lock_acquire+0x88/0x120 > [] _raw_spin_lock+0x3b/0x70 > [] l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core] > [] l2tp_eth_dev_xmit+0x2d/0x40 [l2tp_eth] > [] dev_hard_start_xmit+0x49f/0x7e0 > [] sch_direct_xmit+0xa9/0x250 > [] dev_queue_xmit+0x1c5/0xbd0 > [] ip6_finish_output2+0x11c/0x620 > [] ip6_finish_output+0x7f/0x1e0 > [] ip6_output+0x4a/0x1f0 > [] mld_sendpack+0x21c/0x530 > [] mld_ifc_timer_expire+0x187/0x260 > [] run_timer_softirq+0x140/0x370 > [] __do_softirq+0x97/0x1f0 > > other info that might help us debug this: > > Possible unsafe locking scenario: > > CPU0 CPU1 > ---- ---- > lock(&(&sch->busylock)->rlock); > lock(slock-AF_INET); > lock(&(&sch->busylock)->rlock); > lock(slock-AF_INET); > > *** DEADLOCK *** > > 5 locks held by swapper/1/0: > #0: (&idev->mc_ifc_timer){+.-...}, at: [] run_timer_softirq+0xb8/0x370 > #1: (rcu_read_lock){.+.+..}, at: [] mld_sendpack+0x0/0x530 > #2: (rcu_read_lock){.+.+..}, at: [] ip6_finish_output2+0x3f/0x620 > #3: (rcu_read_lock_bh){.+....}, at: [] dev_queue_xmit+0x0/0xbd0 > #4: (&(&sch->busylock)->rlock){+.-...}, at: [] dev_queue_xmit+0xb42/0xbd0 > > stack backtrace: > Pid: 0, comm: swapper/1 Not tainted 3.5.0-rc2-net-lockdep-u64-sync-006-+ #2 > Call Trace: > [] print_circular_bug+0x1b4/0x1be > [] __lock_acquire+0xaec/0x17d0 > [] lock_acquire+0x88/0x120 > [] ? l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core] > [] _raw_spin_lock+0x3b/0x70 > [] ? l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core] > [] l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core] > [] l2tp_eth_dev_xmit+0x2d/0x40 [l2tp_eth] > [] dev_hard_start_xmit+0x49f/0x7e0 > [] ? dev_hard_start_xmit+0x51/0x7e0 > [] sch_direct_xmit+0xa9/0x250 > [] ? _raw_spin_lock+0x61/0x70 > [] dev_queue_xmit+0x1c5/0xbd0 > [] ? dev_hard_start_xmit+0x7e0/0x7e0 > [] ip6_finish_output2+0x11c/0x620 > [] ? ip6_finish_output2+0x3f/0x620 > [] ip6_finish_output+0x7f/0x1e0 > [] ip6_output+0x4a/0x1f0 > [] ? ip6_blackhole_route+0x2c0/0x2c0 > [] mld_sendpack+0x21c/0x530 > [] ? igmp6_group_added+0x170/0x170 > [] mld_ifc_timer_expire+0x187/0x260 > [] run_timer_softirq+0x140/0x370 > [] ? run_timer_softirq+0xb8/0x370 > [] ? rebalance_domains+0x1b6/0x2a0 > [] ? igmp6_timer_handler+0x80/0x80 > [] __do_softirq+0x97/0x1f0 > [] ? local_bh_enable_ip+0xd0/0xd0 > [] ? irq_exit+0x7e/0xa0 > [] ? smp_apic_timer_interrupt+0x59/0x88 > [] ? trace_hardirqs_off_thunk+0xc/0x14 > [] ? apic_timer_interrupt+0x36/0x3c > [] ? native_safe_halt+0x5/0x10 > [] ? default_idle+0x4f/0x1e0 > [] ? amd_e400_idle+0x51/0x100 > [] ? cpu_idle+0xb9/0xe0 > [] ? start_secondary+0x1ea/0x1f0 > > > > And on AMD64 UP machine: > > ============================================ > INFO: possible recursive locking detected ] > .5.0-rc2-net-lockdep-u64-sync-006-+ #2 Not tainted > -------------------------------------------- > wapper/0/0 is trying to acquire lock: > (slock-AF_INET){+.-...}, at: [] l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core] > > ut task is already holding lock: > (slock-AF_INET){+.-...}, at: [] tcp_delack_timer+0x17/0x1e0 > > ther info that might help us debug this: > Possible unsafe locking scenario: > > CPU0 > ---- > lock(slock-AF_INET); > lock(slock-AF_INET); > > *** DEADLOCK *** > > May be due to missing lock nesting notation > > locks held by swapper/0/0: > #0: (&icsk->icsk_delack_timer){+.-...}, at: [] run_timer_softirq+0xb8/0x370 > #1: (slock-AF_INET){+.-...}, at: [] tcp_delack_timer+0x17/0x1e0 > #2: (rcu_read_lock){.+.+..}, at: [] ip_queue_xmit+0x0/0x610 > #3: (rcu_read_lock){.+.+..}, at: [] ip_finish_output+0x106/0x710 > #4: (rcu_read_lock_bh){.+....}, at: [] dev_queue_xmit+0x0/0xbd0 > > tack backtrace: > id: 0, comm: swapper/0 Not tainted 3.5.0-rc2-net-lockdep-u64-sync-006-+ #2 > all Trace: > [] __lock_acquire+0xd52/0x17d0 > [] ? sched_clock+0x8/0x10 > [] ? sched_clock_local+0xcb/0x1c0 > [] lock_acquire+0x88/0x120 > [] ? l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core] > [] _raw_spin_lock+0x3b/0x70 > [] ? l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core] > [] l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core] > [] l2tp_eth_dev_xmit+0x2d/0x40 [l2tp_eth] > [] dev_hard_start_xmit+0x49f/0x7e0 > [] ? dev_hard_start_xmit+0x51/0x7e0 > [] sch_direct_xmit+0xa9/0x250 > [] ? _raw_spin_lock+0x61/0x70 > [] dev_queue_xmit+0x1c5/0xbd0 > [] ? dev_hard_start_xmit+0x7e0/0x7e0 > [] neigh_resolve_output+0x117/0x230 > [] ? eth_rebuild_header+0x80/0x80 > [] ip_finish_output+0x2c2/0x710 > [] ? ip_finish_output+0x106/0x710 > [] ? ip_output+0x60/0x120 > [] ? trace_hardirqs_on+0xb/0x10 > [] ip_output+0x7b/0x120 > [] ip_local_out+0x25/0x80 > [] ip_queue_xmit+0x183/0x610 > [] ? ip_local_out+0x80/0x80 > [] ? tcp_md5_do_lookup+0x125/0x170 > [] tcp_transmit_skb+0x396/0x970 > [] ? tcp_send_ack+0x32/0x100 > [] tcp_send_ack+0xbd/0x100 > [] tcp_delack_timer+0x111/0x1e0 > [] run_timer_softirq+0x140/0x370 > [] ? run_timer_softirq+0xb8/0x370 > [] ? tcp_out_of_resources+0xb0/0xb0 > [] ? net_rx_action+0x10c/0x210 > [] __do_softirq+0x97/0x1f0 > [] ? local_bh_enable_ip+0xd0/0xd0 > [] ? irq_exit+0x7e/0xa0 > [] ? do_IRQ+0x4b/0xc0 > [] ? common_interrupt+0x35/0x3c > [] ? native_safe_halt+0x5/0x10 > [] ? default_idle+0x4f/0x1e0 > [] ? amd_e400_idle+0x51/0x100 > [] ? cpu_idle+0xb9/0xe0 > [] ? rest_init+0x112/0x124 > [] ? __read_lock_failed+0x14/0x14 > [] ? start_kernel+0x376/0x37c > [] ? repair_env_string+0x51/0x51 > [] ? i386_start_kernel+0x9b/0xa2 > Hi Tom Could you please test following patch ? Thanks ! [PATCH] net: Qdisc busylock gets its own lockdep class Tom Parkin reported following LOCKDEP splat : ====================================================== [ INFO: possible circular locking dependency detected ] 3.5.0-rc2-net-lockdep-u64-sync-006-+ #2 Not tainted ------------------------------------------------------- swapper/1/0 is trying to acquire lock: (slock-AF_INET){+.-...}, at: [] l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core] but task is already holding lock: (&(&sch->busylock)->rlock){+.-...}, at: [] dev_queue_xmit +0xb42/0xbd0 which lock already depends on the new lock. the existing dependency chain (in reverse order) is: -> #1 (&(&sch->busylock)->rlock){+.-...}: [] lock_acquire+0x88/0x120 [] _raw_spin_lock+0x3b/0x70 [] __inet_hash_nolisten+0xb8/0x140 [] __inet_hash_connect+0x267/0x2c0 [] inet_hash_connect+0x40/0x50 [] tcp_v4_connect+0x2c4/0x510 [] inet_stream_connect+0x1ff/0x380 [] sys_connect+0xc1/0xe0 [] sys_socketcall+0xe3/0x2e0 [] sysenter_do_call+0x12/0x38 -> #0 (slock-AF_INET){+.-...}: [] __lock_acquire+0xaec/0x17d0 [] lock_acquire+0x88/0x120 [] _raw_spin_lock+0x3b/0x70 [] l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core] [] l2tp_eth_dev_xmit+0x2d/0x40 [l2tp_eth] [] dev_hard_start_xmit+0x49f/0x7e0 [] sch_direct_xmit+0xa9/0x250 [] dev_queue_xmit+0x1c5/0xbd0 [] ip6_finish_output2+0x11c/0x620 [] ip6_finish_output+0x7f/0x1e0 [] ip6_output+0x4a/0x1f0 [] mld_sendpack+0x21c/0x530 [] mld_ifc_timer_expire+0x187/0x260 [] run_timer_softirq+0x140/0x370 [] __do_softirq+0x97/0x1f0 other info that might help us debug this: Possible unsafe locking scenario: CPU0 CPU1 ---- ---- lock(&(&sch->busylock)->rlock); lock(slock-AF_INET); lock(&(&sch->busylock)->rlock); lock(slock-AF_INET); *** DEADLOCK *** 5 locks held by swapper/1/0: #0: (&idev->mc_ifc_timer){+.-...}, at: [] run_timer_softirq +0xb8/0x370 #1: (rcu_read_lock){.+.+..}, at: [] mld_sendpack+0x0/0x530 #2: (rcu_read_lock){.+.+..}, at: [] ip6_finish_output2 +0x3f/0x620 #3: (rcu_read_lock_bh){.+....}, at: [] dev_queue_xmit +0x0/0xbd0 #4: (&(&sch->busylock)->rlock){+.-...}, at: [] dev_queue_xmit+0xb42/0xbd0 stack backtrace: Pid: 0, comm: swapper/1 Not tainted 3.5.0-rc2-net-lockdep-u64-sync-006-+ #2 Call Trace: [] print_circular_bug+0x1b4/0x1be [] __lock_acquire+0xaec/0x17d0 [] lock_acquire+0x88/0x120 [] ? l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core] [] _raw_spin_lock+0x3b/0x70 [] ? l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core] [] l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core] [] l2tp_eth_dev_xmit+0x2d/0x40 [l2tp_eth] [] dev_hard_start_xmit+0x49f/0x7e0 [] ? dev_hard_start_xmit+0x51/0x7e0 [] sch_direct_xmit+0xa9/0x250 [] ? _raw_spin_lock+0x61/0x70 [] dev_queue_xmit+0x1c5/0xbd0 [] ? dev_hard_start_xmit+0x7e0/0x7e0 [] ip6_finish_output2+0x11c/0x620 [] ? ip6_finish_output2+0x3f/0x620 [] ip6_finish_output+0x7f/0x1e0 [] ip6_output+0x4a/0x1f0 [] ? ip6_blackhole_route+0x2c0/0x2c0 [] mld_sendpack+0x21c/0x530 [] ? igmp6_group_added+0x170/0x170 [] mld_ifc_timer_expire+0x187/0x260 [] run_timer_softirq+0x140/0x370 [] ? run_timer_softirq+0xb8/0x370 [] ? rebalance_domains+0x1b6/0x2a0 [] ? igmp6_timer_handler+0x80/0x80 [] __do_softirq+0x97/0x1f0 [] ? local_bh_enable_ip+0xd0/0xd0 [] ? irq_exit+0x7e/0xa0 [] ? smp_apic_timer_interrupt+0x59/0x88 [] ? trace_hardirqs_off_thunk+0xc/0x14 [] ? apic_timer_interrupt+0x36/0x3c [] ? native_safe_halt+0x5/0x10 [] ? default_idle+0x4f/0x1e0 [] ? amd_e400_idle+0x51/0x100 [] ? cpu_idle+0xb9/0xe0 [] ? start_secondary+0x1ea/0x1f0 Instruct lockdep that each Qdisc busylock is independant, or else bonding or various tunnels can trigger a splat. Reported-by: Tom Parkin Signed-off-by: Eric Dumazet --- include/net/sch_generic.h | 1 + net/sched/sch_generic.c | 1 + 2 files changed, 2 insertions(+) diff --git a/include/net/sch_generic.h b/include/net/sch_generic.h index 9d7d54a..a45b501 100644 --- a/include/net/sch_generic.h +++ b/include/net/sch_generic.h @@ -83,6 +83,7 @@ struct Qdisc { struct rcu_head rcu_head; spinlock_t busylock; u32 limit; + struct lock_class_key busylock_key; }; static inline bool qdisc_is_running(const struct Qdisc *qdisc) diff --git a/net/sched/sch_generic.c b/net/sched/sch_generic.c index 511323e..3357c6d 100644 --- a/net/sched/sch_generic.c +++ b/net/sched/sch_generic.c @@ -572,6 +572,7 @@ struct Qdisc *qdisc_alloc(struct netdev_queue *dev_queue, INIT_LIST_HEAD(&sch->list); skb_queue_head_init(&sch->q); spin_lock_init(&sch->busylock); + lockdep_set_class(&sch->busylock, &sch->busylock_key); sch->ops = ops; sch->enqueue = ops->enqueue; sch->dequeue = ops->dequeue;