From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-0.8 required=3.0 tests=DKIM_SIGNED,DKIM_VALID, DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,MAILING_LIST_MULTI,SPF_PASS autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 9FF4CC43381 for ; Sat, 16 Mar 2019 09:08:07 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.kernel.org (Postfix) with ESMTP id 4F8E2218FC for ; Sat, 16 Mar 2019 09:08:07 +0000 (UTC) Authentication-Results: mail.kernel.org; dkim=pass (2048-bit key) header.d=gmail.com header.i=@gmail.com header.b="D9tSa2jW" Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1726812AbfCPJIG (ORCPT ); Sat, 16 Mar 2019 05:08:06 -0400 Received: from mail-wm1-f66.google.com ([209.85.128.66]:55221 "EHLO mail-wm1-f66.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726105AbfCPJIF (ORCPT ); Sat, 16 Mar 2019 05:08:05 -0400 Received: by mail-wm1-f66.google.com with SMTP id f3so8723236wmj.4 for ; Sat, 16 Mar 2019 02:08:03 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=subject:to:cc:references:from:message-id:date:user-agent :mime-version:in-reply-to:content-language:content-transfer-encoding; bh=f8rDgk1WVbrnRin/qLgodfmt35paDuP//xJ3gzk6iEk=; b=D9tSa2jWDrhN04bRdh6toGXyUZn3cQfTtaE8GTjl8IKZQC7w5RaPhZ3UA0w/MLAJUC 4V2xTj7xd+r7GMv0+5KKDqajW7vd/UBY9LV+Fo0Bd8cQ7vVpRBGem1/1RsRJV25OMvA0 E527wgAfepjzbKhLqGrOKtTfMbmBScQHDxfphnGjgvrPv/nQTPrhoUHAPwthtp/4MK4M 8FsbFOBRmomNUWMjr+CbSV7PWUPTF/vkFGweAsJmz46+t6ZRvG031ZbD/Q4b0eqjSo+l 8/cDsLXeEHk7PUQexcloAykmWmV9ys2qc30DT/87zh5Zah4pqRzCUMBpElQWPOf6U65/ Vm8g== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:subject:to:cc:references:from:message-id:date :user-agent:mime-version:in-reply-to:content-language :content-transfer-encoding; bh=f8rDgk1WVbrnRin/qLgodfmt35paDuP//xJ3gzk6iEk=; b=fDOYA8yvztQVpbuS8yjWRxnIhiwAI3W2g1QjWk5XqFxftj71D5MEwU/MGCV0rYibLN L6Y/MSbNrFaavGjCARr213zn7PJgqLZtZcdZ/J/Nkpbp1wPF8bvPyxwlwK6beOl7Zfw6 /W5jxAmHgpIEac5J8QcVvoXxYOwbOwBQ/afryHTSgDzudNRJSyhWTLWJvoXJt5MM0pis jODupzJZ0C1dWkb/RItvnbiI2q8BCHaRq+BA6w0SubVSZfRFDcfdBKWReKkwWIoTqTt5 8j7gRoKtRtuJDSTFe8MipgQtxgSdLD0DaE9zDG5sEohvquI7sM49z6ezK1WIrna/APim 1osA== X-Gm-Message-State: APjAAAU2qtVXpI5Rw/W9RSNy0nmpcRHBf/CJzNFkHIAqtJj9AHqG6yQF ewKsO2eCW0i7K+yIHYwGmR/e9L92 X-Google-Smtp-Source: APXvYqw2v4g2T0rUbHl3zcPUhtpQ0Yq2I9WnqvF/bEO19kyJrru+bHpJ5x0Ba4YdbWsvcLeWZ2ps8A== X-Received: by 2002:a1c:f503:: with SMTP id t3mr4666132wmh.71.1552727282129; Sat, 16 Mar 2019 02:08:02 -0700 (PDT) Received: from ?IPv6:2003:ea:8bc4:dc00:e9c5:8d8e:8498:7012? (p200300EA8BC4DC00E9C58D8E84987012.dip0.t-ipconnect.de. [2003:ea:8bc4:dc00:e9c5:8d8e:8498:7012]) by smtp.googlemail.com with ESMTPSA id d9sm8515363wrn.72.2019.03.16.02.08.01 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Sat, 16 Mar 2019 02:08:01 -0700 (PDT) Subject: Re: r8169 driver from kernel 5.0 crashing - napi_consume_skb To: Alexander Duyck , VDR User Cc: netdev@vger.kernel.org References: <753b56b8-f1ab-82f5-f9b5-089fbb638989@gmail.com> <02388deb-0a06-95ae-1aac-b39c108fc2e7@gmail.com> <9b34d60d-8de7-5384-3822-98ec79d53e04@gmail.com> <0704f164-aa0a-bcae-a886-a7fc4a4cd52f@gmail.com> <8f910b1339a741cdc780f3948c11a082a8a51b9e.camel@linux.intel.com> From: Heiner Kallweit Message-ID: Date: Sat, 16 Mar 2019 10:07:56 +0100 User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:60.0) Gecko/20100101 Thunderbird/60.5.3 MIME-Version: 1.0 In-Reply-To: Content-Type: text/plain; charset=utf-8 Content-Language: en-US Content-Transfer-Encoding: 7bit Sender: netdev-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: netdev@vger.kernel.org On 16.03.2019 00:54, Alexander Duyck wrote: > On Fri, 2019-03-15 at 23:27 +0100, Heiner Kallweit wrote: >> On 15.03.2019 23:09, Alexander Duyck wrote: >>> On Fri, 2019-03-15 at 21:46 +0100, Heiner Kallweit wrote: >>>> On 15.03.2019 21:40, Alexander Duyck wrote: >>>>> On Fri, 2019-03-15 at 21:26 +0100, Heiner Kallweit wrote: >>>>>> On 15.03.2019 21:09, VDR User wrote: >>>>>>>>>>> Thanks for the additional info and for testing 4.20.15. >>>>>>>>>>> To rule out that the issue is caused by a regression in network or >>>>>>>>>>> some other subsystem: Can you take the r8169.c from 4.20.15 and test >>>>>>>>>>> it on top of 5.0? >>>>>>>>>>> Meanwhile I'll look at the changes in the driver between 4.20 and 5.0. >>>>>>>>>> >>>>>>>>>> Sure, no problem! I'll copy the driver & recompile now actually. >>>>>>>>>> Hopefully there aren't a ton of changes to r8169.c to sift through and >>>>>>>>>> the cause isn't good at hiding itself! >>>>>>>>>> >>>>>>>>> I checked the driver changes new in 5.0 and there are very few >>>>>>>>> functional changes. You could try to revert the following: >>>>>>>>> >>>>>>>>> 5317d5c6d47e ("r8169: use napi_consume_skb where possible") >>>>>>>> >>>>>>>> Will do, and fwiw, while I haven't been able to do tons of testing >>>>>>>> today, I haven't been able to trigger the crash after replacing >>>>>>>> 5.0.0's r8169.c with 4.20.15's r8169.c this morning. I'll restore the >>>>>>>> file and revert the change you mentioned, and report back my findings. >>>>>>> >>>>>>> Heiner, >>>>>>> >>>>>>> After going back to vanilla kernel 5.0 and then reverting 5317d5c6d47e >>>>>>> ("r8169: use napi_consume_skb where possible"), I so far have not had >>>>>>> any crashes after transferring roughly 30GB back & forth. I'm not >>>>>>> completely confident yet the crash is resolve with that revert and >>>>>>> will continue to do further testing throughout the weekend as well. >>>>>>> What confidence level do you have that 5317d5c6d47e is the culprit at >>>>>>> this point? >>>>>>> >>>>>> Good, thanks for testing. I simply see no other change since 4.20 that >>>>>> could cause these symptoms. >>>>>> Using napi_consume_skb() at this place in r8169.c looks safe to me. >>>>>> Option 1 is that I miss something, option 2 is that there's an issue >>>>>> in the NAPI subsystem. However in the latter case I assume at least >>>>>> the Mellanox and/or Intel guys would have observed the same issue >>>>>> on their respective CI systems. >>>>>> Let me add Alexander, maybe he can provide a hint before we go and >>>>>> revert the change. >>>>> >>>>> Do you have the crash log? I'd be curious what the issue is we are >>>>> seeing. >>>>> >>>>> I agree I can't see anything obvious, but it is possible that we may be >>>>> running into something we hadn't seen with the Intel and Mellanox >>>>> parts. >>>>> >>>>> - Alex >>>>> >>>>> >>>> Crash may have been the wrong word, network becomes unresponsive >>>> and the user sees the generic transmit queue timeout. >>>> Let me quote his original mail: >>>> >>>> ------------------------------------------------------------------------ >>>> >>>> Hi, after updating to kernel 5.0, the nic driver (r8169) has been >>>> crashing whenever I start using heavy traffic on it (for example, >>>> xferring large files to the box across my lan). The destination >>>> harddrive may be sleeping and need to spin-up, or not, but the box >>>> itself does not suspend/hibernate. The nic becomes completely >>>> unresponsive and all connections to the box drop. After what I think >>>> is several minutes, the connection comes back to life. The problem >>>> happens consistently but seemingly not consistently at the same point. >>>> For example, I can xfer a few 4gb files and it will crash at around >>>> 2-3gb on the first file. The next time it might not crash until 2-3gb >>>> on the second file.Prior to kernel 5.0 I was using 4.19.12 and this >>>> problem didn't occur. I have since downgraded back to 4.19.12 pending >>>> what response this post gets. >>>> >>>> Thanks for any help or assistance on how to proceed! >>>> -Derek >>>> >>>> NOTE: I'm not subscribed to this mailing list so please CC me on any replies! >>>> >>>> The nic is on-board ECS A75F-A: >>>> 04:00.0 Ethernet controller: Realtek Semiconductor Co., Ltd. >>>> RTL8111/8168/8411 PCI Express Gigabit Ethernet Controller (rev 06) >>>> Subsystem: Elitegroup Computer Systems RTL8111/8168/8411 PCI >>>> Express Gigabit Ethernet Controller >>>> Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- >>>> ParErr- Stepping- SERR- FastB2B- DisINTx+ >>>> Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- >>>> SERR- >>> Latency: 0, Cache Line Size: 64 bytes >>>> Interrupt: pin A routed to IRQ 17 >>>> Region 0: I/O ports at c000 [size=256] >>>> Region 2: Memory at d0004000 (64-bit, prefetchable) [size=4K] >>>> Region 4: Memory at d0000000 (64-bit, prefetchable) [size=16K] >>>> Capabilities: >>>> Kernel driver in use: r8169 >>>> >>>> I see the following in the syslog: >>>> >>>> [164572.785517] ------------[ cut here ]------------ >>>> [164572.785595] NETDEV WATCHDOG: enp4s0 (r8169): transmit queue 0 timed out >>>> [164572.785677] WARNING: CPU: 1 PID: 0 at net/sched/sch_generic.c:461 >>>> dev_watchdog+0x1bb/0x1e0 >>>> [164572.785730] Modules linked in: snd_hda_codec_realtek >>>> snd_hda_codec_generic snd_hda_codec_hdmi ohci_pci snd_hda_intel >>>> snd_hda_codec snd_hwdep xhci_pci ehci_pci ohci_hcd xhci_hcd ehci_hcd >>>> usbcore usb_common snd_hda_core snd_pcm snd_timer snd soundcore nfsd >>>> auth_rpcgss oid_registry lockd grace sunrpc ip_tables x_tables ipv6 >>>> [164572.785807] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.0.0-amd #2 >>>> [164572.785842] Hardware name: ECS A75F-A/A75F-A, BIOS 4.6.5 09/14/2011 >>>> [164572.785878] EIP: dev_watchdog+0x1bb/0x1e0 >>>> [164572.785912] Code: 8b 50 3c 89 f8 e8 3d aa 0a 00 8b 7e f4 eb a4 89 >>>> f8 c6 05 e7 1c 6d c1 01 e8 72 4f fd ff 53 50 57 68 78 05 66 c1 e8 25 >>>> ad ba ff <0f> 0b 83 c4 10 eb c9 eb 1c 8d b4 26 00 00 00 00 8d b4 26 00 >>>> 00 00 >>>> [164572.785963] EAX: 0000003b EBX: 00000000 ECX: 00000800 EDX: 00000103 >>>> [164572.785998] ESI: f4cbc264 EDI: f4cbc000 EBP: f4c99f74 ESP: f4c99f4c >>>> [164572.786033] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00210296 >>>> [164572.786067] CR0: 80050033 CR2: 020dc000 CR3: 2b80b000 CR4: 00000690 >>>> [164572.786102] Call Trace: >>>> [164572.786135] >>>> [164572.786168] ? qdisc_put_unlocked+0x40/0x40 >>>> [164572.786203] call_timer_fn+0x19/0xa0 >>>> [164572.786237] run_timer_softirq+0x337/0x380 >>>> [164572.786270] ? qdisc_put_unlocked+0x40/0x40 >>>> [164572.786302] ? rcu_process_callbacks+0xcb/0x380 >>>> [164572.786337] __do_softirq+0xd6/0x21c >>>> [164572.786370] ? __irqentry_text_end+0x18/0x18 >>>> [164572.786404] call_on_stack+0x10/0x60 >>>> [164572.786435] >>>> [164572.786467] ? irq_exit+0x91/0xc0 >>>> [164572.786495] ? smp_apic_timer_interrupt+0x56/0xa0 >>>> [164572.786525] ? apic_timer_interrupt+0xd5/0xdc >>>> [164572.786555] ? acpi_idle_enter_s2idle+0x60/0x60 >>>> [164572.786584] ? cpuidle_enter_state+0x122/0x360 >>>> [164572.786614] ? tick_nohz_idle_stop_tick+0x27b/0x2a0 >>>> [164572.786644] ? cpuidle_enter+0xf/0x20 >>>> [164572.786673] ? call_cpuidle+0x1c/0x40 >>>> [164572.786701] ? do_idle+0x1e6/0x220 >>>> [164572.786730] ? cpu_startup_entry+0x25/0x40 >>>> [164572.786758] ? start_secondary+0x1a5/0x220 >>>> [164572.786787] ? startup_32_smp+0x15f/0x164 >>>> [164572.786816] ---[ end trace 662a5195537dbad8 ]--- >>>> >>> >>> Okay, the patch suggested doesn't make much sense for the issue >>> described. I was expecting to see something that at least pointed to >>> the NAPI logic, and I don't see anything doing as such. >>> >> According to the tests done so far replacing napi_consume_skb() >> with dev_consume_skb_any() seems to reliably avoid the issue. >> If there really should be an issue with irq/ring management, >> then the question would be why it's not trigger with >> dev_consume_skb_any(). > > Part of the issue though is that we don't know how reliable that test > was. I believe Derek he hasn't had any crashes, but he wasn't confident > that it had actually resolved the issue. > > There isn't anything in the napi_consume_skb code that would cause us > to stop a queue assuming we aren't seeing some sort of bizarre memory > corruption where the only thing we are corrupting is the Tx queue stop > bit. > > The dev_watchdog indicates that the Tx queue is stopped. Usually to end > up in a state there are a few possible causes. The first is some sort > of mess-up in the BQL or Tx descriptor counting logic. The second > possible cause is the Tx interrupt just isn't firing due to a lost > event that somehow leaves it masked. > > A quick pass with "git diff v4.20 v5.0 > drivers/net/ethernet/realtek/r8169.c" shows a number of possible > candidates that could have caused this in terms of changes. My advise > would be to look at possible interrupt issues due to a non-spurious > interrupt getting ignored, or something involving the count of > descriptor slots available. > > Thanks for the feedback! After looking in more detail at the provided trace, it seems to be quite weird to me. qdisc_put_unlocked() doesn't have a single user in 5.0. And start_secondary() I also wouldn't expect to see here.