| Message ID | 20201205234354.1710-1-jarod@redhat.com (mailing list archive) |
|---|---|
| State | Changes Requested |
| Delegated to: | Netdev Maintainers |
| Headers | show |
| Series | [net] bonding: reduce rtnl lock contention in mii monitor thread | expand |
| Context | Check | Description |
|---|---|---|
| netdev/cover_letter | success | Link |
| netdev/fixes_present | fail | Series targets non-next tree, but doesn't contain any Fixes tags |
| netdev/patch_count | success | Link |
| netdev/tree_selection | success | Clearly marked for net |
| netdev/subject_prefix | success | Link |
| netdev/source_inline | success | Was 0 now: 0 |
| netdev/verify_signedoff | success | Link |
| netdev/module_param | success | Was 0 now: 0 |
| netdev/build_32bit | success | Errors and warnings before: 17 this patch: 17 |
| netdev/kdoc | success | Errors and warnings before: 2 this patch: 2 |
| netdev/verify_fixes | success | Link |
| netdev/checkpatch | fail | ERROR: space required before the open parenthesis '(' WARNING: line length of 81 exceeds 80 columns |
| netdev/build_allmodconfig_warn | success | Errors and warnings before: 17 this patch: 17 |
| netdev/header_inline | success | Link |
| netdev/stable | success | Stable not CCed |
On Sat, 5 Dec 2020 18:43:54 -0500 Jarod Wilson wrote: > I'm seeing a system get stuck unable to bring a downed interface back up > when it's got an updelay value set, behavior which ceased when logging > spew was removed from bond_miimon_inspect(). I'm monitoring logs on this > system over another network connection, and it seems that the act of > spewing logs at all there increases rtnl lock contention, because > instrumented code showed bond_mii_monitor() never able to succeed in it's > attempts to call rtnl_trylock() to actually commit link state changes, > leaving the downed link stuck in BOND_LINK_DOWN. The system in question > appears to be fine with the log spew being moved to > bond_commit_link_state(), which is called after the successful > rtnl_trylock(). But it's not called under rtnl_lock AFAICT. So something else is also spewing messages? While bond_commit_link_state() _is_ called under the lock. So you're increasing the retry rate, by putting the slow operation under the lock, is that right? Also isn't bond_commit_link_state() called from many more places? So we're adding new prints, effectively? > I'm actually wondering if perhaps we ultimately need/want > some bond-specific lock here to prevent racing with bond_close() instead > of using rtnl, but this shift of the output appears to work. I believe > this started happening when de77ecd4ef02 ("bonding: improve link-status > update in mii-monitoring") went in, but I'm not 100% on that. > > The addition of a case BOND_LINK_BACK in bond_miimon_inspect() is somewhat > separate from the fix for the actual hang, but it eliminates a constant > "invalid new link 3 on slave" message seen related to this issue, and it's > not actually an invalid state here, so we shouldn't be reporting it as an > error. Let's make it a separate patch, then.
Jarod Wilson <jarod@redhat.com> wrote: >I'm seeing a system get stuck unable to bring a downed interface back up >when it's got an updelay value set, behavior which ceased when logging >spew was removed from bond_miimon_inspect(). I'm monitoring logs on this >system over another network connection, and it seems that the act of >spewing logs at all there increases rtnl lock contention, because >instrumented code showed bond_mii_monitor() never able to succeed in it's >attempts to call rtnl_trylock() to actually commit link state changes, >leaving the downed link stuck in BOND_LINK_DOWN. The system in question >appears to be fine with the log spew being moved to >bond_commit_link_state(), which is called after the successful >rtnl_trylock(). I'm actually wondering if perhaps we ultimately need/want >some bond-specific lock here to prevent racing with bond_close() instead >of using rtnl, but this shift of the output appears to work. I believe >this started happening when de77ecd4ef02 ("bonding: improve link-status >update in mii-monitoring") went in, but I'm not 100% on that. We use RTNL not to avoid deadlock with bonding itself, but because the "commit" side undertakes actions which require RTNL, e.g., various events will eventually call netdev_lower_state_changed. However, the RTNL acquisition is a trylock to avoid the deadlock with bond_close. Moving that out of line here (e.g., putting the commit into another work queue event or the like) has the same problem, in that bond_close needs to wait for all of the work queue events to finish, and it holds RTNL. Also, a dim memory says that the various notification messages were mostly placed in the "inspect" phase and not the "commit" phase to avoid doing printk-like activities with RTNL held. As a general principle, I don't think we want to add more verbiage under RTNL. >The addition of a case BOND_LINK_BACK in bond_miimon_inspect() is somewhat >separate from the fix for the actual hang, but it eliminates a constant >"invalid new link 3 on slave" message seen related to this issue, and it's >not actually an invalid state here, so we shouldn't be reporting it as an >error. Do you mean bond_miimon_commit here and not bond_miimon_inspect (which already has a case for BOND_LINK_BACK)? In principle, bond_miimon_commit should not see _BACK or _FAIL state as a new link state, because those states should be managed at the bond_miimon_inspect level (as they are the result of updelay and downdelay). These states should not be "committed" in the sense of causing notifications or doing actions that require RTNL. My recollection is that the "invalid new link" messages were the result of a bug in de77ecd4ef02, which was fixed in 1899bb325149 ("bonding: fix state transition issue in link monitoring"), but maybe the RTNL problem here induces that in some other fashion. Either way, I believe this message is correct as-is. -J >CC: Mahesh Bandewar <maheshb@google.com> >CC: Jay Vosburgh <j.vosburgh@gmail.com> >CC: Veaceslav Falico <vfalico@gmail.com> >CC: Andy Gospodarek <andy@greyhouse.net> >CC: "David S. Miller" <davem@davemloft.net> >CC: Jakub Kicinski <kuba@kernel.org> >CC: Thomas Davis <tadavis@lbl.gov> >CC: netdev@vger.kernel.org >Signed-off-by: Jarod Wilson <jarod@redhat.com> >--- > drivers/net/bonding/bond_main.c | 26 ++++++---------------- > include/net/bonding.h | 38 +++++++++++++++++++++++++++++++++ > 2 files changed, 44 insertions(+), 20 deletions(-) > >diff --git a/drivers/net/bonding/bond_main.c b/drivers/net/bonding/bond_main.c >index 47afc5938c26..cdb6c64f16b6 100644 >--- a/drivers/net/bonding/bond_main.c >+++ b/drivers/net/bonding/bond_main.c >@@ -2292,23 +2292,13 @@ static int bond_miimon_inspect(struct bonding *bond) > bond_propose_link_state(slave, BOND_LINK_FAIL); > commit++; > slave->delay = bond->params.downdelay; >- if (slave->delay) { >- slave_info(bond->dev, slave->dev, "link status down for %sinterface, disabling it in %d ms\n", >- (BOND_MODE(bond) == >- BOND_MODE_ACTIVEBACKUP) ? >- (bond_is_active_slave(slave) ? >- "active " : "backup ") : "", >- bond->params.downdelay * bond->params.miimon); >- } >+ > fallthrough; > case BOND_LINK_FAIL: > if (link_state) { > /* recovered before downdelay expired */ > bond_propose_link_state(slave, BOND_LINK_UP); > slave->last_link_up = jiffies; >- slave_info(bond->dev, slave->dev, "link status up again after %d ms\n", >- (bond->params.downdelay - slave->delay) * >- bond->params.miimon); > commit++; > continue; > } >@@ -2330,19 +2320,10 @@ static int bond_miimon_inspect(struct bonding *bond) > commit++; > slave->delay = bond->params.updelay; > >- if (slave->delay) { >- slave_info(bond->dev, slave->dev, "link status up, enabling it in %d ms\n", >- ignore_updelay ? 0 : >- bond->params.updelay * >- bond->params.miimon); >- } > fallthrough; > case BOND_LINK_BACK: > if (!link_state) { > bond_propose_link_state(slave, BOND_LINK_DOWN); >- slave_info(bond->dev, slave->dev, "link status down again after %d ms\n", >- (bond->params.updelay - slave->delay) * >- bond->params.miimon); > commit++; > continue; > } >@@ -2456,6 +2437,11 @@ static void bond_miimon_commit(struct bonding *bond) > > continue; > >+ case BOND_LINK_BACK: >+ bond_propose_link_state(slave, BOND_LINK_NOCHANGE); >+ >+ continue; >+ > default: > slave_err(bond->dev, slave->dev, "invalid new link %d on slave\n", > slave->link_new_state); >diff --git a/include/net/bonding.h b/include/net/bonding.h >index adc3da776970..6a09de9a3f03 100644 >--- a/include/net/bonding.h >+++ b/include/net/bonding.h >@@ -558,10 +558,48 @@ static inline void bond_propose_link_state(struct slave *slave, int state) > > static inline void bond_commit_link_state(struct slave *slave, bool notify) > { >+ struct bonding *bond = slave->bond; >+ > if (slave->link_new_state == BOND_LINK_NOCHANGE) > return; > >+ if (slave->link == slave->link_new_state) >+ return; >+ > slave->link = slave->link_new_state; >+ >+ switch(slave->link) { >+ case BOND_LINK_UP: >+ slave_info(bond->dev, slave->dev, "link status up again after %d ms\n", >+ (bond->params.downdelay - slave->delay) * >+ bond->params.miimon); >+ break; >+ >+ case BOND_LINK_FAIL: >+ if (slave->delay) { >+ slave_info(bond->dev, slave->dev, "link status down for %sinterface, disabling it in %d ms\n", >+ (BOND_MODE(bond) == >+ BOND_MODE_ACTIVEBACKUP) ? >+ (bond_is_active_slave(slave) ? >+ "active " : "backup ") : "", >+ bond->params.downdelay * bond->params.miimon); >+ } >+ break; >+ >+ case BOND_LINK_DOWN: >+ slave_info(bond->dev, slave->dev, "link status down again after %d ms\n", >+ (bond->params.updelay - slave->delay) * >+ bond->params.miimon); >+ break; >+ >+ case BOND_LINK_BACK: >+ if (slave->delay) { >+ slave_info(bond->dev, slave->dev, "link status up, enabling it in %d ms\n", >+ bond->params.updelay * bond->params.miimon); >+ } >+ break; >+ } >+ > if (notify) { > bond_queue_slave_event(slave); > bond_lower_state_changed(slave); >-- >2.28.0 > --- -Jay Vosburgh, jay.vosburgh@canonical.com
On Tue, Dec 8, 2020 at 2:38 PM Jakub Kicinski <kuba@kernel.org> wrote: > > On Sat, 5 Dec 2020 18:43:54 -0500 Jarod Wilson wrote: > > I'm seeing a system get stuck unable to bring a downed interface back up > > when it's got an updelay value set, behavior which ceased when logging > > spew was removed from bond_miimon_inspect(). I'm monitoring logs on this > > system over another network connection, and it seems that the act of > > spewing logs at all there increases rtnl lock contention, because > > instrumented code showed bond_mii_monitor() never able to succeed in it's > > attempts to call rtnl_trylock() to actually commit link state changes, > > leaving the downed link stuck in BOND_LINK_DOWN. The system in question > > appears to be fine with the log spew being moved to > > bond_commit_link_state(), which is called after the successful > > rtnl_trylock(). > > But it's not called under rtnl_lock AFAICT. So something else is also > spewing messages? > > While bond_commit_link_state() _is_ called under the lock. So you're > increasing the retry rate, by putting the slow operation under the > lock, is that right? Partially, yes. I probably should have tagged this with RFC instead of PATCH, tbh. My theory was that the log spew, being sent out *other* network interfaces when monitoring the system or remote syslog or ssh was potentially causing some rtnl_lock() calls, so not spewing until after actually being able to grab the lock would lessen the problem w/actually acquiring the lock, but I ... don't know offhand how to verify that theory. > Also isn't bond_commit_link_state() called from many more places? > So we're adding new prints, effectively? Ah. Crap. Yes. bond_set_slave_link_state() is called quite a few places, and that in turn calls bond_commit_link_state(). > > I'm actually wondering if perhaps we ultimately need/want > > some bond-specific lock here to prevent racing with bond_close() instead > > of using rtnl, but this shift of the output appears to work. I believe > > this started happening when de77ecd4ef02 ("bonding: improve link-status > > update in mii-monitoring") went in, but I'm not 100% on that. > > > > The addition of a case BOND_LINK_BACK in bond_miimon_inspect() is somewhat > > separate from the fix for the actual hang, but it eliminates a constant > > "invalid new link 3 on slave" message seen related to this issue, and it's > > not actually an invalid state here, so we shouldn't be reporting it as an > > error. > > Let's make it a separate patch, then. Sounds like Jay is confident that bit is valid, and I shouldn't be ending up in that state, unless something else is going wrong.
On Tue, Dec 8, 2020 at 3:35 PM Jay Vosburgh <jay.vosburgh@canonical.com> wrote: > > Jarod Wilson <jarod@redhat.com> wrote: > > >I'm seeing a system get stuck unable to bring a downed interface back up > >when it's got an updelay value set, behavior which ceased when logging > >spew was removed from bond_miimon_inspect(). I'm monitoring logs on this > >system over another network connection, and it seems that the act of > >spewing logs at all there increases rtnl lock contention, because > >instrumented code showed bond_mii_monitor() never able to succeed in it's > >attempts to call rtnl_trylock() to actually commit link state changes, > >leaving the downed link stuck in BOND_LINK_DOWN. The system in question > >appears to be fine with the log spew being moved to > >bond_commit_link_state(), which is called after the successful > >rtnl_trylock(). I'm actually wondering if perhaps we ultimately need/want > >some bond-specific lock here to prevent racing with bond_close() instead > >of using rtnl, but this shift of the output appears to work. I believe > >this started happening when de77ecd4ef02 ("bonding: improve link-status > >update in mii-monitoring") went in, but I'm not 100% on that. > > We use RTNL not to avoid deadlock with bonding itself, but > because the "commit" side undertakes actions which require RTNL, e.g., > various events will eventually call netdev_lower_state_changed. > > However, the RTNL acquisition is a trylock to avoid the deadlock > with bond_close. Moving that out of line here (e.g., putting the commit > into another work queue event or the like) has the same problem, in that > bond_close needs to wait for all of the work queue events to finish, and > it holds RTNL. Ah, okay, it wasn't clear to me that we actually do need RTNL here, I'd thought it was just for the deadlock avoidance with bond_close, based on the comments in the source. > Also, a dim memory says that the various notification messages > were mostly placed in the "inspect" phase and not the "commit" phase to > avoid doing printk-like activities with RTNL held. As a general > principle, I don't think we want to add more verbiage under RTNL. Yeah, that's fair. > >The addition of a case BOND_LINK_BACK in bond_miimon_inspect() is somewhat > >separate from the fix for the actual hang, but it eliminates a constant > >"invalid new link 3 on slave" message seen related to this issue, and it's > >not actually an invalid state here, so we shouldn't be reporting it as an > >error. > > Do you mean bond_miimon_commit here and not bond_miimon_inspect > (which already has a case for BOND_LINK_BACK)? Whoops, yes. > In principle, bond_miimon_commit should not see _BACK or _FAIL > state as a new link state, because those states should be managed at the > bond_miimon_inspect level (as they are the result of updelay and > downdelay). These states should not be "committed" in the sense of > causing notifications or doing actions that require RTNL. > > My recollection is that the "invalid new link" messages were the > result of a bug in de77ecd4ef02, which was fixed in 1899bb325149 > ("bonding: fix state transition issue in link monitoring"), but maybe > the RTNL problem here induces that in some other fashion. > > Either way, I believe this message is correct as-is. Hm, okay, definitely seeing this message pop up regularly when a link recovers, using a fairly simple reproducer: slave1=p6p1 slave2=p6p2 modprobe -rv bonding modprobe -v bonding mode=2 miimon=100 updelay=200 ip link set bond0 up ifenslave bond0 $slave1 $slave2 sleep 10 while : do ip link set $slave1 down sleep 1 ip link set $slave1 up sleep 1 done I wasn't actually seeing the problem until I was running a 'watch -n 1 "dmesg | tail -n 50"' or similar in a remote ssh session on the host. I should add the caveat that this was also initially seen on an older kernel, but with a fairly up-to-date bonding driver, which does include both de77ecd4ef02 and 1899bb325149. I'm going to keep prodding w/a more recent upstreamier kernel, and see if I can get a better idea of what's actually going on.
On Tue, Dec 8, 2020 at 3:35 PM Jay Vosburgh <jay.vosburgh@canonical.com> wrote: > > Jarod Wilson <jarod@redhat.com> wrote: ... > >The addition of a case BOND_LINK_BACK in bond_miimon_commit() is somewhat > >separate from the fix for the actual hang, but it eliminates a constant > >"invalid new link 3 on slave" message seen related to this issue, and it's > >not actually an invalid state here, so we shouldn't be reporting it as an > >error. ... > In principle, bond_miimon_commit should not see _BACK or _FAIL > state as a new link state, because those states should be managed at the > bond_miimon_inspect level (as they are the result of updelay and > downdelay). These states should not be "committed" in the sense of > causing notifications or doing actions that require RTNL. > > My recollection is that the "invalid new link" messages were the > result of a bug in de77ecd4ef02, which was fixed in 1899bb325149 > ("bonding: fix state transition issue in link monitoring"), but maybe > the RTNL problem here induces that in some other fashion. > > Either way, I believe this message is correct as-is. For reference, with 5.10.1 and this script: #!/bin/sh slave1=ens4f0 slave2=ens4f1 modprobe -rv bonding modprobe -v bonding mode=2 miimon=100 updelay=200 ip link set bond0 up ifenslave bond0 $slave1 $slave2 sleep 5 while : do ip link set $slave1 down sleep 1 ip link set $slave1 up sleep 1 done I get this repeating log output: [ 9488.262291] sfc 0000:05:00.0 ens4f0: link up at 10000Mbps full-duplex (MTU 1500) [ 9488.339508] bond0: (slave ens4f0): link status up, enabling it in 200 ms [ 9488.339511] bond0: (slave ens4f0): invalid new link 3 on slave [ 9488.547643] bond0: (slave ens4f0): link status definitely up, 10000 Mbps full duplex [ 9489.276614] bond0: (slave ens4f0): link status definitely down, disabling slave [ 9490.273830] sfc 0000:05:00.0 ens4f0: link up at 10000Mbps full-duplex (MTU 1500) [ 9490.315540] bond0: (slave ens4f0): link status up, enabling it in 200 ms [ 9490.315543] bond0: (slave ens4f0): invalid new link 3 on slave [ 9490.523641] bond0: (slave ens4f0): link status definitely up, 10000 Mbps full duplex [ 9491.356526] bond0: (slave ens4f0): link status definitely down, disabling slave [ 9492.285249] sfc 0000:05:00.0 ens4f0: link up at 10000Mbps full-duplex (MTU 1500) [ 9492.291522] bond0: (slave ens4f0): link status up, enabling it in 200 ms [ 9492.291523] bond0: (slave ens4f0): invalid new link 3 on slave [ 9492.499604] bond0: (slave ens4f0): link status definitely up, 10000 Mbps full duplex [ 9493.331594] bond0: (slave ens4f0): link status definitely down, disabling slave "invalid new link 3 on slave" is there every single time. Side note: I'm not actually able to reproduce the repeating "link status up, enabling it in 200 ms" and never recovering from a downed link on this host, no clue why it's so reproducible w/another system.
diff --git a/drivers/net/bonding/bond_main.c b/drivers/net/bonding/bond_main.c index 47afc5938c26..cdb6c64f16b6 100644 --- a/drivers/net/bonding/bond_main.c +++ b/drivers/net/bonding/bond_main.c @@ -2292,23 +2292,13 @@ static int bond_miimon_inspect(struct bonding *bond) bond_propose_link_state(slave, BOND_LINK_FAIL); commit++; slave->delay = bond->params.downdelay; - if (slave->delay) { - slave_info(bond->dev, slave->dev, "link status down for %sinterface, disabling it in %d ms\n", - (BOND_MODE(bond) == - BOND_MODE_ACTIVEBACKUP) ? - (bond_is_active_slave(slave) ? - "active " : "backup ") : "", - bond->params.downdelay * bond->params.miimon); - } + fallthrough; case BOND_LINK_FAIL: if (link_state) { /* recovered before downdelay expired */ bond_propose_link_state(slave, BOND_LINK_UP); slave->last_link_up = jiffies; - slave_info(bond->dev, slave->dev, "link status up again after %d ms\n", - (bond->params.downdelay - slave->delay) * - bond->params.miimon); commit++; continue; } @@ -2330,19 +2320,10 @@ static int bond_miimon_inspect(struct bonding *bond) commit++; slave->delay = bond->params.updelay; - if (slave->delay) { - slave_info(bond->dev, slave->dev, "link status up, enabling it in %d ms\n", - ignore_updelay ? 0 : - bond->params.updelay * - bond->params.miimon); - } fallthrough; case BOND_LINK_BACK: if (!link_state) { bond_propose_link_state(slave, BOND_LINK_DOWN); - slave_info(bond->dev, slave->dev, "link status down again after %d ms\n", - (bond->params.updelay - slave->delay) * - bond->params.miimon); commit++; continue; } @@ -2456,6 +2437,11 @@ static void bond_miimon_commit(struct bonding *bond) continue; + case BOND_LINK_BACK: + bond_propose_link_state(slave, BOND_LINK_NOCHANGE); + + continue; + default: slave_err(bond->dev, slave->dev, "invalid new link %d on slave\n", slave->link_new_state); diff --git a/include/net/bonding.h b/include/net/bonding.h index adc3da776970..6a09de9a3f03 100644 --- a/include/net/bonding.h +++ b/include/net/bonding.h @@ -558,10 +558,48 @@ static inline void bond_propose_link_state(struct slave *slave, int state) static inline void bond_commit_link_state(struct slave *slave, bool notify) { + struct bonding *bond = slave->bond; + if (slave->link_new_state == BOND_LINK_NOCHANGE) return; + if (slave->link == slave->link_new_state) + return; + slave->link = slave->link_new_state; + + switch(slave->link) { + case BOND_LINK_UP: + slave_info(bond->dev, slave->dev, "link status up again after %d ms\n", + (bond->params.downdelay - slave->delay) * + bond->params.miimon); + break; + + case BOND_LINK_FAIL: + if (slave->delay) { + slave_info(bond->dev, slave->dev, "link status down for %sinterface, disabling it in %d ms\n", + (BOND_MODE(bond) == + BOND_MODE_ACTIVEBACKUP) ? + (bond_is_active_slave(slave) ? + "active " : "backup ") : "", + bond->params.downdelay * bond->params.miimon); + } + break; + + case BOND_LINK_DOWN: + slave_info(bond->dev, slave->dev, "link status down again after %d ms\n", + (bond->params.updelay - slave->delay) * + bond->params.miimon); + break; + + case BOND_LINK_BACK: + if (slave->delay) { + slave_info(bond->dev, slave->dev, "link status up, enabling it in %d ms\n", + bond->params.updelay * bond->params.miimon); + } + break; + } + if (notify) { bond_queue_slave_event(slave); bond_lower_state_changed(slave);
I'm seeing a system get stuck unable to bring a downed interface back up when it's got an updelay value set, behavior which ceased when logging spew was removed from bond_miimon_inspect(). I'm monitoring logs on this system over another network connection, and it seems that the act of spewing logs at all there increases rtnl lock contention, because instrumented code showed bond_mii_monitor() never able to succeed in it's attempts to call rtnl_trylock() to actually commit link state changes, leaving the downed link stuck in BOND_LINK_DOWN. The system in question appears to be fine with the log spew being moved to bond_commit_link_state(), which is called after the successful rtnl_trylock(). I'm actually wondering if perhaps we ultimately need/want some bond-specific lock here to prevent racing with bond_close() instead of using rtnl, but this shift of the output appears to work. I believe this started happening when de77ecd4ef02 ("bonding: improve link-status update in mii-monitoring") went in, but I'm not 100% on that. The addition of a case BOND_LINK_BACK in bond_miimon_inspect() is somewhat separate from the fix for the actual hang, but it eliminates a constant "invalid new link 3 on slave" message seen related to this issue, and it's not actually an invalid state here, so we shouldn't be reporting it as an error. CC: Mahesh Bandewar <maheshb@google.com> CC: Jay Vosburgh <j.vosburgh@gmail.com> CC: Veaceslav Falico <vfalico@gmail.com> CC: Andy Gospodarek <andy@greyhouse.net> CC: "David S. Miller" <davem@davemloft.net> CC: Jakub Kicinski <kuba@kernel.org> CC: Thomas Davis <tadavis@lbl.gov> CC: netdev@vger.kernel.org Signed-off-by: Jarod Wilson <jarod@redhat.com> --- drivers/net/bonding/bond_main.c | 26 ++++++---------------- include/net/bonding.h | 38 +++++++++++++++++++++++++++++++++ 2 files changed, 44 insertions(+), 20 deletions(-)