Re: inconsistent lock state with usbnet/asix usb ethernet and xhci
From: Marek Szyprowski
Date: Tue Feb 27 2018 - 09:42:23 EST
Hi Eric,
On 2018-02-27 15:07, Eric Dumazet wrote:
On Tue, 2018-02-27 at 08:26 +0100, Marek Szyprowski wrote:
I've noticed that USBnet/ASIX AX88772B USB driver produces deplock kernel
warning ("inconsistent lock state") on Chromebook2 Peach-PIT board. No
special activity is needed to reproduce this issue, it happens almost
on every boot. ASIX USB ethernet is connected to XHCI USB host controller
on that board. Is it a known issue? Frankly I have no idea where to look
to fix it. The same adapter connected to EHCI ports on other boards based
on the same SoC works fine without any warnings.
Here are some more information from that board:
# lsusb
Bus 006 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 005 Device 002: ID 0b95:772b ASIX Electronics Corp. AX88772B
Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 004 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 001 Device 002: ID 2232:1056 Silicon Motion
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
# lsusb -t
/:Â Bus 06.Port 1: Dev 1, Class=root_hub, Driver=xhci-hcd/1p, 5000M
/:Â Bus 05.Port 1: Dev 1, Class=root_hub, Driver=xhci-hcd/1p, 480M
ÂÂÂ |__ Port 1: Dev 2, If 0, Class=Vendor Specific Class, Driver=asix, 480M
/:Â Bus 04.Port 1: Dev 1, Class=root_hub, Driver=xhci-hcd/1p, 5000M
/:Â Bus 03.Port 1: Dev 1, Class=root_hub, Driver=xhci-hcd/1p, 480M
/:Â Bus 02.Port 1: Dev 1, Class=root_hub, Driver=exynos-ohci/3p, 12M
/:Â Bus 01.Port 1: Dev 1, Class=root_hub, Driver=exynos-ehci/3p, 480M
ÂÂÂ |__ Port 1: Dev 2, If 0, Class=Video, Driver=, 480M
ÂÂÂ |__ Port 1: Dev 2, If 1, Class=Video, Driver=, 480M
And the log with mentioned warning:
[ÂÂ 17.768040] ================================
[ÂÂ 17.772239] WARNING: inconsistent lock state
[ÂÂ 17.776511] 4.16.0-rc3-next-20180227-00007-g876c53a7493c #453 Not tainted
[ÂÂ 17.783329] --------------------------------
[ÂÂ 17.787580] inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
[ÂÂ 17.793607] swapper/0/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
[ÂÂ 17.798751]Â (&syncp->seq#5){?.-.}, at: [<9b22e5f0>]
asix_rx_fixup_internal+0x188/0x288
[ÂÂ 17.806790] {IN-HARDIRQ-W} state was registered at:
[ÂÂ 17.811677]ÂÂ tx_complete+0x100/0x208
[ÂÂ 17.815319]ÂÂ __usb_hcd_giveback_urb+0x60/0xf0
[ÂÂ 17.819770]ÂÂ xhci_giveback_urb_in_irq+0xa8/0x240
[ÂÂ 17.824469]ÂÂ xhci_td_cleanup+0xf4/0x16c
[ÂÂ 17.828367]ÂÂ xhci_irq+0xe74/0x2240
[ÂÂ 17.831827]ÂÂ usb_hcd_irq+0x24/0x38
[ÂÂ 17.835343]ÂÂ __handle_irq_event_percpu+0x98/0x510
[ÂÂ 17.840111]ÂÂ handle_irq_event_percpu+0x1c/0x58
[ÂÂ 17.844623]ÂÂ handle_irq_event+0x38/0x5c
[ÂÂ 17.848519]ÂÂ handle_fasteoi_irq+0xa4/0x138
[ÂÂ 17.852681]ÂÂ generic_handle_irq+0x18/0x28
[ÂÂ 17.856760]ÂÂ __handle_domain_irq+0x6c/0xe4
[ÂÂ 17.860941]ÂÂ gic_handle_irq+0x54/0xa0
[ÂÂ 17.864666]ÂÂ __irq_svc+0x70/0xb0
[ÂÂ 17.867964]ÂÂ arch_cpu_idle+0x20/0x3c
[ÂÂ 17.871578]ÂÂ arch_cpu_idle+0x20/0x3c
[ÂÂ 17.875190]ÂÂ do_idle+0x144/0x218
[ÂÂ 17.878468]ÂÂ cpu_startup_entry+0x18/0x1c
[ÂÂ 17.882454]ÂÂ start_kernel+0x394/0x400
[ÂÂ 17.886177] irq event stamp: 161912
[ 17.889616] hardirqs last enabled at (161912): [<7bedfacf>]
__netdev_alloc_skb+0xcc/0x140
[ÂÂ 17.897893] hardirqs last disabled at (161911): [<d58261d0>]
__netdev_alloc_skb+0x94/0x140
[ÂÂ 17.904903] exynos5-hsi2c 12ca0000.i2c: tx timeout
[ 17.906116] softirqs last enabled at (161904): [<387102ff>]
irq_enter+0x78/0x80
[ÂÂ 17.906123] softirqs last disabled at (161905): [<cf4c628e>]
irq_exit+0x134/0x158
[ÂÂ 17.925722].
[ÂÂ 17.925722] other info that might help us debug this:
[ÂÂ 17.933435]Â Possible unsafe locking scenario:
[ÂÂ 17.933435].
[ÂÂ 17.940331]ÂÂÂÂÂÂÂ CPU0
[ÂÂ 17.942488]ÂÂÂÂÂÂÂ ----
[ÂÂ 17.944894]ÂÂ lock(&syncp->seq#5);
[ÂÂ 17.948274]ÂÂ <Interrupt>
[ÂÂ 17.950847]ÂÂÂÂ lock(&syncp->seq#5);
[ÂÂ 17.954386].
[ÂÂ 17.954386]Â *** DEADLOCK ***
[ÂÂ 17.954386].
[ÂÂ 17.962422] no locks held by swapper/0/0.
[ÂÂ 17.966011].
[ÂÂ 17.966011] stack backtrace:
[ÂÂ 17.971333] CPU: 0 PID: 0 Comm: swapper/0 Not tainted
4.16.0-rc3-next-20180227-00007-g876c53a7493c #453
[ÂÂ 17.980312] Hardware name: SAMSUNG EXYNOS (Flattened Device Tree)
[ÂÂ 17.986380] [<c0111548>] (unwind_backtrace) from [<c010dbd8>]
(show_stack+0x10/0x14)
[ÂÂ 17.994128] [<c010dbd8>] (show_stack) from [<c09bd418>]
(dump_stack+0x90/0xc8)
[ÂÂ 18.001339] [<c09bd418>] (dump_stack) from [<c017fdf8>]
(print_usage_bug+0x25c/0x2cc)
[ÂÂ 18.009161] [<c017fdf8>] (print_usage_bug) from [<c017c14c>]
(mark_lock+0x290/0x698)
[ÂÂ 18.014952] exynos5-hsi2c 12ca0000.i2c: tx timeout
[ÂÂ 18.016899] [<c017c14c>] (mark_lock) from [<c017c9a8>]
(__lock_acquire+0x454/0x1850)
[ÂÂ 18.029449] [<c017c9a8>] (__lock_acquire) from [<c017e6e0>]
(lock_acquire+0xc8/0x2b8)
[ÂÂ 18.037272] [<c017e6e0>] (lock_acquire) from [<c05be98c>]
(usbnet_skb_return+0x7c/0x1a0)
[ÂÂ 18.045356] [<c05be98c>] (usbnet_skb_return) from [<c05b185c>]
(asix_rx_fixup_internal+0x188/0x288)
[ÂÂ 18.054420] [<c05b185c>] (asix_rx_fixup_internal) from [<c05bfe40>]
(usbnet_bh+0xf8/0x2e4)
[ÂÂ 18.062694] [<c05bfe40>] (usbnet_bh) from [<c012d6b4>]
(tasklet_action+0x8c/0x13c)
[ÂÂ 18.070259] [<c012d6b4>] (tasklet_action) from [<c0102214>]
(__do_softirq+0xd4/0x6d4)
[ÂÂ 18.078089] [<c0102214>] (__do_softirq) from [<c012cf34>]
(irq_exit+0x134/0x158)
[ÂÂ 18.085480] [<c012cf34>] (irq_exit) from [<c018c444>]
(__handle_domain_irq+0x70/0xe4)
[ÂÂ 18.093314] [<c018c444>] (__handle_domain_irq) from [<c046400c>]
(gic_handle_irq+0x54/0xa0)
[ÂÂ 18.101670] [<c046400c>] (gic_handle_irq) from [<c01019f0>]
(__irq_svc+0x70/0xb0)
[ÂÂ 18.109163] Exception stack(0xc0f01eb8 to 0xc0f01f00)
[ÂÂ 18.114202] 1ea0: 00000001 00000001
[ÂÂ 18.122397] 1ec0: 00000000 c0f0ba80 eef3a540 eef3a540 ee8d2700
c0f088b4 00000402 c09d23e0
[ÂÂ 18.124980] exynos5-hsi2c 12ca0000.i2c: tx timeout
[ÂÂ 18.130611] 1ee0: c0f0ba80 c0f01f4c 00000000 c0f01f08 c017ea54
c09d92d4 20000013 ffffffff
[ÂÂ 18.135504] cpu cpu0: _set_opp_voltage: failed to set voltage
(1250000 1250000 1250000 mV): -110
[ÂÂ 18.143690] [<c01019f0>] (__irq_svc) from [<c09d92d4>]
(_raw_spin_unlock_irq+0x28/0x5c)
[ÂÂ 18.152671] cpufreq: __target_index: Failed to change cpu frequency: -110
[ÂÂ 18.160683] [<c09d92d4>] (_raw_spin_unlock_irq) from [<c0152684>]
(finish_task_switch+0xb4/0x254)
[ÂÂ 18.160696] [<c0152684>] (finish_task_switch) from [<c09d23e0>]
(__schedule+0x290/0xb10)
[ÂÂ 18.160704] [<c09d23e0>] (__schedule) from [<c09d3134>]
(schedule_idle+0x2c/0x78)
[ÂÂ 18.160711] [<c09d3134>] (schedule_idle) from [<c01703a0>]
(cpu_startup_entry+0x18/0x1c)
[ÂÂ 18.200726] [<c01703a0>] (cpu_startup_entry) from [<c0e00c74>]
(start_kernel+0x394/0x400)
Best regards
Please try the attached patch, thanks.
Thanks for the patch. It fixes the deplock warning. However IMHO the same
fix should be also applied to complete_tx function for modifying stats64
there:
diff --git a/drivers/net/usb/usbnet.c b/drivers/net/usb/usbnet.c
index 7f5bda0ec9e8..d9eea8cfe6cb 100644
--- a/drivers/net/usb/usbnet.c
+++ b/drivers/net/usb/usbnet.c
@@ -1249,11 +1249,12 @@ static void tx_complete (struct urb *urb)
ÂÂÂÂÂÂÂ if (urb->status == 0) {
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂ struct pcpu_sw_netstats *stats64 =
this_cpu_ptr(dev->stats64);
+ÂÂÂÂÂÂÂÂÂÂÂÂÂÂ unsigned long flags;
-ÂÂÂÂÂÂÂÂÂÂÂÂÂÂ u64_stats_update_begin(&stats64->syncp);
+ÂÂÂÂÂÂÂÂÂÂÂÂÂÂ flags = u64_stats_update_begin_irqsave(&stats64->syncp);
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂ stats64->tx_packets += entry->packets;
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂ stats64->tx_bytes += entry->length;
-ÂÂÂÂÂÂÂÂÂÂÂÂÂÂ u64_stats_update_end(&stats64->syncp);
+ u64_stats_update_end_irqrestore(&stats64->syncp, flags);
ÂÂÂÂÂÂÂ } else {
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂ dev->net->stats.tx_errors++;
I've did that and it also works fine without deplock warning.
Âdrivers/net/usb/usbnet.cÂÂÂÂÂÂÂ|ÂÂÂÂ5 +++--
Âinclude/linux/u64_stats_sync.h |ÂÂÂ22 ++++++++++++++++++++++
Â2 files changed, 25 insertions(+), 2 deletions(-)
diff --git a/drivers/net/usb/usbnet.c b/drivers/net/usb/usbnet.c
index 8a22ff67b0268a588428c61c6a6211e3c6c2a02a..7f5bda0ec9e8520e6db327b713152afdb250255f 100644
--- a/drivers/net/usb/usbnet.c
+++ b/drivers/net/usb/usbnet.c
@@ -315,6 +315,7 @@ static void __usbnet_status_stop_force(struct usbnet *dev)
void usbnet_skb_return (struct usbnet *dev, struct sk_buff *skb)
{
struct pcpu_sw_netstats *stats64 = this_cpu_ptr(dev->stats64);
+ unsigned long flags;
int status;
if (test_bit(EVENT_RX_PAUSED, &dev->flags)) {
@@ -326,10 +327,10 @@ void usbnet_skb_return (struct usbnet *dev, struct sk_buff *skb)
if (skb->protocol == 0)
skb->protocol = eth_type_trans (skb, dev->net);
- u64_stats_update_begin(&stats64->syncp);
+ flags = u64_stats_update_begin_irqsave(&stats64->syncp);
stats64->rx_packets++;
stats64->rx_bytes += skb->len;
- u64_stats_update_end(&stats64->syncp);
+ u64_stats_update_end_irqrestore(&stats64->syncp, flags);
netif_dbg(dev, rx_status, dev->net, "< rx, len %zu, type 0x%x\n",
skb->len + sizeof (struct ethhdr), skb->protocol);
diff --git a/include/linux/u64_stats_sync.h b/include/linux/u64_stats_sync.h
index 5bdbd9f49395f883ca2dc5aa0d7bbde11f379063..07ee0f84a46caa9e2b1c446f96009f63b3b99f50 100644
--- a/include/linux/u64_stats_sync.h
+++ b/include/linux/u64_stats_sync.h
@@ -90,6 +90,28 @@ static inline void u64_stats_update_end(struct u64_stats_sync *syncp)
#endif
}
+static inline unsigned long
+u64_stats_update_begin_irqsave(struct u64_stats_sync *syncp)
+{
+ unsigned long flags = 0;
+
+#if BITS_PER_LONG==32 && defined(CONFIG_SMP)
+ local_irq_save(flags);
+ write_seqcount_begin(&syncp->seq);
+#endif
+ return flags;
+}
+
+static inline void
+u64_stats_update_end_irqrestore(struct u64_stats_sync *syncp,
+ unsigned long flags)
+{
+#if BITS_PER_LONG==32 && defined(CONFIG_SMP)
+ write_seqcount_end(&syncp->seq);
+ local_irq_restore(flags);
+#endif
+}
+
static inline void u64_stats_update_begin_raw(struct u64_stats_sync *syncp)
{
#if BITS_PER_LONG==32 && defined(CONFIG_SMP)
Best regards
--
Marek Szyprowski, PhD
Samsung R&D Institute Poland