From mboxrd@z Thu Jan  1 00:00:00 1970
From: Tom Parkin <tparkin@katalix.com>
Subject: LOCKDEP complaints in l2tp_xmit_skb()
Date: Wed, 27 Jun 2012 12:11:53 +0100
Message-ID: <20120627111152.GA2531@raven>
Mime-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha1;
	protocol="application/pgp-signature"; boundary="tThc/1wpZn/ma/RB"
To: netdev <netdev@vger.kernel.org>
Return-path: <netdev-owner@vger.kernel.org>
Received: from katalix.com ([82.103.140.233]:54335 "EHLO mail.katalix.com"
	rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP
	id S1752345Ab2F0LL4 (ORCPT <rfc822;netdev@vger.kernel.org>);
	Wed, 27 Jun 2012 07:11:56 -0400
Received: from localhost (cpc2-brad20-0-0-cust774.barn.cable.virginmedia.com [94.168.235.7])
	(using TLSv1 with cipher DHE-RSA-AES128-SHA (128/128 bits))
	(No client certificate requested)
	(Authenticated sender: tom)
	by mail.katalix.com (Postfix) with ESMTPSA id 40AC5A620CC
	for <netdev@vger.kernel.org>; Wed, 27 Jun 2012 12:11:54 +0100 (BST)
Content-Disposition: inline
Sender: netdev-owner@vger.kernel.org
List-ID: <netdev.vger.kernel.org>


--tThc/1wpZn/ma/RB
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable

In testing L2TP ethernet pseudowires I have observed some complaints
=66rom 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 <HOST A ip> \
	remote <HOST B ip> \
	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 <HOST B ip> \
	remote <HOST A ip> \
	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:

=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D
[ 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: [<f85f5bff>] l2tp_xmit_skb+0x13f/0x8e0 [l2tp_=
core]

but task is already holding lock:
 (&(&sch->busylock)->rlock){+.-...}, at: [<c14fb1b2>] 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){+.-...}:
       [<c10a8b48>] lock_acquire+0x88/0x120
       [<c16157bb>] _raw_spin_lock+0x3b/0x70
       [<c1535cf8>] __inet_hash_nolisten+0xb8/0x140
       [<c1536b77>] __inet_hash_connect+0x267/0x2c0
       [<c1536c10>] inet_hash_connect+0x40/0x50
       [<c154e4d4>] tcp_v4_connect+0x2c4/0x510
       [<c156293f>] inet_stream_connect+0x1ff/0x380
       [<c14e30c1>] sys_connect+0xc1/0xe0
       [<c14e3d13>] sys_socketcall+0xe3/0x2e0
       [<c161d89f>] sysenter_do_call+0x12/0x38

-> #0 (slock-AF_INET){+.-...}:
       [<c10a78cc>] __lock_acquire+0xaec/0x17d0
       [<c10a8b48>] lock_acquire+0x88/0x120
       [<c16157bb>] _raw_spin_lock+0x3b/0x70
       [<f85f5bff>] l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core]
       [<f851432d>] l2tp_eth_dev_xmit+0x2d/0x40 [l2tp_eth]
       [<c14fa32f>] dev_hard_start_xmit+0x49f/0x7e0
       [<c1515819>] sch_direct_xmit+0xa9/0x250
       [<c14fa835>] dev_queue_xmit+0x1c5/0xbd0
       [<c159442c>] ip6_finish_output2+0x11c/0x620
       [<c159813f>] ip6_finish_output+0x7f/0x1e0
       [<c15982ea>] ip6_output+0x4a/0x1f0
       [<c15bbddc>] mld_sendpack+0x21c/0x530
       [<c15bc817>] mld_ifc_timer_expire+0x187/0x260
       [<c1055d10>] run_timer_softirq+0x140/0x370
       [<c104da27>] __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: [<c1055c88>] run_timer_softirq+0xb=
8/0x370
 #1:  (rcu_read_lock){.+.+..}, at: [<c15bbbc0>] mld_sendpack+0x0/0x530
 #2:  (rcu_read_lock){.+.+..}, at: [<c159434f>] ip6_finish_output2+0x3f/0x6=
20
 #3:  (rcu_read_lock_bh){.+....}, at: [<c14fa670>] dev_queue_xmit+0x0/0xbd0
 #4:  (&(&sch->busylock)->rlock){+.-...}, at: [<c14fb1b2>] dev_queue_xmit+0=
