tick/rcu: fix false positive "softirq work is pending" messages on RT

PATCH Applied [email protected] 8 participants 8 messages Aug 18, 2023 – Sep 1, 2023 Nohz, dynticks support

lore

Share & tools

lore

[email protected]

author

2023-08-18 20:09 UTC #0 lore raw

PATCH 1/1 tick/rcu: fix false positive "softirq work is pending" messages on RT

From: Paul Gortmaker <[email protected]>

In commit 0345691b24c0 ("tick/rcu: Stop allowing RCU_SOFTIRQ in idle") the new function report_idle_softirq() was created by breaking code out of the existing can_stop_idle_tick() for kernels v5.18 and newer.

In doing so, the code essentially went from a one conditional:

	if (a && b && c)
		warn();

to a three conditional:

	if (!a)
		return;
	if (!b)
		return;
	if (!c)
		return;
	warn();

However, it seems one of the conditionals didn't get a "!" removed. Compare the instance of local_bh_blocked() in the old code:

- if (ratelimit < 10 && !local_bh_blocked() &&
- (local_softirq_pending() & SOFTIRQ_STOP_IDLE_MASK)) {
- pr_warn("NOHZ tick-stop error: Non-RCU local softirq work is pending, handler #%02x!!!\n",
- (unsigned int) local_softirq_pending());
- ratelimit++;
- }

...to the usage in the new (5.18+) code:

+ /* On RT, softirqs handling may be waiting on some lock */
+ if (!local_bh_blocked())
+ return false;

It seems apparent that the "!" should be removed from the new code.

This issue lay dormant until another fixup for the same commit was added in commit a7e282c77785 ("tick/rcu: Fix bogus ratelimit condition"). This commit realized the ratelimit was essentially set to zero instead of ten, and hence *no* softirq pending messages would ever be issued.

Once this commit was backported via linux-stable, both the v6.1 and v6.4 preempt-rt kernels started printing out 10 instances of this at boot:

NOHZ tick-stop error: local softirq work is pending, handler #80!!!

Just to double check my understanding of things, I confirmed that the v5.18-rt did print the pending-80 messages with a cherry pick of the ratelimit fix, and then confirmed no pending softirq messages were printed with a revert of mainline's 034569 on a v5.18-rt baseline.

Finally I confirmed it fixed the issue on v6.1-rt and v6.4-rt, and also didn't break anything on a defconfig of mainline master of today.

Fixes 0345691b24c0 ("tick/rcu: Stop allowing RCU_SOFTIRQ in idle")

Cc Wen Yang <[email protected]>

Cc Thomas Gleixner <[email protected]>

Cc Peter Zijlstra <[email protected]>

Cc Paul E. McKenney <[email protected]>

Cc Frederic Weisbecker <[email protected]>

Signed-off-by Paul Gortmaker <[email protected]>

kernel/time/tick-sched.c +1 -1

index 2b865cb77feb..b52e1861b913 100644
@@ -1050,7 +1050,7 @@ static bool report_idle_softirq(void)
 		return false;
 
 	/* On RT, softirqs handling may be waiting on some lock */
