| Message ID | 20250310165932.1201702-1-fiona.klute@gmx.de (mailing list archive) |
|---|---|
| State | New |
| Headers | show |
| Series | net: usb: lan78xx: Enforce a minimum interrupt polling period | expand |
On Mon, Mar 10, 2025 at 05:59:31PM +0100, Fiona Klute wrote: > If a new reset event appears before the previous one has been > processed, the device can get stuck into a reset loop. This happens > rarely, but blocks the device when it does, and floods the log with > messages like the following: > > lan78xx 2-3:1.0 enp1s0u3: kevent 4 may have been dropped > > The only bit that the driver pays attention to in the interrupt data > is "link was reset". If there's a flapping status bit in that endpoint > data (such as if PHY negotiation needs a few tries to get a stable > link), polling at a slower rate allows the state to settle. > > This is a simplified version of a patch that's been in the Raspberry > Pi downstream kernel since their 4.14 branch, see also: > https://github.com/raspberrypi/linux/issues/2447 > > Signed-off-by: Fiona Klute <fiona.klute@gmx.de> > Cc: kernel-list@raspberrypi.com > Cc: stable@vger.kernel.org > --- > For the stable crew: I've *tested* the patch with 6.12.7 and 6.13.5 on > a Revolution Pi Connect 4 (Raspberry Pi CM4 based device with built-in > LAN7800 as second ethernet port), according to the linked issue for > the RPi downstream kernel the problem should be present in all > maintained longterm kernel versions, too (based on how long they've > carried a patch). > > drivers/net/usb/lan78xx.c | 12 +++++++++++- > 1 file changed, 11 insertions(+), 1 deletion(-) > > diff --git a/drivers/net/usb/lan78xx.c b/drivers/net/usb/lan78xx.c > index a91bf9c7e31d..7bf01a31a932 100644 > --- a/drivers/net/usb/lan78xx.c > +++ b/drivers/net/usb/lan78xx.c > @@ -173,6 +173,12 @@ > #define INT_EP_GPIO_1 (1) > #define INT_EP_GPIO_0 (0) > > +/* highspeed device, so polling interval is in microframes (eight per > + * millisecond) > + */ > +#define INT_URB_MICROFRAMES_PER_MS 8 > +#define MIN_INT_URB_INTERVAL_MS 8 > + > static const char lan78xx_gstrings[][ETH_GSTRING_LEN] = { > "RX FCS Errors", > "RX Alignment Errors", > @@ -4527,7 +4533,11 @@ static int lan78xx_probe(struct usb_interface *intf, > if (ret < 0) > goto out4; > > - period = ep_intr->desc.bInterval; > + period = max(ep_intr->desc.bInterval, > + MIN_INT_URB_INTERVAL_MS * INT_URB_MICROFRAMES_PER_MS); This calculation is completely wrong. For high-speed interrupt endpoints, the bInterval value is encoded using a logarithmic scheme. The actual interval in microframes is given by 2^(bInterval - 1) (see Table 9-13 in the USB 2.0 spec). Furthermore, when the value is passed to usb_fill_int_urb(), the interval argument must be encoded in the same way (see the kerneldoc for usb_fill_int_urb() in include/linux/usb.h). The encoded value corresponding to 8 ms is 7, not 64, since 8 ms = 64 uframes and 64 = 2^(7-1). > + dev_info(&intf->dev, > + "interrupt urb period set to %d, bInterval is %d\n", > + period, ep_intr->desc.bInterval); I doubt that this dev_info() will be very helpful to anyone (in addition to being wrong since the value in "period" is not the actual period). Alan Stern
On Mon, Mar 10, 2025 at 05:59:31PM +0100, Fiona Klute wrote: > If a new reset event appears before the previous one has been > processed, the device can get stuck into a reset loop. This happens > rarely, but blocks the device when it does, and floods the log with > messages like the following: > > lan78xx 2-3:1.0 enp1s0u3: kevent 4 may have been dropped > > The only bit that the driver pays attention to in the interrupt data > is "link was reset". If there's a flapping status bit in that endpoint > data (such as if PHY negotiation needs a few tries to get a stable > link), polling at a slower rate allows the state to settle. Could you expand on this a little bit more. What is the issue you are seeing? I had a quick look at the PHY handling code, and it looks broken. The only time a MAC driver should look at members of phydev is during the adjust link callback, so lan78xx_link_status_change(). Everything is guaranteed to be consistent at this time. However, the current lan78xx_link_status_change() only adjusts EEE setting. The PHY code in lan78xx_link_reset() looks wrong. MAC drivers should not be reading PHY registers, or calling functions like phy_read_status(). Setting flow control should be performed in lan78xx_link_status_change() using phydev->pause and phydev->asym_pause. Andrew
Am 10.03.25 um 22:27 schrieb Andrew Lunn: > On Mon, Mar 10, 2025 at 05:59:31PM +0100, Fiona Klute wrote: >> If a new reset event appears before the previous one has been >> processed, the device can get stuck into a reset loop. This happens >> rarely, but blocks the device when it does, and floods the log with >> messages like the following: >> >> lan78xx 2-3:1.0 enp1s0u3: kevent 4 may have been dropped >> >> The only bit that the driver pays attention to in the interrupt data >> is "link was reset". If there's a flapping status bit in that endpoint >> data (such as if PHY negotiation needs a few tries to get a stable >> link), polling at a slower rate allows the state to settle. > > Could you expand on this a little bit more. What is the issue you are > seeing? What happens is that *sometimes* when the interface is activated (up, im my case via NetworkManager) during boot, the "kevent 4 may have been dropped" message starts to be emitted about every 6 or 7 ms. The interface is not usable. Today I also got this trace (and an equivalent one at about 90s): [ 27.905405] lan78xx 2-3:1.0 enp1s0u3: kevent 4 may have been dropped [ 27.911834] lan78xx 2-3:1.0 enp1s0u3: kevent 4 may have been dropped [ 27.918199] rcu: INFO: rcu_sched self-detected stall on CPU [ 27.918205] rcu: 0-....: (3351 ticks this GP) idle=e6bc/1/0x4000000000000000 softirq=671/671 fqs=2300 [ 27.918214] rcu: (t=5250 jiffies g=113 q=10467 ncpus=4) [ 27.918224] CPU: 0 UID: 0 PID: 64 Comm: kworker/0:4 Tainted: G C 6.13.5 #1 [ 27.918232] Tainted: [C]=CRAP [ 27.918234] Hardware name: Raspberry Pi Compute Module 4 Rev 1.1 (DT) [ 27.918238] Workqueue: events_power_efficient phy_state_machine [ 27.918252] pstate: 60000005 (nZCv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--) [ 27.918257] pc : console_flush_all+0x2b0/0x4f8 [ 27.918266] lr : console_flush_all+0x3f0/0x4f8 [ 27.918271] sp : ffff8000805c3880 [ 27.918273] x29: ffff8000805c38d0 x28: 0000000000000001 x27: ffffcb3e232df2e8 [ 27.918280] x26: ffffcb3e231bdaf0 x25: 0000000000000000 x24: ffffcb3e231d40b8 [ 27.918287] x23: 0000000000000000 x22: ffff8000805c3940 x21: 0000000000000000 [ 27.918293] x20: ffff8000805c393b x19: ffffcb3e233950c8 x18: ffff8000805c3560 [ 27.918299] x17: 6c6f72746e6f6320 x16: 776f6c66202d206c x15: ffff8001005c3717 [ 27.918305] x14: 0000000000000000 x13: 646570706f726420 x12: 6e65656220657661 [ 27.918311] x11: 682079616d203420 x10: 746e6576656b203a x9 : ffffcb3e22b36c0c [ 27.918317] x8 : ffff8000805c3788 x7 : 0000000000000000 x6 : ffff8000805c3840 [ 27.918323] x5 : ffffcb3e231be000 x4 : 0000000000000000 x3 : ffffcb3e231be3e8 [ 27.918329] x2 : 0000000000000000 x1 : ffffcb3e21f25414 x0 : ffff9e55d866a000 [ 27.918335] Call trace: [ 27.918338] console_flush_all+0x2b0/0x4f8 (P) [ 27.918346] console_unlock+0x8c/0x170 [ 27.918352] vprintk_emit+0x238/0x3b8 [ 27.918357] dev_vprintk_emit+0xe4/0x1b8 [ 27.918364] dev_printk_emit+0x64/0x98 [ 27.918368] __netdev_printk+0xc8/0x228 [ 27.918376] netdev_info+0x70/0xa8 [ 27.918382] phy_print_status+0xcc/0x138 [ 27.918386] lan78xx_link_status_change+0x78/0xb0 [ 27.918392] phy_link_change+0x38/0x70 [ 27.918398] phy_check_link_status+0xa8/0x110 [ 27.918405] _phy_start_aneg+0x5c/0xb8 [ 27.918409] lan88xx_link_change_notify+0x5c/0x128 [ 27.918416] _phy_state_machine+0x12c/0x2b0 [ 27.918420] phy_state_machine+0x34/0x80 [ 27.918425] process_one_work+0x150/0x3b8 [ 27.918432] worker_thread+0x2a4/0x4b8 [ 27.918438] kthread+0xec/0xf8 [ 27.918442] ret_from_fork+0x10/0x20 [ 27.918534] lan78xx 2-3:1.0 enp1s0u3: kevent 4 may have been dropped [ 27.924985] lan78xx 2-3:1.0 enp1s0u3: kevent 4 may have been dropped In this case the interface recovered about 150s after boot (the messages stopped and it became active), which correlates with when I logged in over serial to check what is going on. I do not know if that *caused* it to recover, the log gives no indication, but it's the first time I've seen the interface get out of the stuck state (before it was in CI runs where the device simply got reset, and I could only check logs afterwards). Unfortunately I have no reliable way to reproduce the bug, it just appears randomly during some boots. Another problem is that this was *with* the patch, so it's clearly not a correct solution and at most makes the issue less frequent (I had tested >300 boots successfully before sending it). > I had a quick look at the PHY handling code, and it looks broken. The > only time a MAC driver should look at members of phydev is during the > adjust link callback, so lan78xx_link_status_change(). Everything is > guaranteed to be consistent at this time. However, the current > lan78xx_link_status_change() only adjusts EEE setting. The PHY code in > lan78xx_link_reset() looks wrong. MAC drivers should not be reading > PHY registers, or calling functions like phy_read_status(). Setting > flow control should be performed in lan78xx_link_status_change() using > phydev->pause and phydev->asym_pause. Thanks for looking into this! I'm not familiar with ethernet drivers yet, do you have a hint on where I can learn what those functions *should* be doing (and thus how they might be fixed)? Documentation/driver-api/phy/phy.rst has only a very general overview of phy drivers. Best regards, Fiona
Am 10.03.25 um 19:06 schrieb Alan Stern: > On Mon, Mar 10, 2025 at 05:59:31PM +0100, Fiona Klute wrote: >> If a new reset event appears before the previous one has been >> processed, the device can get stuck into a reset loop. This happens >> rarely, but blocks the device when it does, and floods the log with >> messages like the following: >> >> lan78xx 2-3:1.0 enp1s0u3: kevent 4 may have been dropped >> >> The only bit that the driver pays attention to in the interrupt data >> is "link was reset". If there's a flapping status bit in that endpoint >> data (such as if PHY negotiation needs a few tries to get a stable >> link), polling at a slower rate allows the state to settle. >> >> This is a simplified version of a patch that's been in the Raspberry >> Pi downstream kernel since their 4.14 branch, see also: >> https://github.com/raspberrypi/linux/issues/2447 >> >> Signed-off-by: Fiona Klute <fiona.klute@gmx.de> >> Cc: kernel-list@raspberrypi.com >> Cc: stable@vger.kernel.org >> --- >> For the stable crew: I've *tested* the patch with 6.12.7 and 6.13.5 on >> a Revolution Pi Connect 4 (Raspberry Pi CM4 based device with built-in >> LAN7800 as second ethernet port), according to the linked issue for >> the RPi downstream kernel the problem should be present in all >> maintained longterm kernel versions, too (based on how long they've >> carried a patch). >> >> drivers/net/usb/lan78xx.c | 12 +++++++++++- >> 1 file changed, 11 insertions(+), 1 deletion(-) >> >> diff --git a/drivers/net/usb/lan78xx.c b/drivers/net/usb/lan78xx.c >> index a91bf9c7e31d..7bf01a31a932 100644 >> --- a/drivers/net/usb/lan78xx.c >> +++ b/drivers/net/usb/lan78xx.c >> @@ -173,6 +173,12 @@ >> #define INT_EP_GPIO_1 (1) >> #define INT_EP_GPIO_0 (0) >> >> +/* highspeed device, so polling interval is in microframes (eight per >> + * millisecond) >> + */ >> +#define INT_URB_MICROFRAMES_PER_MS 8 >> +#define MIN_INT_URB_INTERVAL_MS 8 >> + >> static const char lan78xx_gstrings[][ETH_GSTRING_LEN] = { >> "RX FCS Errors", >> "RX Alignment Errors", >> @@ -4527,7 +4533,11 @@ static int lan78xx_probe(struct usb_interface *intf, >> if (ret < 0) >> goto out4; >> >> - period = ep_intr->desc.bInterval; >> + period = max(ep_intr->desc.bInterval, >> + MIN_INT_URB_INTERVAL_MS * INT_URB_MICROFRAMES_PER_MS); > > This calculation is completely wrong. For high-speed interrupt > endpoints, the bInterval value is encoded using a logarithmic scheme. > The actual interval in microframes is given by 2^(bInterval - 1) (see > Table 9-13 in the USB 2.0 spec). Furthermore, when the value is passed > to usb_fill_int_urb(), the interval argument must be encoded in the same > way (see the kerneldoc for usb_fill_int_urb() in include/linux/usb.h). > > The encoded value corresponding to 8 ms is 7, not 64, since 8 ms = 64 > uframes and 64 = 2^(7-1). Thanks, I'll have to fix that if I send a revision. Though after Andrew Lunn's response and seeing the bug again today despite the patch after a few hundred good boots I suspect a different fix is needed. >> + dev_info(&intf->dev, >> + "interrupt urb period set to %d, bInterval is %d\n", >> + period, ep_intr->desc.bInterval); > > I doubt that this dev_info() will be very helpful to anyone (in addition > to being wrong since the value in "period" is not the actual period). I figured it'd be useful to note that the interval has been modified, especially for possible debugging. Best regards, Fiona
On Tue, Mar 11, 2025 at 01:30:54PM +0100, Fiona Klute wrote: > Am 10.03.25 um 22:27 schrieb Andrew Lunn: > > On Mon, Mar 10, 2025 at 05:59:31PM +0100, Fiona Klute wrote: > > > If a new reset event appears before the previous one has been > > > processed, the device can get stuck into a reset loop. This happens > > > rarely, but blocks the device when it does, and floods the log with > > > messages like the following: > > > > > > lan78xx 2-3:1.0 enp1s0u3: kevent 4 may have been dropped > > > > > > The only bit that the driver pays attention to in the interrupt data > > > is "link was reset". If there's a flapping status bit in that endpoint > > > data (such as if PHY negotiation needs a few tries to get a stable > > > link), polling at a slower rate allows the state to settle. > > > > Could you expand on this a little bit more. What is the issue you are > > seeing? > > What happens is that *sometimes* when the interface is activated (up, im > my case via NetworkManager) during boot, the "kevent 4 may have been > dropped" message starts to be emitted about every 6 or 7 ms. This sounding a bit like an interrupt storm. The PHY interrupt is not being cleared correctly. PHY interrupts are level interrupts, so if you don't clear the interrupt at the source, it will fire again as soon as you re-enable it. So which PHY driver is being used? If you look for the first kernel message about the lan78xx it probably tells you. > [ 27.918335] Call trace: > [ 27.918338] console_flush_all+0x2b0/0x4f8 (P) > [ 27.918346] console_unlock+0x8c/0x170 > [ 27.918352] vprintk_emit+0x238/0x3b8 > [ 27.918357] dev_vprintk_emit+0xe4/0x1b8 > [ 27.918364] dev_printk_emit+0x64/0x98 > [ 27.918368] __netdev_printk+0xc8/0x228 > [ 27.918376] netdev_info+0x70/0xa8 > [ 27.918382] phy_print_status+0xcc/0x138 > [ 27.918386] lan78xx_link_status_change+0x78/0xb0 > [ 27.918392] phy_link_change+0x38/0x70 > [ 27.918398] phy_check_link_status+0xa8/0x110 > [ 27.918405] _phy_start_aneg+0x5c/0xb8 > [ 27.918409] lan88xx_link_change_notify+0x5c/0x128 > [ 27.918416] _phy_state_machine+0x12c/0x2b0 > [ 27.918420] phy_state_machine+0x34/0x80 > [ 27.918425] process_one_work+0x150/0x3b8 > [ 27.918432] worker_thread+0x2a4/0x4b8 > [ 27.918438] kthread+0xec/0xf8 > [ 27.918442] ret_from_fork+0x10/0x20 > [ 27.918534] lan78xx 2-3:1.0 enp1s0u3: kevent 4 may have been dropped > [ 27.924985] lan78xx 2-3:1.0 enp1s0u3: kevent 4 may have been dropped Ah, O.K. This tells me the PHY is a lan88xx. And there is a workaround involved for an issue in this PHY. Often PHYs are driven by polling for status changes once per second. Not all PHYs/boards support interrupts. It could be this workaround has only been tested with polling, not interrupts, and so is broken when interrupts are used. As a quick hack test, in lan78xx_phy_init() /* if phyirq is not set, use polling mode in phylib */ if (dev->domain_data.phyirq > 0) phydev->irq = dev->domain_data.phyirq; else phydev->irq = PHY_POLL; Hard code phydev->irq to PHY_POLL, so interrupts are not used. See if you can reproduce the issue when interrupts are not used. Andrew
Am 11.03.25 um 14:22 schrieb Andrew Lunn: > On Tue, Mar 11, 2025 at 01:30:54PM +0100, Fiona Klute wrote: >> Am 10.03.25 um 22:27 schrieb Andrew Lunn: >>> On Mon, Mar 10, 2025 at 05:59:31PM +0100, Fiona Klute wrote: >>>> If a new reset event appears before the previous one has been >>>> processed, the device can get stuck into a reset loop. This happens >>>> rarely, but blocks the device when it does, and floods the log with >>>> messages like the following: >>>> >>>> lan78xx 2-3:1.0 enp1s0u3: kevent 4 may have been dropped >>>> >>>> The only bit that the driver pays attention to in the interrupt data >>>> is "link was reset". If there's a flapping status bit in that endpoint >>>> data (such as if PHY negotiation needs a few tries to get a stable >>>> link), polling at a slower rate allows the state to settle. >>> >>> Could you expand on this a little bit more. What is the issue you are >>> seeing? >> >> What happens is that *sometimes* when the interface is activated (up, im >> my case via NetworkManager) during boot, the "kevent 4 may have been >> dropped" message starts to be emitted about every 6 or 7 ms. > > This sounding a bit like an interrupt storm. The PHY interrupt is not > being cleared correctly. PHY interrupts are level interrupts, so if > you don't clear the interrupt at the source, it will fire again as > soon as you re-enable it. > > So which PHY driver is being used? If you look for the first kernel > message about the lan78xx it probably tells you. > >> [ 27.918335] Call trace: >> [ 27.918338] console_flush_all+0x2b0/0x4f8 (P) >> [ 27.918346] console_unlock+0x8c/0x170 >> [ 27.918352] vprintk_emit+0x238/0x3b8 >> [ 27.918357] dev_vprintk_emit+0xe4/0x1b8 >> [ 27.918364] dev_printk_emit+0x64/0x98 >> [ 27.918368] __netdev_printk+0xc8/0x228 >> [ 27.918376] netdev_info+0x70/0xa8 >> [ 27.918382] phy_print_status+0xcc/0x138 >> [ 27.918386] lan78xx_link_status_change+0x78/0xb0 >> [ 27.918392] phy_link_change+0x38/0x70 >> [ 27.918398] phy_check_link_status+0xa8/0x110 >> [ 27.918405] _phy_start_aneg+0x5c/0xb8 >> [ 27.918409] lan88xx_link_change_notify+0x5c/0x128 >> [ 27.918416] _phy_state_machine+0x12c/0x2b0 >> [ 27.918420] phy_state_machine+0x34/0x80 >> [ 27.918425] process_one_work+0x150/0x3b8 >> [ 27.918432] worker_thread+0x2a4/0x4b8 >> [ 27.918438] kthread+0xec/0xf8 >> [ 27.918442] ret_from_fork+0x10/0x20 >> [ 27.918534] lan78xx 2-3:1.0 enp1s0u3: kevent 4 may have been dropped >> [ 27.924985] lan78xx 2-3:1.0 enp1s0u3: kevent 4 may have been dropped > > Ah, O.K. This tells me the PHY is a lan88xx. And there is a workaround > involved for an issue in this PHY. Often PHYs are driven by polling > for status changes once per second. Not all PHYs/boards support > interrupts. It could be this workaround has only been tested with > polling, not interrupts, and so is broken when interrupts are used. > > As a quick hack test, in lan78xx_phy_init() > > /* if phyirq is not set, use polling mode in phylib */ > if (dev->domain_data.phyirq > 0) > phydev->irq = dev->domain_data.phyirq; > else > phydev->irq = PHY_POLL; > > Hard code phydev->irq to PHY_POLL, so interrupts are not used. > > See if you can reproduce the issue when interrupts are not used. Thank you, I'll test that. Given the issue appears rarely it'll unfortunately take a while to be (mostly) sure. Best regards, Fiona
diff --git a/drivers/net/usb/lan78xx.c b/drivers/net/usb/lan78xx.c index a91bf9c7e31d..7bf01a31a932 100644 --- a/drivers/net/usb/lan78xx.c +++ b/drivers/net/usb/lan78xx.c @@ -173,6 +173,12 @@ #define INT_EP_GPIO_1 (1) #define INT_EP_GPIO_0 (0) +/* highspeed device, so polling interval is in microframes (eight per + * millisecond) + */ +#define INT_URB_MICROFRAMES_PER_MS 8 +#define MIN_INT_URB_INTERVAL_MS 8 + static const char lan78xx_gstrings[][ETH_GSTRING_LEN] = { "RX FCS Errors", "RX Alignment Errors", @@ -4527,7 +4533,11 @@ static int lan78xx_probe(struct usb_interface *intf, if (ret < 0) goto out4; - period = ep_intr->desc.bInterval; + period = max(ep_intr->desc.bInterval, + MIN_INT_URB_INTERVAL_MS * INT_URB_MICROFRAMES_PER_MS); + dev_info(&intf->dev, + "interrupt urb period set to %d, bInterval is %d\n", + period, ep_intr->desc.bInterval); maxp = usb_maxpacket(dev->udev, dev->pipe_intr); dev->urb_intr = usb_alloc_urb(0, GFP_KERNEL);
If a new reset event appears before the previous one has been processed, the device can get stuck into a reset loop. This happens rarely, but blocks the device when it does, and floods the log with messages like the following: lan78xx 2-3:1.0 enp1s0u3: kevent 4 may have been dropped The only bit that the driver pays attention to in the interrupt data is "link was reset". If there's a flapping status bit in that endpoint data (such as if PHY negotiation needs a few tries to get a stable link), polling at a slower rate allows the state to settle. This is a simplified version of a patch that's been in the Raspberry Pi downstream kernel since their 4.14 branch, see also: https://github.com/raspberrypi/linux/issues/2447 Signed-off-by: Fiona Klute <fiona.klute@gmx.de> Cc: kernel-list@raspberrypi.com Cc: stable@vger.kernel.org --- For the stable crew: I've *tested* the patch with 6.12.7 and 6.13.5 on a Revolution Pi Connect 4 (Raspberry Pi CM4 based device with built-in LAN7800 as second ethernet port), according to the linked issue for the RPi downstream kernel the problem should be present in all maintained longterm kernel versions, too (based on how long they've carried a patch). drivers/net/usb/lan78xx.c | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) base-commit: dd83757f6e686a2188997cb58b5975f744bb7786