xb42/0xbd0

stack backtrace:
Pid: 0, comm: swapper/1 Not tainted 3.5.0-rc2-net-lockdep-u64-sync-006-+ #2
Call Trace:
 [<c160b540>] print_circular_bug+0x1b4/0x1be
 [<c10a78cc>] __lock_acquire+0xaec/0x17d0
 [<c10a8b48>] lock_acquire+0x88/0x120
 [<f85f5bff>] ? l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core]
 [<c16157bb>] _raw_spin_lock+0x3b/0x70
 [<f85f5bff>] ? l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core]
 [<f85f5bff>] l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core]
 [<f851432d>] l2tp_eth_dev_xmit+0x2d/0x40 [l2tp_eth]
 [<c14fa32f>] dev_hard_start_xmit+0x49f/0x7e0
 [<c14f9ee1>] ? dev_hard_start_xmit+0x51/0x7e0
 [<c1515819>] sch_direct_xmit+0xa9/0x250
 [<c16157e1>] ? _raw_spin_lock+0x61/0x70
 [<c14fa835>] dev_queue_xmit+0x1c5/0xbd0
 [<c14fa670>] ? dev_hard_start_xmit+0x7e0/0x7e0
 [<c159442c>] ip6_finish_output2+0x11c/0x620
 [<c159434f>] ? ip6_finish_output2+0x3f/0x620
 [<c159813f>] ip6_finish_output+0x7f/0x1e0
 [<c15982ea>] ip6_output+0x4a/0x1f0
 [<c15a6ae0>] ? ip6_blackhole_route+0x2c0/0x2c0
 [<c15bbddc>] mld_sendpack+0x21c/0x530
 [<c15bbbc0>] ? igmp6_group_added+0x170/0x170
 [<c15bc817>] mld_ifc_timer_expire+0x187/0x260
 [<c1055d10>] run_timer_softirq+0x140/0x370
 [<c1055c88>] ? run_timer_softirq+0xb8/0x370
 [<c1085776>] ? rebalance_domains+0x1b6/0x2a0
 [<c15bc690>] ? igmp6_timer_handler+0x80/0x80
 [<c104da27>] __do_softirq+0x97/0x1f0
 [<c104d990>] ? local_bh_enable_ip+0xd0/0xd0
 <IRQ>  [<c104ddce>] ? irq_exit+0x7e/0xa0
 [<c161e0f9>] ? smp_apic_timer_interrupt+0x59/0x88
 [<c12fb498>] ? trace_hardirqs_off_thunk+0xc/0x14
 [<c1616882>] ? apic_timer_interrupt+0x36/0x3c
 [<c10380d5>] ? native_safe_halt+0x5/0x10
 [<c1018bdf>] ? default_idle+0x4f/0x1e0
 [<c1018dc1>] ? amd_e400_idle+0x51/0x100
 [<c10199c9>] ? cpu_idle+0xb9/0xe0
 [<c16038fc>] ? start_secondary+0x1ea/0x1f0



And on AMD64 UP machine:

=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D
 INFO: possible recursive locking detected ]
=2E5.0-rc2-net-lockdep-u64-sync-006-+ #2 Not tainted
--------------------------------------------
wapper/0/0 is trying to acquire lock:
(slock-AF_INET){+.-...}, at: [<f864fbff>] l2tp_xmit_skb+0x13f/0x8e0 [l2tp_c=
ore]

