From mboxrd@z Thu Jan 1 00:00:00 1970 From: Eric Dumazet Subject: Re: r8169 INFO: inconsistent lock state Date: Fri, 30 Apr 2010 22:59:09 +0200 Message-ID: <1272661149.2230.11.camel@edumazet-laptop> References: <20100430182012.GA3329@swordfish.minsk.epam.com> Mime-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: QUOTED-PRINTABLE Cc: Oleg Nesterov , David Miller , Ingo Molnar , Francois Romieu , Peter Zijlstra , netdev@vger.kernel.org, linux-kernel To: Sergey Senozhatsky Return-path: Received: from mail-bw0-f219.google.com ([209.85.218.219]:44609 "EHLO mail-bw0-f219.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1756216Ab0D3U7P (ORCPT ); Fri, 30 Apr 2010 16:59:15 -0400 In-Reply-To: <20100430182012.GA3329@swordfish.minsk.epam.com> Sender: netdev-owner@vger.kernel.org List-ID: Le vendredi 30 avril 2010 =C3=A0 21:20 +0300, Sergey Senozhatsky a =C3=A9= crit : > Hello, >=20 > Yet another one (during resume): >=20 > kernel: [ 1968.334646]=20 > kernel: [ 1968.334648] =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 > kernel: [ 1968.334651] [ INFO: inconsistent lock state ] > kernel: [ 1968.334654] 2.6.34-rc6-dbg #105 > kernel: [ 1968.334656] --------------------------------- > kernel: [ 1968.334659] inconsistent {IN-SOFTIRQ-W} -> {SOFTIRQ-ON-W} = usage. > kernel: [ 1968.334663] events/1/3854 [HC0[0]:SC0[0]:HE1:SE1] takes: > kernel: [ 1968.334666] (&(&table->hash[i].lock)->rlock){+.?...}, at:= [] __udp4_lib_mcast_deliver+0x3c/0x143 > kernel: [ 1968.334678] {IN-SOFTIRQ-W} state was registered at: > kernel: [ 1968.334681] [] __lock_acquire+0x2ba/0xc01 > kernel: [ 1968.334688] [] lock_acquire+0x5e/0x75 > kernel: [ 1968.334693] [] _raw_spin_lock+0x28/0x58 > kernel: [ 1968.334699] [] __udp4_lib_mcast_deliver+0x3c/0= x143 > kernel: [ 1968.334704] [] __udp4_lib_rcv+0x1dc/0x3ac > kernel: [ 1968.334708] [] udp_rcv+0x12/0x14 > kernel: [ 1968.334713] [] ip_local_deliver_finish+0xd2/0x= 137 > kernel: [ 1968.334719] [] NF_HOOK.clone.1+0x38/0x3f > kernel: [ 1968.334724] [] ip_local_deliver+0x3c/0x42 > kernel: [ 1968.334728] [] ip_rcv_finish+0x25c/0x27e > kernel: [ 1968.334733] [] NF_HOOK.clone.1+0x38/0x3f > kernel: [ 1968.334737] [] ip_rcv+0x1a3/0x1c6 > kernel: [ 1968.334741] [] netif_receive_skb+0x38b/0x3ab > kernel: [ 1968.334747] [] rtl8169_rx_interrupt+0x2de/0x3e= b [r8169] > kernel: [ 1968.334756] [] rtl8169_poll+0x28/0x15d [r8169] > kernel: [ 1968.334763] [] net_rx_action+0x93/0x181 > kernel: [ 1968.334767] [] __do_softirq+0x88/0x10c > kernel: [ 1968.334773] [] do_softirq+0x2f/0x47 > kernel: [ 1968.334778] [] irq_exit+0x38/0x75 > kernel: [ 1968.334782] [] do_IRQ+0x79/0x8d > kernel: [ 1968.334787] [] common_interrupt+0x35/0x3c > kernel: [ 1968.334791] [] cpuidle_idle_call+0x6a/0xa0 > kernel: [ 1968.334799] [] cpu_idle+0x89/0xbe > kernel: [ 1968.334802] [] rest_init+0xd1/0xd6 > kernel: [ 1968.334807] [] start_kernel+0x339/0x33e > kernel: [ 1968.334813] [] i386_start_kernel+0xc9/0xd0 > kernel: [ 1968.334818] irq event stamp: 63 > kernel: [ 1968.334820] hardirqs last enabled at (63): [] k= mem_cache_free+0x83/0x8f > kernel: [ 1968.334828] hardirqs last disabled at (62): [] k= mem_cache_free+0x2a/0x8f > kernel: [ 1968.334833] softirqs last enabled at (60): [] r= cu_read_unlock_bh+0x1c/0x1e > kernel: [ 1968.334839] softirqs last disabled at (58): [] r= cu_read_lock_bh+0x8/0x26 > kernel: [ 1968.334845]=20 > kernel: [ 1968.334846] other info that might help us debug this: > kernel: [ 1968.334849] 5 locks held by events/1/3854: > kernel: [ 1968.334851] #0: (events){+.+.+.}, at: [] worke= r_thread+0x128/0x23c > kernel: [ 1968.334859] #1: ((&(&tp->task)->work)){+.+...}, at: [] worker_thread+0x128/0x23c > kernel: [ 1968.334865] #2: (rtnl_mutex){+.+.+.}, at: [] r= tnl_lock+0xf/0x11 > kernel: [ 1968.334871] #3: (rcu_read_lock){.+.+..}, at: [= ] rcu_read_lock+0x0/0x2b > kernel: [ 1968.334877] #4: (rcu_read_lock){.+.+..}, at: [= ] rcu_read_lock+0x0/0x2b > kernel: [ 1968.334884]=20 > kernel: [ 1968.334885] stack backtrace: > kernel: [ 1968.334888] Pid: 3854, comm: events/1 Not tainted 2.6.34-r= c6-dbg #105 > kernel: [ 1968.334891] Call Trace: > kernel: [ 1968.334895] [] ? printk+0xf/0x11 > kernel: [ 1968.334901] [] valid_state+0x133/0x141 > kernel: [ 1968.334906] [] mark_lock+0xcf/0x1bc > kernel: [ 1968.334911] [] ? check_usage_backwards+0x0/0x72 > kernel: [ 1968.334915] [] __lock_acquire+0x32c/0xc01 > kernel: [ 1968.334922] [] ? fib_table_lookup+0x81/0x8e > kernel: [ 1968.334927] [] ? __cycles_2_ns+0xf/0x3e > kernel: [ 1968.334932] [] ? rcu_read_unlock+0x0/0x38 > kernel: [ 1968.334937] [] ? native_sched_clock+0x49/0x4f > kernel: [ 1968.334943] [] ? sched_clock_local+0x11/0x11f > kernel: [ 1968.334948] [] lock_acquire+0x5e/0x75 > kernel: [ 1968.334953] [] ? __udp4_lib_mcast_deliver+0x3c/= 0x143 > kernel: [ 1968.334958] [] _raw_spin_lock+0x28/0x58 > kernel: [ 1968.334963] [] ? __udp4_lib_mcast_deliver+0x3c/= 0x143 > kernel: [ 1968.334967] [] __udp4_lib_mcast_deliver+0x3c/0x= 143 > kernel: [ 1968.334973] [] ? sched_clock_cpu+0x121/0x131 > kernel: [ 1968.334978] [] ? rcu_read_unlock+0x0/0x38 > kernel: [ 1968.334983] [] ? sched_clock_cpu+0x121/0x131 > kernel: [ 1968.334988] [] ? __lock_acquire+0xbf2/0xc01 > kernel: [ 1968.334994] [] ? rcu_read_unlock+0x2d/0x38 > kernel: [ 1968.334998] [] ? ip_route_input+0x101/0xaf4 > kernel: [ 1968.335003] [] __udp4_lib_rcv+0x1dc/0x3ac > kernel: [ 1968.335008] [] udp_rcv+0x12/0x14 > kernel: [ 1968.335013] [] ip_local_deliver_finish+0xd2/0x1= 37 > kernel: [ 1968.335017] [] ? ip_local_deliver_finish+0x0/0x= 137 > kernel: [ 1968.335022] [] NF_HOOK.clone.1+0x38/0x3f > kernel: [ 1968.335026] [] ip_local_deliver+0x3c/0x42 > kernel: [ 1968.335031] [] ? ip_local_deliver_finish+0x0/0x= 137 > kernel: [ 1968.335035] [] ip_rcv_finish+0x25c/0x27e > kernel: [ 1968.335040] [] ? ip_rcv_finish+0x0/0x27e > kernel: [ 1968.335044] [] NF_HOOK.clone.1+0x38/0x3f > kernel: [ 1968.335048] [] ip_rcv+0x1a3/0x1c6 > kernel: [ 1968.335052] [] ? ip_rcv_finish+0x0/0x27e > kernel: [ 1968.335057] [] netif_receive_skb+0x38b/0x3ab > kernel: [ 1968.335066] [] rtl8169_rx_interrupt+0x2de/0x3eb= [r8169] > kernel: [ 1968.335073] [] rtl8169_reset_task+0x33/0xe8 [r8= 169] So we have following illegal chain (process context, not softirq) rtl8169_reset_task() -> tl8169_rx_interrupt() -> netif_receive_skb() And normally, commit 630b943c tried to change this chain to : rtl8169_reset_task() -> tl8169_rx_interrupt() -> netif_rx() I have no idea why it doesnt work. commit 630b943c182d1aed69f244405131902fbcba7ec6 Author: Eric Dumazet Date: Wed Mar 31 02:08:31 2010 +0000 r8169: Fix rtl8169_rx_interrupt() =20 In case a reset is performed, rtl8169_rx_interrupt() is called from process context instead of softirq context. Special care must be ta= ken to call appropriate network core services (netif_rx() instead of netif_receive_skb()). VLAN handling also corrected. =20 Reported-by: Sergey Senozhatsky Tested-by: Sergey Senozhatsky Diagnosed-by: Oleg Nesterov Signed-off-by: Eric Dumazet Signed-off-by: David S. Miller diff --git a/drivers/net/r8169.c b/drivers/net/r8169.c index 964305c..f7ffa5d 100644 --- a/drivers/net/r8169.c +++ b/drivers/net/r8169.c @@ -1054,14 +1054,14 @@ static void rtl8169_vlan_rx_register(struct net= _device *dev, } =20 static int rtl8169_rx_vlan_skb(struct rtl8169_private *tp, struct RxDe= sc *desc, - struct sk_buff *skb) + struct sk_buff *skb, int polling) { u32 opts2 =3D le32_to_cpu(desc->opts2); struct vlan_group *vlgrp =3D tp->vlgrp; int ret; =20 if (vlgrp && (opts2 & RxVlanTag)) { - vlan_hwaccel_receive_skb(skb, vlgrp, swab16(opts2 & 0xffff)); + __vlan_hwaccel_rx(skb, vlgrp, swab16(opts2 & 0xffff), polling); ret =3D 0; } else ret =3D -1; @@ -1078,7 +1078,7 @@ static inline u32 rtl8169_tx_vlan_tag(struct rtl8= 169_private *tp, } =20 static int rtl8169_rx_vlan_skb(struct rtl8169_private *tp, struct RxDe= sc *desc, - struct sk_buff *skb) + struct sk_buff *skb, int polling) { return -1; } @@ -4467,12 +4467,20 @@ out: return done; } =20 +/* + * Warning : rtl8169_rx_interrupt() might be called : + * 1) from NAPI (softirq) context + * (polling =3D 1 : we should call netif_receive_skb()) + * 2) from process context (rtl8169_reset_task()) + * (polling =3D 0 : we must call netif_rx() instead) + */ static int rtl8169_rx_interrupt(struct net_device *dev, struct rtl8169_private *tp, void __iomem *ioaddr, u32 budget) { unsigned int cur_rx, rx_left; unsigned int delta, count; + int polling =3D (budget !=3D ~(u32)0) ? 1 : 0; =20 cur_rx =3D tp->cur_rx; rx_left =3D NUM_RX_DESC + tp->dirty_rx - cur_rx; @@ -4534,8 +4542,12 @@ static int rtl8169_rx_interrupt(struct net_devic= e *dev, skb_put(skb, pkt_size); skb->protocol =3D eth_type_trans(skb, dev); =20 - if (rtl8169_rx_vlan_skb(tp, desc, skb) < 0) - netif_receive_skb(skb); + if (rtl8169_rx_vlan_skb(tp, desc, skb, polling) < 0) { + if (likely(polling)) + netif_receive_skb(skb); + else + netif_rx(skb); + } =20 dev->stats.rx_bytes +=3D pkt_size; dev->stats.rx_packets++;