[PATCH RFC] bonding: rate-limit bonding driver inspect messages

[PATCH RFC] bonding: rate-limit bonding driver inspect messages

[Praveen Kumar Kannoju]

Rate limit bond driver log messages, to prevent a log flood in a run-away
situation, e.g couldn't get rtnl lock. Message flood leads to instability
of system and loss of other crucial messages.

Signed-off-by: Praveen Kumar Kannoju <praveen.kannoju@oracle.com>
---
 drivers/net/bonding/bond_main.c | 34 +++++++++++++++++++---------------
 include/net/bonding.h           | 11 +++++++++++
 2 files changed, 30 insertions(+), 15 deletions(-)

diff --git a/drivers/net/bonding/bond_main.c b/drivers/net/bonding/bond_main.c
index 4e0600c..32098dd 100644
--- a/drivers/net/bonding/bond_main.c
+++ b/drivers/net/bonding/bond_main.c
@@ -2610,12 +2610,13 @@ static int bond_miimon_inspect(struct bonding *bond)
 			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) ?
+				bond_info_rl(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);
+					     bond->params.downdelay * bond->params.miimon);
 			}
 			fallthrough;
 		case BOND_LINK_FAIL:
@@ -2623,9 +2624,10 @@ static int bond_miimon_inspect(struct bonding *bond)
 				/* 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);
+				bond_info_rl(bond->dev, slave->dev,
+					     "link status up again after %d ms\n",
+					     (bond->params.downdelay - slave->delay) *
+					     bond->params.miimon);
 				commit++;
 				continue;
 			}
@@ -2648,18 +2650,20 @@ static int bond_miimon_inspect(struct bonding *bond)
 			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);
+				bond_info_rl(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);
+				bond_info_rl(bond->dev, slave->dev,
+					     "link status down again after %d ms\n",
+					     (bond->params.updelay - slave->delay) *
+					     bond->params.miimon);
 				commit++;
 				continue;
 			}
diff --git a/include/net/bonding.h b/include/net/bonding.h
index 5b8b1b6..ebdfaf0 100644
--- a/include/net/bonding.h
+++ b/include/net/bonding.h
@@ -39,8 +39,19 @@
 #define __long_aligned __attribute__((aligned((sizeof(long)))))
 #endif
 
+DEFINE_RATELIMIT_STATE(bond_rs, DEFAULT_RATELIMIT_INTERVAL,
+		       DEFAULT_RATELIMIT_BURST);
+
+#define bond_ratelimited_function(function, ...)	\
+do {							\
+	if (__ratelimit(&bond_rs))		\
+		function(__VA_ARGS__);			\
+} while (0)
+
 #define slave_info(bond_dev, slave_dev, fmt, ...) \
 	netdev_info(bond_dev, "(slave %s): " fmt, (slave_dev)->name, ##__VA_ARGS__)
+#define bond_info_rl(bond_dev, slave_dev, fmt, ...) \
+	bond_ratelimited_function(slave_info, fmt, ##__VA_ARGS__)
 #define slave_warn(bond_dev, slave_dev, fmt, ...) \
 	netdev_warn(bond_dev, "(slave %s): " fmt, (slave_dev)->name, ##__VA_ARGS__)
 #define slave_dbg(bond_dev, slave_dev, fmt, ...) \
-- 
1.8.3.1

Re: [PATCH RFC] bonding: rate-limit bonding driver inspect messages

[Jay Vosburgh]

Praveen Kumar Kannoju <praveen.kannoju@oracle.com> wrote:

>Rate limit bond driver log messages, to prevent a log flood in a run-away
>situation, e.g couldn't get rtnl lock. Message flood leads to instability
>of system and loss of other crucial messages.
>
>Signed-off-by: Praveen Kumar Kannoju <praveen.kannoju@oracle.com>
>---
> drivers/net/bonding/bond_main.c | 34 +++++++++++++++++++---------------
> include/net/bonding.h           | 11 +++++++++++
> 2 files changed, 30 insertions(+), 15 deletions(-)
>
>diff --git a/drivers/net/bonding/bond_main.c b/drivers/net/bonding/bond_main.c
>index 4e0600c..32098dd 100644
>--- a/drivers/net/bonding/bond_main.c
>+++ b/drivers/net/bonding/bond_main.c
>@@ -2610,12 +2610,13 @@ static int bond_miimon_inspect(struct bonding *bond)
> 			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) ?
>+				bond_info_rl(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);
>+					     bond->params.downdelay * bond->params.miimon);

	Why not use net_info_ratelimited() or net_ratelimit()?  The rest
of the bonding messages that are rate limited are almost all gated by
the net rate limiter.

	-J

> 			}
> 			fallthrough;
> 		case BOND_LINK_FAIL:
>@@ -2623,9 +2624,10 @@ static int bond_miimon_inspect(struct bonding *bond)
> 				/* 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);
>+				bond_info_rl(bond->dev, slave->dev,
>+					     "link status up again after %d ms\n",
>+					     (bond->params.downdelay - slave->delay) *
>+					     bond->params.miimon);
> 				commit++;
> 				continue;
> 			}
>@@ -2648,18 +2650,20 @@ static int bond_miimon_inspect(struct bonding *bond)
> 			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);
>+				bond_info_rl(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);
>+				bond_info_rl(bond->dev, slave->dev,
>+					     "link status down again after %d ms\n",
>+					     (bond->params.updelay - slave->delay) *
>+					     bond->params.miimon);
> 				commit++;
> 				continue;
> 			}
>diff --git a/include/net/bonding.h b/include/net/bonding.h
>index 5b8b1b6..ebdfaf0 100644
>--- a/include/net/bonding.h
>+++ b/include/net/bonding.h
>@@ -39,8 +39,19 @@
> #define __long_aligned __attribute__((aligned((sizeof(long)))))
> #endif
> 
>+DEFINE_RATELIMIT_STATE(bond_rs, DEFAULT_RATELIMIT_INTERVAL,
>+		       DEFAULT_RATELIMIT_BURST);
>+
>+#define bond_ratelimited_function(function, ...)	\
>+do {							\
>+	if (__ratelimit(&bond_rs))		\
>+		function(__VA_ARGS__);			\
>+} while (0)
>+
> #define slave_info(bond_dev, slave_dev, fmt, ...) \
> 	netdev_info(bond_dev, "(slave %s): " fmt, (slave_dev)->name, ##__VA_ARGS__)
>+#define bond_info_rl(bond_dev, slave_dev, fmt, ...) \
>+	bond_ratelimited_function(slave_info, fmt, ##__VA_ARGS__)
> #define slave_warn(bond_dev, slave_dev, fmt, ...) \
> 	netdev_warn(bond_dev, "(slave %s): " fmt, (slave_dev)->name, ##__VA_ARGS__)
> #define slave_dbg(bond_dev, slave_dev, fmt, ...) \
>-- 
>1.8.3.1
>
>

---
	-Jay Vosburgh, jay.vosburgh@canonical.com

RE: [PATCH RFC] bonding: rate-limit bonding driver inspect messages

[Praveen Kannoju]

> -----Original Message-----
> From: Jay Vosburgh <jay.vosburgh@canonical.com>
> Sent: 15 February 2024 12:05 AM
> To: Praveen Kannoju <praveen.kannoju@oracle.com>
> Cc: andy@greyhouse.net; davem@davemloft.net; edumazet@google.com; kuba@kernel.org; pabeni@redhat.com;
> netdev@vger.kernel.org; linux-kernel@vger.kernel.org; Rajesh Sivaramasubramaniom <rajesh.sivaramasubramaniom@oracle.com>;
> Rama Nichanamatlu <rama.nichanamatlu@oracle.com>; Manjunath Patil <manjunath.b.patil@oracle.com>
> Subject: Re: [PATCH RFC] bonding: rate-limit bonding driver inspect messages
> 
> Praveen Kumar Kannoju <praveen.kannoju@oracle.com> wrote:
> 
> >Rate limit bond driver log messages, to prevent a log flood in a
> >run-away situation, e.g couldn't get rtnl lock. Message flood leads to
> >instability of system and loss of other crucial messages.
> >
> >Signed-off-by: Praveen Kumar Kannoju <praveen.kannoju@oracle.com>
> >---
> > drivers/net/bonding/bond_main.c | 34 +++++++++++++++++++---------------
> > include/net/bonding.h           | 11 +++++++++++
> > 2 files changed, 30 insertions(+), 15 deletions(-)
> >
> >diff --git a/drivers/net/bonding/bond_main.c
> >b/drivers/net/bonding/bond_main.c index 4e0600c..32098dd 100644
> >--- a/drivers/net/bonding/bond_main.c
> >+++ b/drivers/net/bonding/bond_main.c
> >@@ -2610,12 +2610,13 @@ static int bond_miimon_inspect(struct bonding *bond)
> > 			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) ?
> >+				bond_info_rl(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);
> >+					     bond->params.downdelay * bond->params.miimon);
> 
> 	Why not use net_info_ratelimited() or net_ratelimit()?  The rest of the bonding messages that are rate limited are almost all
> gated by the net rate limiter.
> 
> 	-J

Thank you for the reply, Jay. Yes, I agree. Used net_ratelimit() and resent the v2 patch. Please review and provide your comments.

> 
> > 			}
> > 			fallthrough;
> > 		case BOND_LINK_FAIL:
> >@@ -2623,9 +2624,10 @@ static int bond_miimon_inspect(struct bonding *bond)
> > 				/* 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);
> >+				bond_info_rl(bond->dev, slave->dev,
> >+					     "link status up again after %d ms\n",
> >+					     (bond->params.downdelay - slave->delay) *
> >+					     bond->params.miimon);
> > 				commit++;
> > 				continue;
> > 			}
> >@@ -2648,18 +2650,20 @@ static int bond_miimon_inspect(struct bonding *bond)
> > 			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);
> >+				bond_info_rl(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);
> >+				bond_info_rl(bond->dev, slave->dev,
> >+					     "link status down again after %d ms\n",
> >+					     (bond->params.updelay - slave->delay) *
> >+					     bond->params.miimon);
> > 				commit++;
> > 				continue;
> > 			}
> >diff --git a/include/net/bonding.h b/include/net/bonding.h index
> >5b8b1b6..ebdfaf0 100644
> >--- a/include/net/bonding.h
> >+++ b/include/net/bonding.h
> >@@ -39,8 +39,19 @@
> > #define __long_aligned __attribute__((aligned((sizeof(long)))))
> > #endif
> >
> >+DEFINE_RATELIMIT_STATE(bond_rs, DEFAULT_RATELIMIT_INTERVAL,
> >+		       DEFAULT_RATELIMIT_BURST);
> >+
> >+#define bond_ratelimited_function(function, ...)	\
> >+do {							\
> >+	if (__ratelimit(&bond_rs))		\
> >+		function(__VA_ARGS__);			\
> >+} while (0)
> >+
> > #define slave_info(bond_dev, slave_dev, fmt, ...) \
> > 	netdev_info(bond_dev, "(slave %s): " fmt, (slave_dev)->name,
> > ##__VA_ARGS__)
> >+#define bond_info_rl(bond_dev, slave_dev, fmt, ...) \
> >+	bond_ratelimited_function(slave_info, fmt, ##__VA_ARGS__)
> > #define slave_warn(bond_dev, slave_dev, fmt, ...) \
> > 	netdev_warn(bond_dev, "(slave %s): " fmt, (slave_dev)->name,
> >##__VA_ARGS__)  #define slave_dbg(bond_dev, slave_dev, fmt, ...) \
> >--
> >1.8.3.1
> >
> >
> 
> ---
> 	-Jay Vosburgh, jay.vosburgh@canonical.com

[PATCH RFC] bonding: rate-limit bonding driver inspect messages

[Praveen Kumar Kannoju]

Rate limit bond driver log messages, to prevent a log flood in a run-away
situation, e.g couldn't get rtnl lock. Message flood leads to instability
of system and loss of other crucial messages.

v2: Use exising net_ratelimit() instead of introducing new rate-limit
parameter.

Signed-off-by: Praveen Kumar Kannoju <praveen.kannoju@oracle.com>
---
 drivers/net/bonding/bond_main.c | 36 ++++++++++++++++++++----------------
 1 file changed, 20 insertions(+), 16 deletions(-)

diff --git a/drivers/net/bonding/bond_main.c b/drivers/net/bonding/bond_main.c
index 4e0600c..e92eba1 100644
--- a/drivers/net/bonding/bond_main.c
+++ b/drivers/net/bonding/bond_main.c
@@ -2610,12 +2610,13 @@ static int bond_miimon_inspect(struct bonding *bond)
 			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);
+				if (net_ratelimit())
+					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:
@@ -2623,9 +2624,10 @@ static int bond_miimon_inspect(struct bonding *bond)
 				/* 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);
+				if (net_ratelimit())
+					slave_info(bond->dev, slave->dev, "link status up again after %d ms\n",
+						   (bond->params.downdelay - slave->delay) *
+						   bond->params.miimon);
 				commit++;
 				continue;
 			}
@@ -2648,18 +2650,20 @@ static int bond_miimon_inspect(struct bonding *bond)
 			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);
+				if (net_ratelimit())
+					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);
+				if (net_ratelimit())
+					slave_info(bond->dev, slave->dev, "link status down again after %d ms\n",
+						   (bond->params.updelay - slave->delay) *
+						   bond->params.miimon);
 				commit++;
 				continue;
 			}
-- 
1.8.3.1

Re: [PATCH RFC] bonding: rate-limit bonding driver inspect messages

[Hangbin Liu]

On Thu, Feb 15, 2024 at 10:55:54PM +0530, Praveen Kumar Kannoju wrote:
> Rate limit bond driver log messages, to prevent a log flood in a run-away
> situation, e.g couldn't get rtnl lock. Message flood leads to instability
> of system and loss of other crucial messages.

Hi Praveen,

The patch looks good to me. But would you please help explain why these
slave_info() are chosen under net_ratelimit?

Thanks
Hangbin
> 
> v2: Use exising net_ratelimit() instead of introducing new rate-limit
> parameter.
> 
> Signed-off-by: Praveen Kumar Kannoju <praveen.kannoju@oracle.com>
> ---
>  drivers/net/bonding/bond_main.c | 36 ++++++++++++++++++++----------------
>  1 file changed, 20 insertions(+), 16 deletions(-)
> 
> diff --git a/drivers/net/bonding/bond_main.c b/drivers/net/bonding/bond_main.c
> index 4e0600c..e92eba1 100644
> --- a/drivers/net/bonding/bond_main.c
> +++ b/drivers/net/bonding/bond_main.c
> @@ -2610,12 +2610,13 @@ static int bond_miimon_inspect(struct bonding *bond)
>  			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);
> +				if (net_ratelimit())
> +					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:
> @@ -2623,9 +2624,10 @@ static int bond_miimon_inspect(struct bonding *bond)
>  				/* 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);
> +				if (net_ratelimit())
> +					slave_info(bond->dev, slave->dev, "link status up again after %d ms\n",
> +						   (bond->params.downdelay - slave->delay) *
> +						   bond->params.miimon);
>  				commit++;
>  				continue;
>  			}
> @@ -2648,18 +2650,20 @@ static int bond_miimon_inspect(struct bonding *bond)
>  			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);
> +				if (net_ratelimit())
> +					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);
> +				if (net_ratelimit())
> +					slave_info(bond->dev, slave->dev, "link status down again after %d ms\n",
> +						   (bond->params.updelay - slave->delay) *
> +						   bond->params.miimon);
>  				commit++;
>  				continue;
>  			}
> -- 
> 1.8.3.1
> 

RE: [PATCH RFC] bonding: rate-limit bonding driver inspect messages

[Praveen Kannoju]

> -----Original Message-----
> From: Hangbin Liu <liuhangbin@gmail.com>
> Sent: 16 February 2024 02:33 PM
> To: Praveen Kannoju <praveen.kannoju@oracle.com>
> Cc: j.vosburgh@gmail.com; andy@greyhouse.net; davem@davemloft.net; edumazet@google.com; kuba@kernel.org;
> pabeni@redhat.com; netdev@vger.kernel.org; linux-kernel@vger.kernel.org; Rajesh Sivaramasubramaniom
> <rajesh.sivaramasubramaniom@oracle.com>; Rama Nichanamatlu <rama.nichanamatlu@oracle.com>; Manjunath Patil
> <manjunath.b.patil@oracle.com>
> Subject: Re: [PATCH RFC] bonding: rate-limit bonding driver inspect messages
> 
> On Thu, Feb 15, 2024 at 10:55:54PM +0530, Praveen Kumar Kannoju wrote:
> > Rate limit bond driver log messages, to prevent a log flood in a
> > run-away situation, e.g couldn't get rtnl lock. Message flood leads to
> > instability of system and loss of other crucial messages.
> 
> Hi Praveen,
> 
> The patch looks good to me. But would you please help explain why these
> slave_info() are chosen under net_ratelimit?
> 
> Thanks
> Hangbin

Thank you, Hangbin.

The routine bond_mii_monitor() periodically inspects the slave carrier state in order to detect for state changes, on a state change internally records it and does the state change action.

Parked-to-Parked state changes goes through transient state. As an example for Up to Down, BOND_LINK_UP to BOND_LINK_DOWN, is thru BOND_LINK_FAIL.  In order to attain next parked state or transient state bond needs rtnl mutex. If in a situation it cannot get it, a state change wouldn't happen.  In order to achieve a state change as quickly as possible  bond_mii_monitor() reschedules itself to come around after 1 msec. And every single come around reinspects the link and sees a state change compared to its internally recorded, which in reality internal state could be not changed earlier as failed to get rtnl lock, and throws again log indicating it sees a state change. If attaining rtnl mutex take long say hypothetical 5 secs, then bond logs 5000 state change message. 1 message at every 1 msec. 

And in production environments we have seen bond taking long to achieve a state as someone else holding rtnl. Many processes do get rtnl lock.  As an example we can see eth drivers. They hold rtnl mutex for the entire duration while performing a fault recovery. There are many such scenarios.

This patch doesn't change -how- bond functions. It only simply limits this kind of log flood. 

-
Praveen.
> >
> > v2: Use exising net_ratelimit() instead of introducing new rate-limit
> > parameter.
> >
> > Signed-off-by: Praveen Kumar Kannoju <praveen.kannoju@oracle.com>
> > ---
> >  drivers/net/bonding/bond_main.c | 36
> > ++++++++++++++++++++----------------
> >  1 file changed, 20 insertions(+), 16 deletions(-)
> >
> > diff --git a/drivers/net/bonding/bond_main.c
> > b/drivers/net/bonding/bond_main.c index 4e0600c..e92eba1 100644
> > --- a/drivers/net/bonding/bond_main.c
> > +++ b/drivers/net/bonding/bond_main.c
> > @@ -2610,12 +2610,13 @@ static int bond_miimon_inspect(struct bonding *bond)
> >  			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);
> > +				if (net_ratelimit())
> > +					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:
> > @@ -2623,9 +2624,10 @@ static int bond_miimon_inspect(struct bonding *bond)
> >  				/* 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);
> > +				if (net_ratelimit())
> > +					slave_info(bond->dev, slave->dev, "link status up again after %d ms\n",
> > +						   (bond->params.downdelay - slave->delay) *
> > +						   bond->params.miimon);
> >  				commit++;
> >  				continue;
> >  			}
> > @@ -2648,18 +2650,20 @@ static int bond_miimon_inspect(struct bonding *bond)
> >  			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);
> > +				if (net_ratelimit())
> > +					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);
> > +				if (net_ratelimit())
> > +					slave_info(bond->dev, slave->dev, "link status down again after %d ms\n",
> > +						   (bond->params.updelay - slave->delay) *
> > +						   bond->params.miimon);
> >  				commit++;
> >  				continue;
> >  			}
> > --
> > 1.8.3.1
> >

Re: [PATCH RFC] bonding: rate-limit bonding driver inspect messages

[Hangbin Liu]

On Sat, Feb 17, 2024 at 12:39:44PM +0000, Praveen Kannoju wrote:
> > -----Original Message-----
> > From: Hangbin Liu <liuhangbin@gmail.com>
> > Sent: 16 February 2024 02:33 PM
> > To: Praveen Kannoju <praveen.kannoju@oracle.com>
> > Cc: j.vosburgh@gmail.com; andy@greyhouse.net; davem@davemloft.net; edumazet@google.com; kuba@kernel.org;
> > pabeni@redhat.com; netdev@vger.kernel.org; linux-kernel@vger.kernel.org; Rajesh Sivaramasubramaniom
> > <rajesh.sivaramasubramaniom@oracle.com>; Rama Nichanamatlu <rama.nichanamatlu@oracle.com>; Manjunath Patil
> > <manjunath.b.patil@oracle.com>
> > Subject: Re: [PATCH RFC] bonding: rate-limit bonding driver inspect messages
> > 
> > On Thu, Feb 15, 2024 at 10:55:54PM +0530, Praveen Kumar Kannoju wrote:
> > > Rate limit bond driver log messages, to prevent a log flood in a
> > > run-away situation, e.g couldn't get rtnl lock. Message flood leads to
> > > instability of system and loss of other crucial messages.
> > 
> > Hi Praveen,
> > 
> > The patch looks good to me. But would you please help explain why these
> > slave_info() are chosen under net_ratelimit?
> > 
> > Thanks
> > Hangbin
> 
> Thank you, Hangbin.
> 
> The routine bond_mii_monitor() periodically inspects the slave carrier state in order to detect for state changes, on a state change internally records it and does the state change action.
> 
> Parked-to-Parked state changes goes through transient state. As an example for Up to Down, BOND_LINK_UP to BOND_LINK_DOWN, is thru BOND_LINK_FAIL.  In order to attain next parked state or transient state bond needs rtnl mutex. If in a situation it cannot get it, a state change wouldn't happen.  In order to achieve a state change as quickly as possible  bond_mii_monitor() reschedules itself to come around after 1 msec. 

I think a large miimon downdelay/updelay setting could reduce this.

> And every single come around reinspects the link and sees a state change compared to its internally recorded, which in reality internal state could be not changed earlier as failed to get rtnl lock, and throws again log indicating it sees a state change. If attaining rtnl mutex take long say hypothetical 5 secs, then bond logs 5000 state change message. 1 message at every 1 msec. 

Anyway, setting the rate limit do reduce the message flood. Would you please
summarise the paragraph and add it in commit description when post the formal
patch?

thanks
Hangbin

RE: [PATCH RFC] bonding: rate-limit bonding driver inspect messages

[Praveen Kannoju]

> -----Original Message-----
> From: Hangbin Liu <liuhangbin@gmail.com>
> Sent: 18 February 2024 08:39 AM
> To: Praveen Kannoju <praveen.kannoju@oracle.com>
> Cc: j.vosburgh@gmail.com; andy@greyhouse.net; davem@davemloft.net; edumazet@google.com; kuba@kernel.org;
> pabeni@redhat.com; netdev@vger.kernel.org; linux-kernel@vger.kernel.org; Rajesh Sivaramasubramaniom
> <rajesh.sivaramasubramaniom@oracle.com>; Rama Nichanamatlu <rama.nichanamatlu@oracle.com>; Manjunath Patil
> <manjunath.b.patil@oracle.com>
> Subject: Re: [PATCH RFC] bonding: rate-limit bonding driver inspect messages
> 
> On Sat, Feb 17, 2024 at 12:39:44PM +0000, Praveen Kannoju wrote:
> > > -----Original Message-----
> > > From: Hangbin Liu <liuhangbin@gmail.com>
> > > Sent: 16 February 2024 02:33 PM
> > > To: Praveen Kannoju <praveen.kannoju@oracle.com>
> > > Cc: j.vosburgh@gmail.com; andy@greyhouse.net; davem@davemloft.net;
> > > edumazet@google.com; kuba@kernel.org; pabeni@redhat.com;
> > > netdev@vger.kernel.org; linux-kernel@vger.kernel.org; Rajesh
> > > Sivaramasubramaniom <rajesh.sivaramasubramaniom@oracle.com>; Rama
> > > Nichanamatlu <rama.nichanamatlu@oracle.com>; Manjunath Patil
> > > <manjunath.b.patil@oracle.com>
> > > Subject: Re: [PATCH RFC] bonding: rate-limit bonding driver inspect
> > > messages
> > >
> > > On Thu, Feb 15, 2024 at 10:55:54PM +0530, Praveen Kumar Kannoju wrote:
> > > > Rate limit bond driver log messages, to prevent a log flood in a
> > > > run-away situation, e.g couldn't get rtnl lock. Message flood
> > > > leads to instability of system and loss of other crucial messages.
> > >
> > > Hi Praveen,
> > >
> > > The patch looks good to me. But would you please help explain why
> > > these
> > > slave_info() are chosen under net_ratelimit?
> > >
> > > Thanks
> > > Hangbin
> >
> > Thank you, Hangbin.
> >
> > The routine bond_mii_monitor() periodically inspects the slave carrier state in order to detect for state changes, on a state change
> internally records it and does the state change action.
> >
> > Parked-to-Parked state changes goes through transient state. As an example for Up to Down, BOND_LINK_UP to
> BOND_LINK_DOWN, is thru BOND_LINK_FAIL.  In order to attain next parked state or transient state bond needs rtnl mutex. If in a
> situation it cannot get it, a state change wouldn't happen.  In order to achieve a state change as quickly as possible
> bond_mii_monitor() reschedules itself to come around after 1 msec.
> 
> I think a large miimon downdelay/updelay setting could reduce this.
> 
> > And every single come around reinspects the link and sees a state change compared to its internally recorded, which in reality
> internal state could be not changed earlier as failed to get rtnl lock, and throws again log indicating it sees a state change. If attaining
> rtnl mutex take long say hypothetical 5 secs, then bond logs 5000 state change message. 1 message at every 1 msec.
> 
> Anyway, setting the rate limit do reduce the message flood. Would you please summarise the paragraph and add it in commit
> description when post the formal patch?
> 
> thanks
> Hangbin

Thank you very much, Hangbin.

I've added the summary on why we intend to rate-limit the messages in the commit, and re-sent the formal patch.

-
Praveen.

[PATCH RFC] bonding: rate-limit bonding driver inspect messages

[Praveen Kumar Kannoju]

Through the routine bond_mii_monitor(), bonding driver inspects and commits the
slave state changes. During the times when slave state change and failure in
aqcuiring rtnl lock happen at the same time, the routine bond_mii_monitor()
reschedules itself to come around after 1 msec to commit the new state.

During this, it executes the routine bond_miimon_inspect() to re-inspect the
state chane and prints the corresponding slave state on to the console. Hence
we do see a message at every 1 msec till the rtnl lock is acquired and state
chage is committed.

This patch doesn't change how bond functions. It only simply limits this kind
of log flood.

v2: Use exising net_ratelimit() instead of introducing new rate-limit
parameter.

v3: Commit message is modified to provide summary of the issue, because of
which rate-limiting the bonding driver messages is needed.

Signed-off-by: Praveen Kumar Kannoju <praveen.kannoju@oracle.com>
---
 drivers/net/bonding/bond_main.c | 36 ++++++++++++++++++++----------------
 1 file changed, 20 insertions(+), 16 deletions(-)

diff --git a/drivers/net/bonding/bond_main.c b/drivers/net/bonding/bond_main.c
index 4e0600c..e92eba1 100644
--- a/drivers/net/bonding/bond_main.c
+++ b/drivers/net/bonding/bond_main.c
@@ -2610,12 +2610,13 @@ static int bond_miimon_inspect(struct bonding *bond)
 			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);
+				if (net_ratelimit())
+					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:
@@ -2623,9 +2624,10 @@ static int bond_miimon_inspect(struct bonding *bond)
 				/* 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);
+				if (net_ratelimit())
+					slave_info(bond->dev, slave->dev, "link status up again after %d ms\n",
+						   (bond->params.downdelay - slave->delay) *
+						   bond->params.miimon);
 				commit++;
 				continue;
 			}
@@ -2648,18 +2650,20 @@ static int bond_miimon_inspect(struct bonding *bond)
 			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);
+				if (net_ratelimit())
+					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);
+				if (net_ratelimit())
+					slave_info(bond->dev, slave->dev, "link status down again after %d ms\n",
+						   (bond->params.updelay - slave->delay) *
+						   bond->params.miimon);
 				commit++;
 				continue;
 			}
-- 
1.8.3.1

RE: [PATCH RFC] bonding: rate-limit bonding driver inspect messages

[Praveen Kannoju]

Hi,
I've forgot to remove RFC in the subject line. Will remove it and re-send another copy.

-
Praveen.
> -----Original Message-----
> From: Praveen Kumar Kannoju <praveen.kannoju@oracle.com>
> Sent: 19 February 2024 05:02 PM
> To: j.vosburgh@gmail.com; andy@greyhouse.net; davem@davemloft.net; edumazet@google.com; kuba@kernel.org;
> pabeni@redhat.com; netdev@vger.kernel.org; linux-kernel@vger.kernel.org
> Cc: Rajesh Sivaramasubramaniom <rajesh.sivaramasubramaniom@oracle.com>; Rama Nichanamatlu
> <rama.nichanamatlu@oracle.com>; Manjunath Patil <manjunath.b.patil@oracle.com>; Praveen Kannoju
> <praveen.kannoju@oracle.com>
> Subject: [PATCH RFC] bonding: rate-limit bonding driver inspect messages
> 
> Through the routine bond_mii_monitor(), bonding driver inspects and commits the slave state changes. During the times when slave
> state change and failure in aqcuiring rtnl lock happen at the same time, the routine bond_mii_monitor() reschedules itself to come
> around after 1 msec to commit the new state.
> 
> During this, it executes the routine bond_miimon_inspect() to re-inspect the state chane and prints the corresponding slave state on
> to the console. Hence we do see a message at every 1 msec till the rtnl lock is acquired and state chage is committed.
> 
> This patch doesn't change how bond functions. It only simply limits this kind of log flood.
> 
> v2: Use exising net_ratelimit() instead of introducing new rate-limit parameter.
> 
> v3: Commit message is modified to provide summary of the issue, because of which rate-limiting the bonding driver messages is
> needed.
> 
> Signed-off-by: Praveen Kumar Kannoju <praveen.kannoju@oracle.com>
> ---
>  drivers/net/bonding/bond_main.c | 36 ++++++++++++++++++++----------------
>  1 file changed, 20 insertions(+), 16 deletions(-)
> 
> diff --git a/drivers/net/bonding/bond_main.c b/drivers/net/bonding/bond_main.c index 4e0600c..e92eba1 100644
> --- a/drivers/net/bonding/bond_main.c
> +++ b/drivers/net/bonding/bond_main.c
> @@ -2610,12 +2610,13 @@ static int bond_miimon_inspect(struct bonding *bond)
>  			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);
> +				if (net_ratelimit())
> +					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:
> @@ -2623,9 +2624,10 @@ static int bond_miimon_inspect(struct bonding *bond)
>  				/* 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);
> +				if (net_ratelimit())
> +					slave_info(bond->dev, slave->dev, "link status up again after %d ms\n",
> +						   (bond->params.downdelay - slave->delay) *
> +						   bond->params.miimon);
>  				commit++;
>  				continue;
>  			}
> @@ -2648,18 +2650,20 @@ static int bond_miimon_inspect(struct bonding *bond)
>  			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);
> +				if (net_ratelimit())
> +					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);
> +				if (net_ratelimit())
> +					slave_info(bond->dev, slave->dev, "link status down again after %d ms\n",
> +						   (bond->params.updelay - slave->delay) *
> +						   bond->params.miimon);
>  				commit++;
>  				continue;
>  			}
> --
> 1.8.3.1