-	if (!local_bh_blocked())
+	if (local_bh_blocked())
 		return false;
 
 	pr_warn("NOHZ tick-stop error: local softirq work is pending, handler #%02x!!!\n",

Signature · 1 line

2.40.0

Wen Yang

Reviewed-by on v1 1/1

2023-08-20 17:36 UTC #1 lore raw

Quoted 70 lines · On 2023/8/19 04:07, [email protected] wrote:

From: Paul Gortmaker <[email protected]>
In commit 0345691b24c0 ("tick/rcu: Stop allowing RCU_SOFTIRQ in idle") the new function report_idle_softirq() was created by breaking code out of the existing can_stop_idle_tick() for kernels v5.18 and newer.
In doing so, the code essentially went from a one conditional:
	if (a && b && c)
		warn();
to a three conditional:
	if (!a)
		return;
	if (!b)
		return;
	if (!c)
		return;
	warn();
However, it seems one of the conditionals didn't get a "!" removed. Compare the instance of local_bh_blocked() in the old code:
(quoted diff) +0 -6
-               if (ratelimit < 10 && !local_bh_blocked() &&
-                   (local_softirq_pending() & SOFTIRQ_STOP_IDLE_MASK)) {
-                       pr_warn("NOHZ tick-stop error: Non-RCU local softirq work is pending, handler #%02x!!!\n",
-                               (unsigned int) local_softirq_pending());
-                       ratelimit++;
-               }
...to the usage in the new (5.18+) code:
(quoted diff) +3 -0
+       /* On RT, softirqs handling may be waiting on some lock */
+       if (!local_bh_blocked())
+               return false;
It seems apparent that the "!" should be removed from the new code.
This issue lay dormant until another fixup for the same commit was added in commit a7e282c77785 ("tick/rcu: Fix bogus ratelimit condition"). This commit realized the ratelimit was essentially set to zero instead of ten, and hence *no* softirq pending messages would ever be issued.
Once this commit was backported via linux-stable, both the v6.1 and v6.4 preempt-rt kernels started printing out 10 instances of this at boot:
NOHZ tick-stop error: local softirq work is pending, handler #80!!!
Just to double check my understanding of things, I confirmed that the v5.18-rt did print the pending-80 messages with a cherry pick of the ratelimit fix, and then confirmed no pending softirq messages were printed with a revert of mainline's 034569 on a v5.18-rt baseline.
Finally I confirmed it fixed the issue on v6.1-rt and v6.4-rt, and also didn't break anything on a defconfig of mainline master of today.
Fixes 0345691b24c0 ("tick/rcu: Stop allowing RCU_SOFTIRQ in idle")
Cc Wen Yang <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Paul E. McKenney <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Signed-off-by Paul Gortmaker <[email protected]>
kernel/time/tick-sched.c +0 -0
index 2b865cb77feb..b52e1861b913 100644

kernel/time/tick-sched.c static bool report_idle_softirq(void) · line 1056

Quoted 8 lines

kernel/time/tick-sched.c +1 -1

@@ -1050,7 +1050,7 @@ static bool report_idle_softirq(void)
  		return false;
 
  	/* On RT, softirqs handling may be waiting on some lock */
-	if (!local_bh_blocked())
+	if (local_bh_blocked())
  		return false;
 
  	pr_warn("NOHZ tick-stop error: local softirq work is pending, handler #%02x!!!\n",

Good catch!

Reviewed-by Wen Yang <[email protected]>

--
Thanks,
Wen

Paul E. McKenney

2023-08-21 22:03 UTC #2 lore raw

Quoted 81 lines · Wen Yang

Quoted 70 lines · On 2023/8/19 04:07, [email protected] wrote:
From: Paul Gortmaker <[email protected]>
In commit 0345691b24c0 ("tick/rcu: Stop allowing RCU_SOFTIRQ in idle") the new function report_idle_softirq() was created by breaking code out of the existing can_stop_idle_tick() for kernels v5.18 and newer.
In doing so, the code essentially went from a one conditional:
	if (a && b && c)
		warn();
to a three conditional:
	if (!a)
		return;
	if (!b)
		return;
	if (!c)
		return;
	warn();
However, it seems one of the conditionals didn't get a "!" removed. Compare the instance of local_bh_blocked() in the old code:
(quoted diff) +0 -6
-               if (ratelimit < 10 && !local_bh_blocked() &&
-                   (local_softirq_pending() & SOFTIRQ_STOP_IDLE_MASK)) {
-                       pr_warn("NOHZ tick-stop error: Non-RCU local softirq work is pending, handler #%02x!!!\n",
-                               (unsigned int) local_softirq_pending());
-                       ratelimit++;
-               }
...to the usage in the new (5.18+) code:
(quoted diff) +3 -0
+       /* On RT, softirqs handling may be waiting on some lock */
+       if (!local_bh_blocked())
+               return false;
It seems apparent that the "!" should be removed from the new code.
This issue lay dormant until another fixup for the same commit was added in commit a7e282c77785 ("tick/rcu: Fix bogus ratelimit condition"). This commit realized the ratelimit was essentially set to zero instead of ten, and hence *no* softirq pending messages would ever be issued.
Once this commit was backported via linux-stable, both the v6.1 and v6.4 preempt-rt kernels started printing out 10 instances of this at boot:
NOHZ tick-stop error: local softirq work is pending, handler #80!!!
Just to double check my understanding of things, I confirmed that the v5.18-rt did print the pending-80 messages with a cherry pick of the ratelimit fix, and then confirmed no pending softirq messages were printed with a revert of mainline's 034569 on a v5.18-rt baseline.
Finally I confirmed it fixed the issue on v6.1-rt and v6.4-rt, and also didn't break anything on a defconfig of mainline master of today.
Fixes 0345691b24c0 ("tick/rcu: Stop allowing RCU_SOFTIRQ in idle")
Cc Wen Yang <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Paul E. McKenney <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Signed-off-by Paul Gortmaker <[email protected]>
kernel/time/tick-sched.c +0 -0
index 2b865cb77feb..b52e1861b913 100644
kernel/time/tick-sched.c static bool report_idle_softirq(void) · line 1054
Quoted 6 lines
kernel/time/tick-sched.c +1 -1
@@ -1050,7 +1050,7 @@ static bool report_idle_softirq(void)
  		return false;
  	/* On RT, softirqs handling may be waiting on some lock */
-	if (!local_bh_blocked())
+	if (local_bh_blocked())
  		return false;
  	pr_warn("NOHZ tick-stop error: local softirq work is pending, handler #%02x!!!\n",
Good catch!

Quoted 1 line

Reviewed-by Wen Yang <[email protected]>

Frederic would normally take this, but he appears to be out. So I am (probably only temporarily) queueing this in -rcu for more testing coverage.

Thanx, Paul

Frederic Weisbecker

maintainer

2023-08-28 15:04 UTC #3 lore raw

Quoted 82 lines · Paul E. McKenney

Quoted 81 lines · Wen Yang
Quoted 70 lines · On 2023/8/19 04:07, [email protected] wrote:
From: Paul Gortmaker <[email protected]>
In commit 0345691b24c0 ("tick/rcu: Stop allowing RCU_SOFTIRQ in idle") the new function report_idle_softirq() was created by breaking code out of the existing can_stop_idle_tick() for kernels v5.18 and newer.
In doing so, the code essentially went from a one conditional:
	if (a && b && c)
		warn();
to a three conditional:
	if (!a)
		return;
	if (!b)
		return;
	if (!c)
		return;
	warn();
However, it seems one of the conditionals didn't get a "!" removed. Compare the instance of local_bh_blocked() in the old code:
(quoted diff) +0 -6
-               if (ratelimit < 10 && !local_bh_blocked() &&
-                   (local_softirq_pending() & SOFTIRQ_STOP_IDLE_MASK)) {
-                       pr_warn("NOHZ tick-stop error: Non-RCU local softirq work is pending, handler #%02x!!!\n",
-                               (unsigned int) local_softirq_pending());
-                       ratelimit++;
-               }
...to the usage in the new (5.18+) code:
(quoted diff) +3 -0
+       /* On RT, softirqs handling may be waiting on some lock */
+       if (!local_bh_blocked())
+               return false;
It seems apparent that the "!" should be removed from the new code.
This issue lay dormant until another fixup for the same commit was added in commit a7e282c77785 ("tick/rcu: Fix bogus ratelimit condition"). This commit realized the ratelimit was essentially set to zero instead of ten, and hence *no* softirq pending messages would ever be issued.
Once this commit was backported via linux-stable, both the v6.1 and v6.4 preempt-rt kernels started printing out 10 instances of this at boot:
NOHZ tick-stop error: local softirq work is pending, handler #80!!!
Just to double check my understanding of things, I confirmed that the v5.18-rt did print the pending-80 messages with a cherry pick of the ratelimit fix, and then confirmed no pending softirq messages were printed with a revert of mainline's 034569 on a v5.18-rt baseline.
Finally I confirmed it fixed the issue on v6.1-rt and v6.4-rt, and also didn't break anything on a defconfig of mainline master of today.
Fixes 0345691b24c0 ("tick/rcu: Stop allowing RCU_SOFTIRQ in idle")
Cc Wen Yang <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Paul E. McKenney <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Signed-off-by Paul Gortmaker <[email protected]>
kernel/time/tick-sched.c +0 -0
index 2b865cb77feb..b52e1861b913 100644
kernel/time/tick-sched.c static bool report_idle_softirq(void) · line 1054
Quoted 6 lines
kernel/time/tick-sched.c +1 -1
@@ -1050,7 +1050,7 @@ static bool report_idle_softirq(void)
  		return false;
  	/* On RT, softirqs handling may be waiting on some lock */
-	if (!local_bh_blocked())
+	if (local_bh_blocked())
  		return false;
  	pr_warn("NOHZ tick-stop error: local softirq work is pending, handler #%02x!!!\n",
Good catch!

Quoted 5 lines

Quoted 1 line
Reviewed-by Wen Yang <[email protected]>
Frederic would normally take this, but he appears to be out. So I am (probably only temporarily) queueing this in -rcu for more testing coverage.

I'm back, I should relay this to Thomas to avoid conflicts with timers changes.

Thanks all of you, clearly I wasn't thinking much the day I wrote this patch.

Sebastian Andrzej Siewior

2023-08-31 13:32 UTC #4 lore raw

Quoted 6 lines · Frederic Weisbecker

Quoted 3 lines
Frederic would normally take this, but he appears to be out. So I am (probably only temporarily) queueing this in -rcu for more testing coverage.
I'm back, I should relay this to Thomas to avoid conflicts with timers changes.

I somehow missed this thread and I do see this if I enable NO_HZ. I lost it…
Anyway, I'm going to pick it up for RT and ping the timer department after the merge window.

Quoted 2 lines

Thanks all of you, clearly I wasn't thinking much the day I wrote this patch.

Sebastian

Thomas Gleixner

2023-09-01 09:56 UTC #5 lore raw

Quoted 5 lines · Sebastian Andrzej Siewior

Quoted 4 lines · Frederic Weisbecker
Quoted 3 lines
Frederic would normally take this, but he appears to be out. So I am (probably only temporarily) queueing this in -rcu for more testing coverage.

Quoted 7 lines

Quoted 2 lines
I'm back, I should relay this to Thomas to avoid conflicts with timers changes.
I somehow missed this thread and I do see this if I enable NO_HZ. I lost it…
Anyway, I'm going to pick it up for RT and ping the timer department after the merge window.

It's queued in timers/urgent and will hit Linus tree before rc1

Ahmad Fatoum

Tested-by on v1 1/1

2023-08-24 16:01 UTC #6 lore raw

In reply to [email protected]

Quoted 57 lines · On 18.08.23 22:07, [email protected] wrote:

From: Paul Gortmaker <[email protected]>
In commit 0345691b24c0 ("tick/rcu: Stop allowing RCU_SOFTIRQ in idle") the new function report_idle_softirq() was created by breaking code out of the existing can_stop_idle_tick() for kernels v5.18 and newer.
In doing so, the code essentially went from a one conditional:
	if (a && b && c)
		warn();
to a three conditional:
	if (!a)
		return;
	if (!b)
		return;
	if (!c)
		return;
	warn();
However, it seems one of the conditionals didn't get a "!" removed. Compare the instance of local_bh_blocked() in the old code:
(quoted diff) +0 -6
-               if (ratelimit < 10 && !local_bh_blocked() &&
-                   (local_softirq_pending() & SOFTIRQ_STOP_IDLE_MASK)) {
-                       pr_warn("NOHZ tick-stop error: Non-RCU local softirq work is pending, handler #%02x!!!\n",
-                               (unsigned int) local_softirq_pending());
-                       ratelimit++;
-               }
...to the usage in the new (5.18+) code:
(quoted diff) +3 -0
+       /* On RT, softirqs handling may be waiting on some lock */
+       if (!local_bh_blocked())
+               return false;
It seems apparent that the "!" should be removed from the new code.
This issue lay dormant until another fixup for the same commit was added in commit a7e282c77785 ("tick/rcu: Fix bogus ratelimit condition"). This commit realized the ratelimit was essentially set to zero instead of ten, and hence *no* softirq pending messages would ever be issued.
Once this commit was backported via linux-stable, both the v6.1 and v6.4 preempt-rt kernels started printing out 10 instances of this at boot:
NOHZ tick-stop error: local softirq work is pending, handler #80!!!
Just to double check my understanding of things, I confirmed that the v5.18-rt did print the pending-80 messages with a cherry pick of the ratelimit fix, and then confirmed no pending softirq messages were printed with a revert of mainline's 034569 on a v5.18-rt baseline.
Finally I confirmed it fixed the issue on v6.1-rt and v6.4-rt, and also didn't break anything on a defconfig of mainline master of today.

Quoted 7 lines

Fixes 0345691b24c0 ("tick/rcu: Stop allowing RCU_SOFTIRQ in idle")
Cc Wen Yang <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Paul E. McKenney <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Signed-off-by Paul Gortmaker <[email protected]>

Tested-by Ahmad Fatoum <[email protected]>

Thanks,
Ahmad

Quoted 14 lines

kernel/time/tick-sched.c +1 -1

index 2b865cb77feb..b52e1861b913 100644
@@ -1050,7 +1050,7 @@ static bool report_idle_softirq(void)
 		return false;
 
 	/* On RT, softirqs handling may be waiting on some lock */
-	if (!local_bh_blocked())
+	if (local_bh_blocked())
 		return false;
 
 	pr_warn("NOHZ tick-stop error: local softirq work is pending, handler #%02x!!!\n",

Signature · 4 lines

Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

tip-bot2 for Paul Gortmaker

merge bot Applied

2023-08-30 19:14 UTC #7 lore raw

[tip: timers/urgent] tick/rcu: Fix false positive "softirq work is pending" messages

In reply to [email protected]

The following commit has been merged into the timers/urgent branch of tip:

Commit-ID:     96c1fa04f089a7e977a44e4e8fdc92e81be20bef
Gitweb:        https://git.kernel.org/tip/96c1fa04f089a7e977a44e4e8fdc92e81be20bef
Author:        Paul Gortmaker <[email protected]>
AuthorDate:    Fri, 18 Aug 2023 16:07:57 -04:00
Committer:     Thomas Gleixner <[email protected]>
CommitterDate: Wed, 30 Aug 2023 12:20:28 +02:00

tick/rcu: Fix false positive "softirq work is pending" messages

In doing so, the code essentially went from a one conditional:

	if (a && b && c)
		warn();

to a three conditional:

	if (!a)
		return;
	if (!b)
		return;
	if (!c)
		return;
	warn();

But that conversion got the condition for the RT specific local_bh_blocked() wrong. The original condition was:

!local_bh_blocked()

but the conversion failed to negate it so it ended up as:

        if (!local_bh_blocked())
		return false;

Once this commit was backported via linux-stable, both the v6.1 and v6.4 preempt-rt kernels started printing out 10 instances of this at boot:

NOHZ tick-stop error: local softirq work is pending, handler #80!!!

Remove the negation and return when local_bh_blocked() evaluates to true to bring the correct behaviour back.

Fixes 0345691b24c0 ("tick/rcu: Stop allowing RCU_SOFTIRQ in idle")

Signed-off-by Paul Gortmaker <[email protected]>

Signed-off-by Thomas Gleixner <[email protected]>

Tested-by Ahmad Fatoum <[email protected]>

Reviewed-by Wen Yang <[email protected]>

Acked-by Frederic Weisbecker <[email protected]>

Link https://lore.kernel.org/r/[email protected] open here

---
 kernel/time/tick-sched.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

kernel/time/tick-sched.c +1 -1

index 4df14db..87015e9 100644
@@ -1045,7 +1045,7 @@ static bool report_idle_softirq(void)
 		return false;
 
 	/* On RT, softirqs handling may be waiting on some lock */
-	if (!local_bh_blocked())
+	if (local_bh_blocked())
 		return false;
 
 	pr_warn("NOHZ tick-stop error: local softirq work is pending, handler #%02x!!!\n",