linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [PATCH net] bonding: reduce rtnl lock contention in mii monitor thread
@ 2020-12-05 23:43 Jarod Wilson
  2020-12-08 19:38 ` Jakub Kicinski
  2020-12-08 20:34 ` Jay Vosburgh
  0 siblings, 2 replies; 6+ messages in thread
From: Jarod Wilson @ 2020-12-05 23:43 UTC (permalink / raw)
  To: linux-kernel
  Cc: Jarod Wilson, Mahesh Bandewar, Jay Vosburgh, Veaceslav Falico,
	Andy Gospodarek, David S. Miller, Jakub Kicinski, Thomas Davis,
	netdev

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(-)

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


^ permalink raw reply related	[flat|nested] 6+ messages in thread

* Re: [PATCH net] bonding: reduce rtnl lock contention in mii monitor thread
  2020-12-05 23:43 [PATCH net] bonding: reduce rtnl lock contention in mii monitor thread Jarod Wilson
@ 2020-12-08 19:38 ` Jakub Kicinski
  2020-12-09 15:08   ` Jarod Wilson
  2020-12-08 20:34 ` Jay Vosburgh
  1 sibling, 1 reply; 6+ messages in thread
From: Jakub Kicinski @ 2020-12-08 19:38 UTC (permalink / raw)
  To: Jarod Wilson
  Cc: linux-kernel, Mahesh Bandewar, Jay Vosburgh, Veaceslav Falico,
	Andy Gospodarek, David S. Miller, Thomas Davis, netdev

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.

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [PATCH net] bonding: reduce rtnl lock contention in mii monitor thread
  2020-12-05 23:43 [PATCH net] bonding: reduce rtnl lock contention in mii monitor thread Jarod Wilson
  2020-12-08 19:38 ` Jakub Kicinski
@ 2020-12-08 20:34 ` Jay Vosburgh
  2020-12-09 15:26   ` Jarod Wilson
  2020-12-18 23:48   ` Jarod Wilson
  1 sibling, 2 replies; 6+ messages in thread
From: Jay Vosburgh @ 2020-12-08 20:34 UTC (permalink / raw)
  To: Jarod Wilson
  Cc: linux-kernel, Mahesh Bandewar, Veaceslav Falico, Andy Gospodarek,
	David S. Miller, Jakub Kicinski, Thomas Davis, netdev

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

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [PATCH net] bonding: reduce rtnl lock contention in mii monitor thread
  2020-12-08 19:38 ` Jakub Kicinski
@ 2020-12-09 15:08   ` Jarod Wilson
  0 siblings, 0 replies; 6+ messages in thread
From: Jarod Wilson @ 2020-12-09 15:08 UTC (permalink / raw)
  To: Jakub Kicinski
  Cc: LKML, Mahesh Bandewar, Jay Vosburgh, Veaceslav Falico,
	Andy Gospodarek, David S. Miller, Thomas Davis, Netdev

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.

-- 
Jarod Wilson
jarod@redhat.com


^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [PATCH net] bonding: reduce rtnl lock contention in mii monitor thread
  2020-12-08 20:34 ` Jay Vosburgh
@ 2020-12-09 15:26   ` Jarod Wilson
  2020-12-18 23:48   ` Jarod Wilson
  1 sibling, 0 replies; 6+ messages in thread
From: Jarod Wilson @ 2020-12-09 15:26 UTC (permalink / raw)
  To: Jay Vosburgh
  Cc: LKML, Mahesh Bandewar, Veaceslav Falico, Andy Gospodarek,
	David S. Miller, Jakub Kicinski, Thomas Davis, Netdev

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.

-- 
Jarod Wilson
jarod@redhat.com


^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [PATCH net] bonding: reduce rtnl lock contention in mii monitor thread
  2020-12-08 20:34 ` Jay Vosburgh
  2020-12-09 15:26   ` Jarod Wilson
@ 2020-12-18 23:48   ` Jarod Wilson
  1 sibling, 0 replies; 6+ messages in thread
From: Jarod Wilson @ 2020-12-18 23:48 UTC (permalink / raw)
  To: Jay Vosburgh
  Cc: LKML, Mahesh Bandewar, Veaceslav Falico, Andy Gospodarek,
	David S. Miller, Jakub Kicinski, Thomas Davis, Netdev

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.

-- 
Jarod Wilson
jarod@redhat.com


^ permalink raw reply	[flat|nested] 6+ messages in thread

end of thread, other threads:[~2020-12-18 23:50 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-12-05 23:43 [PATCH net] bonding: reduce rtnl lock contention in mii monitor thread Jarod Wilson
2020-12-08 19:38 ` Jakub Kicinski
2020-12-09 15:08   ` Jarod Wilson
2020-12-08 20:34 ` Jay Vosburgh
2020-12-09 15:26   ` Jarod Wilson
2020-12-18 23:48   ` Jarod Wilson

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).