ut task is already holding lock:
(slock-AF_INET){+.-...}, at: [<c154c177>] 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: [<c1055c88>] run_timer_softirq=
+0xb8/0x370
#1:  (slock-AF_INET){+.-...}, at: [<c154c177>] tcp_delack_timer+0x17/0x1e0
#2:  (rcu_read_lock){.+.+..}, at: [<c1531bf0>] ip_queue_xmit+0x0/0x610
#3:  (rcu_read_lock){.+.+..}, at: [<c1531456>] ip_finish_output+0x106/0x710
#4:  (rcu_read_lock_bh){.+....}, at: [<c14fa670>] 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:
[<c10a7b32>] __lock_acquire+0xd52/0x17d0
[<c1017ba8>] ? sched_clock+0x8/0x10
[<c107edbb>] ? sched_clock_local+0xcb/0x1c0
[<c10a8b48>] lock_acquire+0x88/0x120
[<f864fbff>] ? l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core]
[<c16157bb>] _raw_spin_lock+0x3b/0x70
[<f864fbff>] ? l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core]
[<f864fbff>] l2tp_xmit_skb+0x13f/0x8e0 [l2tp_core]
[<f853032d>] l2tp_eth_dev_xmit+0x2d/0x40 [l2tp_eth]
[<c14fa32f>] dev_hard_start_xmit+0x49f/0x7e0
[<c14f9ee1>] ? dev_hard_start_xmit+0x51/0x7e0
[<c1515819>] sch_direct_xmit+0xa9/0x250
[<c16157e1>] ? _raw_spin_lock+0x61/0x70
[<c14fa835>] dev_queue_xmit+0x1c5/0xbd0
[<c14fa670>] ? dev_hard_start_xmit+0x7e0/0x7e0
[<c15065f7>] neigh_resolve_output+0x117/0x230
[<c1514880>] ? eth_rebuild_header+0x80/0x80
[<c1531612>] ip_finish_output+0x2c2/0x710
[<c1531456>] ? ip_finish_output+0x106/0x710
[<c1532770>] ? ip_output+0x60/0x120
[<c10a585b>] ? trace_hardirqs_on+0xb/0x10
[<c153278b>] ip_output+0x7b/0x120
[<c1531b95>] ip_local_out+0x25/0x80
[<c1531d73>] ip_queue_xmit+0x183/0x610
[<c1531bf0>] ? ip_local_out+0x80/0x80
[<c154ecb5>] ? tcp_md5_do_lookup+0x125/0x170
[<c15498c6>] tcp_transmit_skb+0x396/0x970
[<c154bb12>] ? tcp_send_ack+0x32/0x100
[<c154bb9d>] tcp_send_ack+0xbd/0x100
[<c154c271>] tcp_delack_timer+0x111/0x1e0
[<c1055d10>] run_timer_softirq+0x140/0x370
[<c1055c88>] ? run_timer_softirq+0xb8/0x370
[<c154c160>] ? tcp_out_of_resources+0xb0/0xb0
[<c14f88cc>] ? net_rx_action+0x10c/0x210
[<c104da27>] __do_softirq+0x97/0x1f0
[<c104d990>] ? local_bh_enable_ip+0xd0/0xd0
<IRQ>  [<c104ddce>] ? irq_exit+0x7e/0xa0
[<c161e02b>] ? do_IRQ+0x4b/0xc0
[<c161de75>] ? common_interrupt+0x35/0x3c
[<c10380d5>] ? native_safe_halt+0x5/0x10
[<c1018bdf>] ? default_idle+0x4f/0x1e0
[<c1018dc1>] ? amd_e400_idle+0x51/0x100
[<c10199c9>] ? cpu_idle+0xb9/0xe0
[<c15eab3e>] ? rest_init+0x112/0x124
[<c15eaa2c>] ? __read_lock_failed+0x14/0x14
[<c1907a11>] ? start_kernel+0x376/0x37c
[<c19074d6>] ? repair_env_string+0x51/0x51
[<c19072f8>] ? i386_start_kernel+0x9b/0xa2

--=20
Tom Parkin
Katalix Systems Ltd
http://www.katalix.com
Catalysts for your Embedded Linux software development

--tThc/1wpZn/ma/RB
Content-Type: application/pgp-signature; name="signature.asc"
Content-Description: Digital signature

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.11 (GNU/Linux)

iQEcBAEBAgAGBQJP6up4AAoJEJSMBmUKuovQrX4H/ihN89p5Q9UxYewsZAsTHUUp
AiEjdYNQpqSHddCSWWPXRVPXb7E6wLdsaHC2lW8nZpb3p1XPfCujKkNNjnBFj7Kv
2B/dUujOyXM3zD8Tdxkfr/NYJyPPrr+ThpNRjxr5FYylqL6c58tC8IVS+98PdLMA
r/gZzA8dB465jTfXdtFhypIpuXba6RiAMupdQfCBXWOCKxqpvwBEejwx1IAZEKAZ
rMSO+/PUsVNH7fjQBItx6Y+q3epHufvI7HB+opgpZN3qcw37hwdy+sBvJpHAouEa
O22yCeQBfxrJy0zOqMk4oi8ddfoG3ehVRBLHrKJN713ErXgGIL9IlIV8RpKvE8c=
=jOD3
-----END PGP SIGNATURE-----

--tThc/1wpZn/ma/RB--