| Message ID | 20170718231435.64us7vu67wtp6pwe@f1.synalogic.ca |
|---|---|
| State | Not Applicable |
| Headers | show |
On Tue, Jul 18, 2017 at 04:14:35PM -0700, Benjamin Poirier wrote: > Thanks for the detailed analysis. > > Refering to the original discussion around this patch series, it seemed like > the IMS bit for a condition had to be set for the Other interrupt to be raised > for that condition. > > https://lkml.org/lkml/2015/11/4/683 > > In this case however, E1000_ICR_RXT0 is not set in IMS so Other shouldn't be > raised for Receiver Overrun. Apparently something is going on... > > I can reproduce the spurious Other interrupts with a simple mdelay() > With the debugging patch at the end of the mail I see stuff like this > while blasting with udp frames: > <idle>-0 [086] d.h1 15338.742675: e1000_msix_other: got Other interrupt, count 15127 > <...>-54504 [086] d.h. 15338.742724: e1000_msix_other: got Other interrupt, count 1 > <...>-54504 [086] d.h. 15338.742774: e1000_msix_other: got Other interrupt, count 1 > <...>-54504 [086] d.h. 15338.742824: e1000_msix_other: got Other interrupt, count 1 > <idle>-0 [086] d.h1 15340.745123: e1000_msix_other: got Other interrupt, count 27584 > <...>-54504 [086] d.h. 15340.745172: e1000_msix_other: got Other interrupt, count 1 > <...>-54504 [086] d.h. 15340.745222: e1000_msix_other: got Other interrupt, count 1 > <...>-54504 [086] d.h. 15340.745272: e1000_msix_other: got Other interrupt, count 1 > > > hence sets the flag that (unfortunately) means both link is down and link > > state should be checked. Since this now happens 3000 times per second, > > the chances of it happening while the watchdog_task is checking the link > > state becomes pretty high, and it if does happen to coincice, then the > > watchdog_task will reset the adapter, which causes a real loss of link. > > Through which path does watchdog_task reset the adapter? I didn't > reproduce that. The other interrupt happens and sets get_link_status to true. At some point the watchdog_task runs on some core and calls e1000e_has_link, which then calls check_for_link to find out the current link status. While e1000e_check_for_copper_link is checking the link state and after updating get_link_status to false to indicate link is up, another interrupt occurs and another core handles it and changes get_link_status to true again. So by the time e1000e_has_link goes to determine the return value, get_link_state has changed back again so now it returns link down, and as a result the watchdog_task calls reset, because we have packets in the transmit queue (we were busy forwarding over 100000 packets per second when it happened). Running on an Atom D525 which isn't very fast and uses hyperthreading might have something to do with how the scheduling manages to trigger this race condition. On a faster CPU you very likely would be done checking the link state quickly enough that the interrupt handler rarely gets a chance to interfere. Also we have the irq affinity set so the RX/TX of one port is handled by one CPU, the RX/TX of the other port by a different CPU and the Other interrupts and other tasks (like the watchdog) are handled by the last two CPUs. Either making the current link state its own bool and keeping it's meaning away from get_link_state, or making the interrupt handler only change get_link_state when LSC is actually present makes the problem go away. Having two meanings to get_link_state (both link state needs checking and what the link state is) causes issues. After all it is using a bool to store 3 values: Link is up, link needs checking but is up and link needs checking but is down. Of course the last two states are rather quantum, in that you don't know which it is until you check. > diff --git a/drivers/net/ethernet/intel/e1000e/netdev.c b/drivers/net/ethernet/intel/e1000e/netdev.c > index b3679728caac..689ad76d0d12 100644 > --- a/drivers/net/ethernet/intel/e1000e/netdev.c > +++ b/drivers/net/ethernet/intel/e1000e/netdev.c > @@ -46,6 +46,8 @@ > > #include "e1000.h" > > +DEFINE_RATELIMIT_STATE(e1000e_ratelimit_state, 2 * HZ, 4); > + > #define DRV_EXTRAVERSION "-k" > > #define DRV_VERSION "3.2.6" DRV_EXTRAVERSION > @@ -937,6 +939,8 @@ static bool e1000_clean_rx_irq(struct e1000_ring *rx_ring, int *work_done, > bool cleaned = false; > unsigned int total_rx_bytes = 0, total_rx_packets = 0; > > + mdelay(10); > + > i = rx_ring->next_to_clean; > rx_desc = E1000_RX_DESC_EXT(*rx_ring, i); > staterr = le32_to_cpu(rx_desc->wb.upper.status_error); > @@ -1067,6 +1071,13 @@ static bool e1000_clean_rx_irq(struct e1000_ring *rx_ring, int *work_done, > > adapter->total_rx_bytes += total_rx_bytes; > adapter->total_rx_packets += total_rx_packets; > + > + if (__ratelimit(&e1000e_ratelimit_state)) { > + static unsigned int max; > + max = max(max, total_rx_packets); > + trace_printk("received %u max %u\n", total_rx_packets, max); > + } > + > return cleaned; > } > > @@ -1904,9 +1915,16 @@ static irqreturn_t e1000_msix_other(int __always_unused irq, void *data) > struct net_device *netdev = data; > struct e1000_adapter *adapter = netdev_priv(netdev); > struct e1000_hw *hw = &adapter->hw; > + static unsigned int count; > > hw->mac.get_link_status = true; > > + count++; > + if (__ratelimit(&e1000e_ratelimit_state)) { > + trace_printk("got Other interrupt, count %u\n", count); > + count = 0; > + } > + > /* guard against interrupt when we're going down */ > if (!test_bit(__E1000_DOWN, &adapter->state)) { > mod_timer(&adapter->watchdog_timer, jiffies + 1); > @@ -7121,7 +7139,7 @@ static int e1000_probe(struct pci_dev *pdev, const struct pci_device_id *ent) > netdev->netdev_ops = &e1000e_netdev_ops; > e1000e_set_ethtool_ops(netdev); > netdev->watchdog_timeo = 5 * HZ; > - netif_napi_add(netdev, &adapter->napi, e1000e_poll, 64); > + netif_napi_add(netdev, &adapter->napi, e1000e_poll, 500); > strlcpy(netdev->name, pci_name(pdev), sizeof(netdev->name)); > > netdev->mem_start = mmio_start; > @@ -7327,6 +7345,8 @@ static int e1000_probe(struct pci_dev *pdev, const struct pci_device_id *ent) > if (err) > goto err_register; > > + ratelimit_set_flags(&e1000e_ratelimit_state, RATELIMIT_MSG_ON_RELEASE); > + > /* carrier off reporting is important to ethtool even BEFORE open */ > netif_carrier_off(netdev);
On 2017/07/19 10:19, Lennart Sorensen wrote: > On Tue, Jul 18, 2017 at 04:14:35PM -0700, Benjamin Poirier wrote: > > Thanks for the detailed analysis. > > > > Refering to the original discussion around this patch series, it seemed like > > the IMS bit for a condition had to be set for the Other interrupt to be raised > > for that condition. > > > > https://lkml.org/lkml/2015/11/4/683 > > > > In this case however, E1000_ICR_RXT0 is not set in IMS so Other shouldn't be > > raised for Receiver Overrun. Apparently something is going on... > > > > I can reproduce the spurious Other interrupts with a simple mdelay() > > With the debugging patch at the end of the mail I see stuff like this > > while blasting with udp frames: > > <idle>-0 [086] d.h1 15338.742675: e1000_msix_other: got Other interrupt, count 15127 > > <...>-54504 [086] d.h. 15338.742724: e1000_msix_other: got Other interrupt, count 1 > > <...>-54504 [086] d.h. 15338.742774: e1000_msix_other: got Other interrupt, count 1 > > <...>-54504 [086] d.h. 15338.742824: e1000_msix_other: got Other interrupt, count 1 > > <idle>-0 [086] d.h1 15340.745123: e1000_msix_other: got Other interrupt, count 27584 > > <...>-54504 [086] d.h. 15340.745172: e1000_msix_other: got Other interrupt, count 1 > > <...>-54504 [086] d.h. 15340.745222: e1000_msix_other: got Other interrupt, count 1 > > <...>-54504 [086] d.h. 15340.745272: e1000_msix_other: got Other interrupt, count 1 > > > > > hence sets the flag that (unfortunately) means both link is down and link > > > state should be checked. Since this now happens 3000 times per second, > > > the chances of it happening while the watchdog_task is checking the link > > > state becomes pretty high, and it if does happen to coincice, then the > > > watchdog_task will reset the adapter, which causes a real loss of link. > > > > Through which path does watchdog_task reset the adapter? I didn't > > reproduce that. > > The other interrupt happens and sets get_link_status to true. At some > point the watchdog_task runs on some core and calls e1000e_has_link, > which then calls check_for_link to find out the current link status. > While e1000e_check_for_copper_link is checking the link state and > after updating get_link_status to false to indicate link is up, another > interrupt occurs and another core handles it and changes get_link_status > to true again. So by the time e1000e_has_link goes to determine the > return value, get_link_state has changed back again so now it returns > link down, and as a result the watchdog_task calls reset, because we > have packets in the transmit queue (we were busy forwarding over 100000 > packets per second when it happened). Ah I see. Thanks again. In your previous mail, On 2017/07/18 10:21, Lennart Sorensen wrote: [...] > I tried checking what the bits in the ICR actually were under these > conditions, and it would appear that the only bit set is 24 (the Other > Causes interrupt bit). So I don't know what the real cause is although Are you sure about this? In my testing, while triggering the overrun with the msleep, I read ICR when entering e1000_msix_other() and RXO is consistently set. I'm working on a patch that uses that fact to handle the situation and limit the interrupt.
On Wed, Jul 19, 2017 at 05:07:47PM -0700, Benjamin Poirier wrote: > Are you sure about this? In my testing, while triggering the overrun > with the msleep, I read ICR when entering e1000_msix_other() and RXO is > consistently set. I had thousands of calls to e1000_msix_other where the only bit set was OTHER. I don't know if the cause is overruns, it just seems plausible. > I'm working on a patch that uses that fact to handle the situation and > limit the interrupt. Excellent. Running in MSI mode rather than MSI-X seems to not have the problem of unexpected interrupts, but has other issues (such as loosing the IRQ affinity setting if you do ifconfig down;ifconfig up on the interface, which does not happen in MSI-X's case.) That's rather annoying as you can't set the affinity before bringing up the interface which is rather undesirable.
diff --git a/drivers/net/ethernet/intel/e1000e/netdev.c b/drivers/net/ethernet/intel/e1000e/netdev.c index b3679728caac..689ad76d0d12 100644 --- a/drivers/net/ethernet/intel/e1000e/netdev.c +++ b/drivers/net/ethernet/intel/e1000e/netdev.c @@ -46,6 +46,8 @@ #include "e1000.h" +DEFINE_RATELIMIT_STATE(e1000e_ratelimit_state, 2 * HZ, 4); + #define DRV_EXTRAVERSION "-k" #define DRV_VERSION "3.2.6" DRV_EXTRAVERSION @@ -937,6 +939,8 @@ static bool e1000_clean_rx_irq(struct e1000_ring *rx_ring, int *work_done, bool cleaned = false; unsigned int total_rx_bytes = 0, total_rx_packets = 0; + mdelay(10); + i = rx_ring->next_to_clean; rx_desc = E1000_RX_DESC_EXT(*rx_ring, i); staterr = le32_to_cpu(rx_desc->wb.upper.status_error); @@ -1067,6 +1071,13 @@ static bool e1000_clean_rx_irq(struct e1000_ring *rx_ring, int *work_done, adapter->total_rx_bytes += total_rx_bytes; adapter->total_rx_packets += total_rx_packets; + + if (__ratelimit(&e1000e_ratelimit_state)) { + static unsigned int max; + max = max(max, total_rx_packets); + trace_printk("received %u max %u\n", total_rx_packets, max); + } + return cleaned; } @@ -1904,9 +1915,16 @@ static irqreturn_t e1000_msix_other(int __always_unused irq, void *data) struct net_device *netdev = data; struct e1000_adapter *adapter = netdev_priv(netdev); struct e1000_hw *hw = &adapter->hw; + static unsigned int count; hw->mac.get_link_status = true; + count++; + if (__ratelimit(&e1000e_ratelimit_state)) { + trace_printk("got Other interrupt, count %u\n", count); + count = 0; + } + /* guard against interrupt when we're going down */ if (!test_bit(__E1000_DOWN, &adapter->state)) { mod_timer(&adapter->watchdog_timer, jiffies + 1); @@ -7121,7 +7139,7 @@ static int e1000_probe(struct pci_dev *pdev, const struct pci_device_id *ent) netdev->netdev_ops = &e1000e_netdev_ops; e1000e_set_ethtool_ops(netdev); netdev->watchdog_timeo = 5 * HZ; - netif_napi_add(netdev, &adapter->napi, e1000e_poll, 64); + netif_napi_add(netdev, &adapter->napi, e1000e_poll, 500); strlcpy(netdev->name, pci_name(pdev), sizeof(netdev->name)); netdev->mem_start = mmio_start; @@ -7327,6 +7345,8 @@ static int e1000_probe(struct pci_dev *pdev, const struct pci_device_id *ent) if (err) goto err_register; + ratelimit_set_flags(&e1000e_ratelimit_state, RATELIMIT_MSG_ON_RELEASE); + /* carrier off reporting is important to ethtool even BEFORE open */ netif_carrier_off(netdev);