On Fri, 28 Jul 2017 09:55:29 -0700
"Paul E. McKenney" [off-list ref] wrote:
On Fri, Jul 28, 2017 at 02:24:03PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 08:44:11 +0100
Jonathan Cameron [off-list ref] wrote:
[ . . . ]
quoted
Ok. Some info. I disabled a few driver (usb and SAS) in the interest of having
fewer timer events. Issue became much easier to trigger (on some runs before
I could get tracing up and running)
e
So logs are large enough that pastebin doesn't like them - please shoet if
quoted
e another timer period is of interest.
https://pastebin.com/iUZDfQGM for the timer trace.
https://pastebin.com/3w1F7amH for dmesg.
The relevant timeout on the RCU stall detector was 8 seconds. Event is
detected around 835.
It's a lot of logs, so I haven't identified a smoking gun yet but there
may well be one in there.
The dmesg says:
rcu_preempt kthread starved for 2508 jiffies! g112 c111 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
So I look for "rcu_preempt" timer events and find these:
rcu_preempt-9 [019] .... 827.579114: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [019] d..1 827.579115: timer_start: timer=ffff8017d5fc7da0 function=process_timeout
Next look for "ffff8017d5fc7da0" and I don't find anything else.
It does show up off the bottom of what would fit in pastebin...
rcu_preempt-9 [001] d..1 837.681077: timer_cancel: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] .... 837.681086: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] d..1 837.681087: timer_start: timer=ffff8017d5fc7da0 function=process_timeout expires=4295101298 [timeout=1] cpu=1 idx=0 flags=
The timeout was one jiffy, and more than a second later, no expiration.
Is it possible that this event was lost? I am not seeing any sign of
this is the trace.
I don't see any sign of CPU hotplug (and I test with lots of that in
any case).
The last time we saw something like this it was a timer HW/driver problem,
but it is a bit hard to imagine such a problem affecting both ARM64
and SPARC. ;-)
From: Paul E. McKenney <hidden> Date: 2017-07-28 19:03:50
On Fri, Jul 28, 2017 at 06:27:05PM +0100, Jonathan Cameron wrote:
On Fri, 28 Jul 2017 09:55:29 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Fri, Jul 28, 2017 at 02:24:03PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 08:44:11 +0100
Jonathan Cameron [off-list ref] wrote:
[ . . . ]
quoted
Ok. Some info. I disabled a few driver (usb and SAS) in the interest of having
fewer timer events. Issue became much easier to trigger (on some runs before
I could get tracing up and running)
e
So logs are large enough that pastebin doesn't like them - please shoet if
quoted
e another timer period is of interest.
https://pastebin.com/iUZDfQGM for the timer trace.
https://pastebin.com/3w1F7amH for dmesg.
The relevant timeout on the RCU stall detector was 8 seconds. Event is
detected around 835.
It's a lot of logs, so I haven't identified a smoking gun yet but there
may well be one in there.
The dmesg says:
rcu_preempt kthread starved for 2508 jiffies! g112 c111 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
So I look for "rcu_preempt" timer events and find these:
rcu_preempt-9 [019] .... 827.579114: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [019] d..1 827.579115: timer_start: timer=ffff8017d5fc7da0 function=process_timeout
Next look for "ffff8017d5fc7da0" and I don't find anything else.
It does show up off the bottom of what would fit in pastebin...
rcu_preempt-9 [001] d..1 837.681077: timer_cancel: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] .... 837.681086: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] d..1 837.681087: timer_start: timer=ffff8017d5fc7da0 function=process_timeout expires=4295101298 [timeout=1] cpu=1 idx=0 flags=
Odd. I would expect an expiration... And ten seconds is way longer
than the requested one jiffy!
quoted
The timeout was one jiffy, and more than a second later, no expiration.
Is it possible that this event was lost? I am not seeing any sign of
this is the trace.
I don't see any sign of CPU hotplug (and I test with lots of that in
any case).
The last time we saw something like this it was a timer HW/driver problem,
but it is a bit hard to imagine such a problem affecting both ARM64
and SPARC. ;-)
On Fri, 28 Jul 2017 12:03:50 -0700
"Paul E. McKenney" [off-list ref] wrote:
On Fri, Jul 28, 2017 at 06:27:05PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 09:55:29 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Fri, Jul 28, 2017 at 02:24:03PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 08:44:11 +0100
Jonathan Cameron [off-list ref] wrote:
[ . . . ]
quoted
Ok. Some info. I disabled a few driver (usb and SAS) in the interest of having
fewer timer events. Issue became much easier to trigger (on some runs before
I could get tracing up and running)
e
So logs are large enough that pastebin doesn't like them - please shoet if
quoted
e another timer period is of interest.
https://pastebin.com/iUZDfQGM for the timer trace.
https://pastebin.com/3w1F7amH for dmesg.
The relevant timeout on the RCU stall detector was 8 seconds. Event is
detected around 835.
It's a lot of logs, so I haven't identified a smoking gun yet but there
may well be one in there.
The dmesg says:
rcu_preempt kthread starved for 2508 jiffies! g112 c111 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
So I look for "rcu_preempt" timer events and find these:
rcu_preempt-9 [019] .... 827.579114: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [019] d..1 827.579115: timer_start: timer=ffff8017d5fc7da0 function=process_timeout
Next look for "ffff8017d5fc7da0" and I don't find anything else.
It does show up off the bottom of what would fit in pastebin...
rcu_preempt-9 [001] d..1 837.681077: timer_cancel: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] .... 837.681086: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] d..1 837.681087: timer_start: timer=ffff8017d5fc7da0 function=process_timeout expires=4295101298 [timeout=1] cpu=1 idx=0 flags=
Odd. I would expect an expiration... And ten seconds is way longer
than the requested one jiffy!
quoted
quoted
The timeout was one jiffy, and more than a second later, no expiration.
Is it possible that this event was lost? I am not seeing any sign of
this is the trace.
I don't see any sign of CPU hotplug (and I test with lots of that in
any case).
The last time we saw something like this it was a timer HW/driver problem,
but it is a bit hard to imagine such a problem affecting both ARM64
and SPARC. ;-)
From: Paul E. McKenney <hidden> Date: 2017-07-31 15:04:11
On Mon, Jul 31, 2017 at 12:08:47PM +0100, Jonathan Cameron wrote:
On Fri, 28 Jul 2017 12:03:50 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Fri, Jul 28, 2017 at 06:27:05PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 09:55:29 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Fri, Jul 28, 2017 at 02:24:03PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 08:44:11 +0100
Jonathan Cameron [off-list ref] wrote:
[ . . . ]
quoted
Ok. Some info. I disabled a few driver (usb and SAS) in the interest of having
fewer timer events. Issue became much easier to trigger (on some runs before
I could get tracing up and running)
e
So logs are large enough that pastebin doesn't like them - please shoet if
quoted
e another timer period is of interest.
https://pastebin.com/iUZDfQGM for the timer trace.
https://pastebin.com/3w1F7amH for dmesg.
The relevant timeout on the RCU stall detector was 8 seconds. Event is
detected around 835.
It's a lot of logs, so I haven't identified a smoking gun yet but there
may well be one in there.
The dmesg says:
rcu_preempt kthread starved for 2508 jiffies! g112 c111 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
So I look for "rcu_preempt" timer events and find these:
rcu_preempt-9 [019] .... 827.579114: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [019] d..1 827.579115: timer_start: timer=ffff8017d5fc7da0 function=process_timeout
Next look for "ffff8017d5fc7da0" and I don't find anything else.
It does show up off the bottom of what would fit in pastebin...
rcu_preempt-9 [001] d..1 837.681077: timer_cancel: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] .... 837.681086: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] d..1 837.681087: timer_start: timer=ffff8017d5fc7da0 function=process_timeout expires=4295101298 [timeout=1] cpu=1 idx=0 flags=
Odd. I would expect an expiration... And ten seconds is way longer
than the requested one jiffy!
quoted
quoted
The timeout was one jiffy, and more than a second later, no expiration.
Is it possible that this event was lost? I am not seeing any sign of
this is the trace.
I don't see any sign of CPU hotplug (and I test with lots of that in
any case).
The last time we saw something like this it was a timer HW/driver problem,
but it is a bit hard to imagine such a problem affecting both ARM64
and SPARC. ;-)
On Mon, 31 Jul 2017 08:04:11 -0700
"Paul E. McKenney" [off-list ref] wrote:
On Mon, Jul 31, 2017 at 12:08:47PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 12:03:50 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Fri, Jul 28, 2017 at 06:27:05PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 09:55:29 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Fri, Jul 28, 2017 at 02:24:03PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 08:44:11 +0100
Jonathan Cameron [off-list ref] wrote:
[ . . . ]
quoted
Ok. Some info. I disabled a few driver (usb and SAS) in the interest of having
fewer timer events. Issue became much easier to trigger (on some runs before
I could get tracing up and running)
e
So logs are large enough that pastebin doesn't like them - please shoet if
quoted
e another timer period is of interest.
https://pastebin.com/iUZDfQGM for the timer trace.
https://pastebin.com/3w1F7amH for dmesg.
The relevant timeout on the RCU stall detector was 8 seconds. Event is
detected around 835.
It's a lot of logs, so I haven't identified a smoking gun yet but there
may well be one in there.
The dmesg says:
rcu_preempt kthread starved for 2508 jiffies! g112 c111 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
So I look for "rcu_preempt" timer events and find these:
rcu_preempt-9 [019] .... 827.579114: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [019] d..1 827.579115: timer_start: timer=ffff8017d5fc7da0 function=process_timeout
Next look for "ffff8017d5fc7da0" and I don't find anything else.
It does show up off the bottom of what would fit in pastebin...
rcu_preempt-9 [001] d..1 837.681077: timer_cancel: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] .... 837.681086: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] d..1 837.681087: timer_start: timer=ffff8017d5fc7da0 function=process_timeout expires=4295101298 [timeout=1] cpu=1 idx=0 flags=
Odd. I would expect an expiration... And ten seconds is way longer
than the requested one jiffy!
quoted
quoted
The timeout was one jiffy, and more than a second later, no expiration.
Is it possible that this event was lost? I am not seeing any sign of
this is the trace.
I don't see any sign of CPU hotplug (and I test with lots of that in
any case).
The last time we saw something like this it was a timer HW/driver problem,
but it is a bit hard to imagine such a problem affecting both ARM64
and SPARC. ;-)
If you can reproduce quickly, might be worth trying anyway...
Thanx, Paul
Errata fix is running already and was for all those tests.
I was afraid of that... ;-)
It's a pretty rare errata it seems. Not actually managed to catch
one yet.
quoted
I'll have a dig into the timers today and see where I get to.
Look forward to seeing what you find!
Nothing obvious turning up other than we don't seem to have issue
when we aren't running hrtimers.
On a plus side I just got a report that it is effecting our d03
boards which is good on the basis I couldn't tell what the difference
could be wrt to this issue!
It indeed looks like we are consistently missing a timer before
the rcu splat occurs.
J
From: Paul E. McKenney <hidden> Date: 2017-08-01 18:46:46
On Mon, Jul 31, 2017 at 04:27:57PM +0100, Jonathan Cameron wrote:
On Mon, 31 Jul 2017 08:04:11 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Mon, Jul 31, 2017 at 12:08:47PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 12:03:50 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Fri, Jul 28, 2017 at 06:27:05PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 09:55:29 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Fri, Jul 28, 2017 at 02:24:03PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 08:44:11 +0100
Jonathan Cameron [off-list ref] wrote:
[ . . . ]
quoted
Ok. Some info. I disabled a few driver (usb and SAS) in the interest of having
fewer timer events. Issue became much easier to trigger (on some runs before
I could get tracing up and running)
e
So logs are large enough that pastebin doesn't like them - please shoet if
quoted
e another timer period is of interest.
https://pastebin.com/iUZDfQGM for the timer trace.
https://pastebin.com/3w1F7amH for dmesg.
The relevant timeout on the RCU stall detector was 8 seconds. Event is
detected around 835.
It's a lot of logs, so I haven't identified a smoking gun yet but there
may well be one in there.
The dmesg says:
rcu_preempt kthread starved for 2508 jiffies! g112 c111 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
So I look for "rcu_preempt" timer events and find these:
rcu_preempt-9 [019] .... 827.579114: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [019] d..1 827.579115: timer_start: timer=ffff8017d5fc7da0 function=process_timeout
Next look for "ffff8017d5fc7da0" and I don't find anything else.
It does show up off the bottom of what would fit in pastebin...
rcu_preempt-9 [001] d..1 837.681077: timer_cancel: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] .... 837.681086: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] d..1 837.681087: timer_start: timer=ffff8017d5fc7da0 function=process_timeout expires=4295101298 [timeout=1] cpu=1 idx=0 flags=
Odd. I would expect an expiration... And ten seconds is way longer
than the requested one jiffy!
quoted
quoted
The timeout was one jiffy, and more than a second later, no expiration.
Is it possible that this event was lost? I am not seeing any sign of
this is the trace.
I don't see any sign of CPU hotplug (and I test with lots of that in
any case).
The last time we saw something like this it was a timer HW/driver problem,
but it is a bit hard to imagine such a problem affecting both ARM64
and SPARC. ;-)
If you can reproduce quickly, might be worth trying anyway...
Thanx, Paul
Errata fix is running already and was for all those tests.
I was afraid of that... ;-)
It's a pretty rare errata it seems. Not actually managed to catch
one yet.
quoted
quoted
I'll have a dig into the timers today and see where I get to.
Look forward to seeing what you find!
Nothing obvious turning up other than we don't seem to have issue
when we aren't running hrtimers.
On a plus side I just got a report that it is effecting our d03
boards which is good on the basis I couldn't tell what the difference
could be wrt to this issue!
It indeed looks like we are consistently missing a timer before
the rcu splat occurs.
And for my part, my tests with CONFIG_HZ_PERIODIC=y and
CONFIG_RCU_FAST_NO_HZ=n showed roughly the same failure rate
as other runs.
Missing a timer can most certainly give RCU severe heartburn! ;-)
Do you have what you need to track down the missing timer?
Thanx, Paul
On Tue, 1 Aug 2017 11:46:46 -0700
"Paul E. McKenney" [off-list ref] wrote:
On Mon, Jul 31, 2017 at 04:27:57PM +0100, Jonathan Cameron wrote:
quoted
On Mon, 31 Jul 2017 08:04:11 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Mon, Jul 31, 2017 at 12:08:47PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 12:03:50 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Fri, Jul 28, 2017 at 06:27:05PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 09:55:29 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Fri, Jul 28, 2017 at 02:24:03PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 08:44:11 +0100
Jonathan Cameron [off-list ref] wrote:
[ . . . ]
quoted
Ok. Some info. I disabled a few driver (usb and SAS) in the interest of having
fewer timer events. Issue became much easier to trigger (on some runs before
I could get tracing up and running)
e
So logs are large enough that pastebin doesn't like them - please shoet if
quoted
e another timer period is of interest.
https://pastebin.com/iUZDfQGM for the timer trace.
https://pastebin.com/3w1F7amH for dmesg.
The relevant timeout on the RCU stall detector was 8 seconds. Event is
detected around 835.
It's a lot of logs, so I haven't identified a smoking gun yet but there
may well be one in there.
The dmesg says:
rcu_preempt kthread starved for 2508 jiffies! g112 c111 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
So I look for "rcu_preempt" timer events and find these:
rcu_preempt-9 [019] .... 827.579114: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [019] d..1 827.579115: timer_start: timer=ffff8017d5fc7da0 function=process_timeout
Next look for "ffff8017d5fc7da0" and I don't find anything else.
It does show up off the bottom of what would fit in pastebin...
rcu_preempt-9 [001] d..1 837.681077: timer_cancel: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] .... 837.681086: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] d..1 837.681087: timer_start: timer=ffff8017d5fc7da0 function=process_timeout expires=4295101298 [timeout=1] cpu=1 idx=0 flags=
Odd. I would expect an expiration... And ten seconds is way longer
than the requested one jiffy!
quoted
quoted
The timeout was one jiffy, and more than a second later, no expiration.
Is it possible that this event was lost? I am not seeing any sign of
this is the trace.
I don't see any sign of CPU hotplug (and I test with lots of that in
any case).
The last time we saw something like this it was a timer HW/driver problem,
but it is a bit hard to imagine such a problem affecting both ARM64
and SPARC. ;-)
If you can reproduce quickly, might be worth trying anyway...
Thanx, Paul
Errata fix is running already and was for all those tests.
I was afraid of that... ;-)
It's a pretty rare errata it seems. Not actually managed to catch
one yet.
quoted
quoted
I'll have a dig into the timers today and see where I get to.
Look forward to seeing what you find!
Nothing obvious turning up other than we don't seem to have issue
when we aren't running hrtimers.
On a plus side I just got a report that it is effecting our d03
boards which is good on the basis I couldn't tell what the difference
could be wrt to this issue!
It indeed looks like we are consistently missing a timer before
the rcu splat occurs.
And for my part, my tests with CONFIG_HZ_PERIODIC=y and
CONFIG_RCU_FAST_NO_HZ=n showed roughly the same failure rate
as other runs.
Missing a timer can most certainly give RCU severe heartburn! ;-)
Do you have what you need to track down the missing timer?
Not managed to make much progress yet. Turning on any additional tracing
in that area seems to make the issue stop happening or at least
occur very infrequently. Which certainly makes it 'fun' to find.
As a long shot I applied a locking fix from another reported issue that
was causing rcu stalls and it seemed good for much longer, but
eventually still occurred.
(from the thread rcu_sched stall while waiting in csd_lock_wait())
Jonathan
From: Paul E. McKenney <hidden> Date: 2017-08-15 15:47:43
On Wed, Aug 02, 2017 at 05:25:55PM +0100, Jonathan Cameron wrote:
On Tue, 1 Aug 2017 11:46:46 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Mon, Jul 31, 2017 at 04:27:57PM +0100, Jonathan Cameron wrote:
quoted
On Mon, 31 Jul 2017 08:04:11 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Mon, Jul 31, 2017 at 12:08:47PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 12:03:50 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Fri, Jul 28, 2017 at 06:27:05PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 09:55:29 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Fri, Jul 28, 2017 at 02:24:03PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 08:44:11 +0100
Jonathan Cameron [off-list ref] wrote:
[ . . . ]
quoted
Ok. Some info. I disabled a few driver (usb and SAS) in the interest of having
fewer timer events. Issue became much easier to trigger (on some runs before
I could get tracing up and running)
e
So logs are large enough that pastebin doesn't like them - please shoet if
quoted
e another timer period is of interest.
https://pastebin.com/iUZDfQGM for the timer trace.
https://pastebin.com/3w1F7amH for dmesg.
The relevant timeout on the RCU stall detector was 8 seconds. Event is
detected around 835.
It's a lot of logs, so I haven't identified a smoking gun yet but there
may well be one in there.
The dmesg says:
rcu_preempt kthread starved for 2508 jiffies! g112 c111 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
So I look for "rcu_preempt" timer events and find these:
rcu_preempt-9 [019] .... 827.579114: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [019] d..1 827.579115: timer_start: timer=ffff8017d5fc7da0 function=process_timeout
Next look for "ffff8017d5fc7da0" and I don't find anything else.
It does show up off the bottom of what would fit in pastebin...
rcu_preempt-9 [001] d..1 837.681077: timer_cancel: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] .... 837.681086: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] d..1 837.681087: timer_start: timer=ffff8017d5fc7da0 function=process_timeout expires=4295101298 [timeout=1] cpu=1 idx=0 flags=
Odd. I would expect an expiration... And ten seconds is way longer
than the requested one jiffy!
quoted
quoted
The timeout was one jiffy, and more than a second later, no expiration.
Is it possible that this event was lost? I am not seeing any sign of
this is the trace.
I don't see any sign of CPU hotplug (and I test with lots of that in
any case).
The last time we saw something like this it was a timer HW/driver problem,
but it is a bit hard to imagine such a problem affecting both ARM64
and SPARC. ;-)
If you can reproduce quickly, might be worth trying anyway...
Thanx, Paul
Errata fix is running already and was for all those tests.
I was afraid of that... ;-)
It's a pretty rare errata it seems. Not actually managed to catch
one yet.
quoted
quoted
I'll have a dig into the timers today and see where I get to.
Look forward to seeing what you find!
Nothing obvious turning up other than we don't seem to have issue
when we aren't running hrtimers.
On a plus side I just got a report that it is effecting our d03
boards which is good on the basis I couldn't tell what the difference
could be wrt to this issue!
It indeed looks like we are consistently missing a timer before
the rcu splat occurs.
And for my part, my tests with CONFIG_HZ_PERIODIC=y and
CONFIG_RCU_FAST_NO_HZ=n showed roughly the same failure rate
as other runs.
Missing a timer can most certainly give RCU severe heartburn! ;-)
Do you have what you need to track down the missing timer?
Not managed to make much progress yet. Turning on any additional tracing
in that area seems to make the issue stop happening or at least
occur very infrequently. Which certainly makes it 'fun' to find.
As a long shot I applied a locking fix from another reported issue that
was causing rcu stalls and it seemed good for much longer, but
eventually still occurred.
(from the thread rcu_sched stall while waiting in csd_lock_wait())
On the perhaps unlikely off-chance that it helps locate something,
here is a patch that adds a trace_printk() to check how long a CPU
believes that it can sleep when going idle. The thought is to check
to see if a CPU with a timer set to expire in one jiffy thinks that
can sleep for (say) 30 seconds.
Didn't find anything for my problem, but I believe that yours is
different, so...
Thanx, Paul
------------------------------------------------------------------------
commit 33103e7b1f89ef432dfe3337d2a6932cdf5c1312
Author: Paul E. McKenney [off-list ref]
Date: Mon Aug 14 08:54:39 2017 -0700
EXP: Trace tick return from tick_nohz_stop_sched_tick
Signed-off-by: Paul E. McKenney [off-list ref]
On Tue, 15 Aug 2017 08:47:43 -0700
"Paul E. McKenney" [off-list ref] wrote:
On Wed, Aug 02, 2017 at 05:25:55PM +0100, Jonathan Cameron wrote:
quoted
On Tue, 1 Aug 2017 11:46:46 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Mon, Jul 31, 2017 at 04:27:57PM +0100, Jonathan Cameron wrote:
quoted
On Mon, 31 Jul 2017 08:04:11 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Mon, Jul 31, 2017 at 12:08:47PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 12:03:50 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Fri, Jul 28, 2017 at 06:27:05PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 09:55:29 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Fri, Jul 28, 2017 at 02:24:03PM +0100, Jonathan Cameron wrote:
quoted
On Fri, 28 Jul 2017 08:44:11 +0100
Jonathan Cameron [off-list ref] wrote:
[ . . . ]
quoted
Ok. Some info. I disabled a few driver (usb and SAS) in the interest of having
fewer timer events. Issue became much easier to trigger (on some runs before
I could get tracing up and running)
e
So logs are large enough that pastebin doesn't like them - please shoet if
quoted
e another timer period is of interest.
https://pastebin.com/iUZDfQGM for the timer trace.
https://pastebin.com/3w1F7amH for dmesg.
The relevant timeout on the RCU stall detector was 8 seconds. Event is
detected around 835.
It's a lot of logs, so I haven't identified a smoking gun yet but there
may well be one in there.
The dmesg says:
rcu_preempt kthread starved for 2508 jiffies! g112 c111 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
So I look for "rcu_preempt" timer events and find these:
rcu_preempt-9 [019] .... 827.579114: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [019] d..1 827.579115: timer_start: timer=ffff8017d5fc7da0 function=process_timeout
Next look for "ffff8017d5fc7da0" and I don't find anything else.
It does show up off the bottom of what would fit in pastebin...
rcu_preempt-9 [001] d..1 837.681077: timer_cancel: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] .... 837.681086: timer_init: timer=ffff8017d5fc7da0
rcu_preempt-9 [001] d..1 837.681087: timer_start: timer=ffff8017d5fc7da0 function=process_timeout expires=4295101298 [timeout=1] cpu=1 idx=0 flags=
Odd. I would expect an expiration... And ten seconds is way longer
than the requested one jiffy!
quoted
quoted
The timeout was one jiffy, and more than a second later, no expiration.
Is it possible that this event was lost? I am not seeing any sign of
this is the trace.
I don't see any sign of CPU hotplug (and I test with lots of that in
any case).
The last time we saw something like this it was a timer HW/driver problem,
but it is a bit hard to imagine such a problem affecting both ARM64
and SPARC. ;-)
If you can reproduce quickly, might be worth trying anyway...
Thanx, Paul
Errata fix is running already and was for all those tests.
I was afraid of that... ;-)
It's a pretty rare errata it seems. Not actually managed to catch
one yet.
quoted
quoted
I'll have a dig into the timers today and see where I get to.
Look forward to seeing what you find!
Nothing obvious turning up other than we don't seem to have issue
when we aren't running hrtimers.
On a plus side I just got a report that it is effecting our d03
boards which is good on the basis I couldn't tell what the difference
could be wrt to this issue!
It indeed looks like we are consistently missing a timer before
the rcu splat occurs.
And for my part, my tests with CONFIG_HZ_PERIODIC=y and
CONFIG_RCU_FAST_NO_HZ=n showed roughly the same failure rate
as other runs.
Missing a timer can most certainly give RCU severe heartburn! ;-)
Do you have what you need to track down the missing timer?
Not managed to make much progress yet. Turning on any additional tracing
in that area seems to make the issue stop happening or at least
occur very infrequently. Which certainly makes it 'fun' to find.
As a long shot I applied a locking fix from another reported issue that
was causing rcu stalls and it seemed good for much longer, but
eventually still occurred.
(from the thread rcu_sched stall while waiting in csd_lock_wait())
On the perhaps unlikely off-chance that it helps locate something,
here is a patch that adds a trace_printk() to check how long a CPU
believes that it can sleep when going idle. The thought is to check
to see if a CPU with a timer set to expire in one jiffy thinks that
can sleep for (say) 30 seconds.
Didn't find anything for my problem, but I believe that yours is
different, so...
Thanx, Paul
Hi Paul,
Thanks for the suggestion. I hadn't thought to look at the
expected time being wrong.
I have noted that adding other tracepoints (and turning them on)
in that function cause the problem to 'disappear' though so it
would seem very timing sensitive. Fingers crossed this doesn't
have the same effect!
Our progress on this has been a bit limited partly as I have been
traveling and haven't sorted out remote hardware access.
May be the start of next week before I can try this out.
Agreed, the problems look to be different.
Interesting question is whether the other known cases fall
into one or the other category?
Thanks for the help and good luck with your variant!
Jonathan
quoted hunk
------------------------------------------------------------------------
commit 33103e7b1f89ef432dfe3337d2a6932cdf5c1312
Author: Paul E. McKenney [off-list ref]
Date: Mon Aug 14 08:54:39 2017 -0700
EXP: Trace tick return from tick_nohz_stop_sched_tick
Signed-off-by: Paul E. McKenney [off-list ref]
commit 33103e7b1f89ef432dfe3337d2a6932cdf5c1312
Author: Paul E. McKenney [off-list ref]
Date: Mon Aug 14 08:54:39 2017 -0700
EXP: Trace tick return from tick_nohz_stop_sched_tick
Signed-off-by: Paul E. McKenney [off-list ref]
From: Paul E. McKenney <hidden> Date: 2017-08-16 12:56:17
On Wed, Aug 16, 2017 at 10:43:52PM +1000, Michael Ellerman wrote:
"Paul E. McKenney" [off-list ref] writes:
...
quoted
commit 33103e7b1f89ef432dfe3337d2a6932cdf5c1312
Author: Paul E. McKenney [off-list ref]
Date: Mon Aug 14 08:54:39 2017 -0700
EXP: Trace tick return from tick_nohz_stop_sched_tick
Signed-off-by: Paul E. McKenney [off-list ref]
Should I be seeing negative values? A small sample:
Maybe due to hypervisor preemption delays, but I confess that I am
surprised to see them this large. 1,602,250,019 microseconds is something
like a half hour, which could result in stall warnings all by itself.
On Wed, 16 Aug 2017 05:56:17 -0700
"Paul E. McKenney" [off-list ref] wrote:
On Wed, Aug 16, 2017 at 10:43:52PM +1000, Michael Ellerman wrote:
quoted
"Paul E. McKenney" [off-list ref] writes:
...
quoted
commit 33103e7b1f89ef432dfe3337d2a6932cdf5c1312
Author: Paul E. McKenney [off-list ref]
Date: Mon Aug 14 08:54:39 2017 -0700
EXP: Trace tick return from tick_nohz_stop_sched_tick
Signed-off-by: Paul E. McKenney [off-list ref]
Should I be seeing negative values? A small sample:
Maybe due to hypervisor preemption delays, but I confess that I am
surprised to see them this large. 1,602,250,019 microseconds is something
like a half hour, which could result in stall warnings all by itself.
I found this, I can't see that it would cause our symptoms, but it's
worth someone who knows the code taking a look at it.
--
cpuidle: fix broadcast control when broadcast can not be entered
When failing to enter broadcast timer mode for an idle state that
requires it, a new state is selected that does not require broadcast,
but the broadcast variable remains set. This causes
tick_broadcast_exit to be called despite not having entered broadcast
mode.
This causes the WARN_ON_ONCE(!irqs_disabled()) to trigger in some
cases, but otherwise does not appear to cause problems.
Signed-off-by: Nicholas Piggin <npiggin@gmail.com>
---
drivers/cpuidle/cpuidle.c | 1 +
1 file changed, 1 insertion(+)
@@ -208,6 +208,7 @@ int cpuidle_enter_state(struct cpuidle_device *dev, struct cpuidle_driver *drv,return-EBUSY;}target_state=&drv->states[index];+broadcast=false;}/* Take note of the planned idle state. */
From: Paul E. McKenney <hidden> Date: 2017-08-16 16:27:31
On Wed, Aug 16, 2017 at 05:56:17AM -0700, Paul E. McKenney wrote:
On Wed, Aug 16, 2017 at 10:43:52PM +1000, Michael Ellerman wrote:
quoted
"Paul E. McKenney" [off-list ref] writes:
...
quoted
commit 33103e7b1f89ef432dfe3337d2a6932cdf5c1312
Author: Paul E. McKenney [off-list ref]
Date: Mon Aug 14 08:54:39 2017 -0700
EXP: Trace tick return from tick_nohz_stop_sched_tick
Signed-off-by: Paul E. McKenney [off-list ref]
Should I be seeing negative values? A small sample:
Maybe due to hypervisor preemption delays, but I confess that I am
surprised to see them this large. 1,602,250,019 microseconds is something
like a half hour, which could result in stall warnings all by itself.
And from your ps output, PID 9 is rcu_sched, which is the RCU grace-period
kthread that stalled. This kthread was starved, based on this from your
dmesg:
[ 1602.067008] rcu_sched kthread starved for 2603 jiffies! g7275 c7274 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
The RCU_GP_WAIT_FQS says that this kthread is periodically scanning for
idle-CPU and offline-CPU quiescent states, which means that its waits
will be accompanied by short timeouts. The "starved for 2603 jiffies"
says that it has not run for one good long time. The ->state is its
task_struct ->state field.
The immediately preceding dmesg line is as follows:
[ 1602.063851] (detected by 53, t=2603 jiffies, g=7275, c=7274, q=608)
In other words, the rcu_sched grace-period kthread has been starved
for the entire duration of the current grace period, as shown by the
t=2603.
Lets turn now to the trace output, looking for the last bit of the
rcu_sched task's activity:
rcu_sched-9 [054] d... 1576.030096: timer_start: timer=c0000007fae1bc20 function=process_timeout expires=4295094922 [timeout=1] cpu=54 idx=0 flags=
ksoftirqd/53-276 [053] ..s. 1576.030097: rcu_invoke_callback: rcu_sched rhp=c000000fcf8c4eb0 func=__d_free
rcu_sched-9 [054] d... 1576.030097: rcu_utilization: Start context switch
ksoftirqd/53-276 [053] ..s. 1576.030098: rcu_invoke_callback: rcu_sched rhp=c000000fcff74ee0 func=proc_i_callback
rcu_sched-9 [054] d... 1576.030098: rcu_grace_period: rcu_sched 7275 cpuqs
rcu_sched-9 [054] d... 1576.030099: rcu_utilization: End context switch
So this task set up a timer ("timer_start:") for one jiffy ("[timeout=1]",
but what is with "expires=4295094922"?) and blocked ("rcu_utilization:
Start context switch" and "rcu_utilization: End context switch"),
recording its CPU's quiescent state in the process ("rcu_grace_period:
rcu_sched 7275 cpuqs").
Of course, the timer will have expired in the context of some other task,
but a search for "c0000007fae1bc20" (see the "timer=" in the first trace
line above) shows nothing (to be painfully accurate, the search wraps back
to earlier uses of this timer by rcu_sched). So the timer never did fire.
The next question is "what did CPU 054 do next?" We find it entering idle:
<idle>-0 [054] d... 1576.030167: tick_stop: success=1 dependency=NONE
<idle>-0 [054] d... 1576.030167: hrtimer_cancel: hrtimer=c000000fff88c680
<idle>-0 [054] d... 1576.030168: hrtimer_start: hrtimer=c000000fff88c680 function=tick_sched_timer expires=1610710000000 softexpires=1610710000000
<idle>-0 [054] d... 1576.030170: __tick_nohz_idle_enter: tick_nohz_stop_sched_tick: 34469831
<idle>-0 [054] d... 1576.030171: rcu_dyntick: Start 140000000000000 0
So we have an hrtimer set for 1610710000000, whatever time that might
happen to map to. And that is the last we hear from CPU 054, so it
apparently maps to something a bit too far into the future. Let's
assume that this value is nanoseconds since boot, in which case we have
1,610.710000000 seconds, which is eight seconds after the stall-warning
message. And -way- longer than the one-jiffy timeout requested!
Thomas, John, am I misinterpreting the timer trace event messages?
Thanx, Paul
On Wed, Aug 16, 2017 at 05:56:17AM -0700, Paul E. McKenney wrote:
quoted
On Wed, Aug 16, 2017 at 10:43:52PM +1000, Michael Ellerman wrote:
quoted
"Paul E. McKenney" [off-list ref] writes:
...
quoted
commit 33103e7b1f89ef432dfe3337d2a6932cdf5c1312
Author: Paul E. McKenney [off-list ref]
Date: Mon Aug 14 08:54:39 2017 -0700
EXP: Trace tick return from tick_nohz_stop_sched_tick
Signed-off-by: Paul E. McKenney [off-list ref]
Should I be seeing negative values? A small sample:
Maybe due to hypervisor preemption delays, but I confess that I am
surprised to see them this large. 1,602,250,019 microseconds is something
like a half hour, which could result in stall warnings all by itself.
Hmm. This is a bare metal machine. So no hypervisor.
quoted
I will take a look!
And from your ps output, PID 9 is rcu_sched, which is the RCU grace-period
kthread that stalled. This kthread was starved, based on this from your
dmesg:
[ 1602.067008] rcu_sched kthread starved for 2603 jiffies! g7275 c7274 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
The RCU_GP_WAIT_FQS says that this kthread is periodically scanning for
idle-CPU and offline-CPU quiescent states, which means that its waits
will be accompanied by short timeouts. The "starved for 2603 jiffies"
says that it has not run for one good long time. The ->state is its
task_struct ->state field.
The immediately preceding dmesg line is as follows:
[ 1602.063851] (detected by 53, t=2603 jiffies, g=7275, c=7274, q=608)
In other words, the rcu_sched grace-period kthread has been starved
for the entire duration of the current grace period, as shown by the
t=2603.
Lets turn now to the trace output, looking for the last bit of the
rcu_sched task's activity:
rcu_sched-9 [054] d... 1576.030096: timer_start: timer=c0000007fae1bc20 function=process_timeout expires=4295094922 [timeout=1] cpu=54 idx=0 flags=
ksoftirqd/53-276 [053] ..s. 1576.030097: rcu_invoke_callback: rcu_sched rhp=c000000fcf8c4eb0 func=__d_free
rcu_sched-9 [054] d... 1576.030097: rcu_utilization: Start context switch
ksoftirqd/53-276 [053] ..s. 1576.030098: rcu_invoke_callback: rcu_sched rhp=c000000fcff74ee0 func=proc_i_callback
rcu_sched-9 [054] d... 1576.030098: rcu_grace_period: rcu_sched 7275 cpuqs
rcu_sched-9 [054] d... 1576.030099: rcu_utilization: End context switch
So this task set up a timer ("timer_start:") for one jiffy ("[timeout=1]",
but what is with "expires=4295094922"?)
That's a good one.
I have HZ=100, and therefore:
INITIAL_JIFFIES = (1 << 32) - (300 * 100) = 4294937296
So the expires value of 4295094922 is:
4295094922 - 4294937296 = 157626
Jiffies since boot.
Or 1576,260,000,000 ns == 1576.26 s.
Of course, the timer will have expired in the context of some other task,
but a search for "c0000007fae1bc20" (see the "timer=" in the first trace
line above) shows nothing (to be painfully accurate, the search wraps back
to earlier uses of this timer by rcu_sched). So the timer never did fire.
Or it just wasn't in the trace ?
I'll try and get it to trace a bit longer and see if that is helpful.
cheers
On Wed, 16 Aug 2017 09:27:31 -0700
"Paul E. McKenney" [off-list ref] wrote:
On Wed, Aug 16, 2017 at 05:56:17AM -0700, Paul E. McKenney wrote:
Thomas, John, am I misinterpreting the timer trace event messages?
So I did some digging, and what you find is that rcu_sched seems to do a
simple scheudle_timeout(1) and just goes out to lunch for many seconds.
The process_timeout timer never fires (when it finally does wake after
one of these events, it usually removes the timer with del_timer_sync).
So this patch seems to fix it. Testing, comments welcome.
Thanks,
Nick
[PATCH] timers: Fix excessive granularity of new timers after a nohz idle
When a timer base is idle, it is forwarded when a new timer is added to
ensure that granularity does not become excessive. When not idle, the
timer tick is expected to increment the base.
However there is a window after a timer is restarted from nohz, when it
is marked not-idle, and before the timer tick on this CPU, where a timer
may be added on an ancient base that does not get forwarded (beacause
the timer appears not-idle).
This results in excessive granularity. So much so that a 1 jiffy timeout
has blown out to 10s of seconds and triggered the RCU stall warning
detector.
Fix this by always forwarding the base when adding a new timer if it is
more than 1 jiffy behind. Another approach I looked at first was to note
if the base was idle but not yet run or forwarded, however this just
seemed to add more branches and complexity when it seems we can just
cover it with this test.
Also add a comment noting a case where we could get an unexpectedly
large granularity for a timer. I debugged this problem by adding
warnings for such cases, but it seems we can't add them in general due
to this corner case.
Signed-off-by: Nicholas Piggin <npiggin@gmail.com>
---
kernel/time/timer.c | 13 ++++++++++---
1 file changed, 10 insertions(+), 3 deletions(-)
From: Paul E. McKenney <hidden> Date: 2017-08-20 05:04:52
On Sun, Aug 20, 2017 at 02:45:53PM +1000, Nicholas Piggin wrote:
On Wed, 16 Aug 2017 09:27:31 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Wed, Aug 16, 2017 at 05:56:17AM -0700, Paul E. McKenney wrote:
Thomas, John, am I misinterpreting the timer trace event messages?
So I did some digging, and what you find is that rcu_sched seems to do a
simple scheudle_timeout(1) and just goes out to lunch for many seconds.
The process_timeout timer never fires (when it finally does wake after
one of these events, it usually removes the timer with del_timer_sync).
So this patch seems to fix it. Testing, comments welcome.
Fired up some tests, which should complete in about 12 hours.
Here is hoping! ;-)
Thanx, Paul
On Sun, 20 Aug 2017 14:45:53 +1000
Nicholas Piggin [off-list ref] wrote:
On Wed, 16 Aug 2017 09:27:31 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Wed, Aug 16, 2017 at 05:56:17AM -0700, Paul E. McKenney wrote:
Thomas, John, am I misinterpreting the timer trace event messages?
So I did some digging, and what you find is that rcu_sched seems to do a
simple scheudle_timeout(1) and just goes out to lunch for many seconds.
The process_timeout timer never fires (when it finally does wake after
one of these events, it usually removes the timer with del_timer_sync).
So this patch seems to fix it. Testing, comments welcome.
Okay this had a problem of trying to forward the timer from a timer
callback function.
This was my other approach which also fixes the RCU warnings, but it's
a little more complex. I reworked it a bit so the mod_timer fast path
hopefully doesn't have much more overhead (actually by reading jiffies
only when needed, it probably saves a load).
Thanks,
Nick
--
[PATCH] timers: Fix excessive granularity of new timers after a nohz idle
When a timer base is idle, it is forwarded when a new timer is added to
ensure that granularity does not become excessive. When not idle, the
timer tick is expected to increment the base.
However there is a window after a timer is restarted from nohz, when it
is marked not-idle, and before the timer tick on this CPU, where a timer
may be added on an ancient base that does not get forwarded (beacause
the timer appears not-idle).
This results in excessive granularity. So much so that a 1 jiffy timeout
has blown out to 10s of seconds and triggered the RCU stall warning
detector.
Fix this by keeping track of whether the timer has been idle since it was
last run or forwarded, and allow forwarding in the case that is true (even
if it is not currently idle).
Also add a comment noting a case where we could get an unexpectedly
large granularity for a timer. I debugged this problem by adding
warnings for such cases, but it seems we can't add them in general due
to this corner case.
Signed-off-by: Nicholas Piggin <npiggin@gmail.com>
---
kernel/time/timer.c | 32 +++++++++++++++++++++++++++-----
1 file changed, 27 insertions(+), 5 deletions(-)
From: Paul E. McKenney <hidden> Date: 2017-08-20 18:35:14
On Sun, Aug 20, 2017 at 11:00:40PM +1000, Nicholas Piggin wrote:
On Sun, 20 Aug 2017 14:45:53 +1000
Nicholas Piggin [off-list ref] wrote:
quoted
On Wed, 16 Aug 2017 09:27:31 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Wed, Aug 16, 2017 at 05:56:17AM -0700, Paul E. McKenney wrote:
Thomas, John, am I misinterpreting the timer trace event messages?
So I did some digging, and what you find is that rcu_sched seems to do a
simple scheudle_timeout(1) and just goes out to lunch for many seconds.
The process_timeout timer never fires (when it finally does wake after
one of these events, it usually removes the timer with del_timer_sync).
So this patch seems to fix it. Testing, comments welcome.
Okay this had a problem of trying to forward the timer from a timer
callback function.
This was my other approach which also fixes the RCU warnings, but it's
a little more complex. I reworked it a bit so the mod_timer fast path
hopefully doesn't have much more overhead (actually by reading jiffies
only when needed, it probably saves a load).
Giving this one a whirl!
Thanx, Paul
quoted hunk
Thanks,
Nick
--
[PATCH] timers: Fix excessive granularity of new timers after a nohz idle
When a timer base is idle, it is forwarded when a new timer is added to
ensure that granularity does not become excessive. When not idle, the
timer tick is expected to increment the base.
However there is a window after a timer is restarted from nohz, when it
is marked not-idle, and before the timer tick on this CPU, where a timer
may be added on an ancient base that does not get forwarded (beacause
the timer appears not-idle).
This results in excessive granularity. So much so that a 1 jiffy timeout
has blown out to 10s of seconds and triggered the RCU stall warning
detector.
Fix this by keeping track of whether the timer has been idle since it was
last run or forwarded, and allow forwarding in the case that is true (even
if it is not currently idle).
Also add a comment noting a case where we could get an unexpectedly
large granularity for a timer. I debugged this problem by adding
warnings for such cases, but it seems we can't add them in general due
to this corner case.
Signed-off-by: Nicholas Piggin <npiggin@gmail.com>
---
kernel/time/timer.c | 32 +++++++++++++++++++++++++++-----
1 file changed, 27 insertions(+), 5 deletions(-)
From: Paul E. McKenney <hidden> Date: 2017-08-20 21:14:29
On Sun, Aug 20, 2017 at 11:35:14AM -0700, Paul E. McKenney wrote:
On Sun, Aug 20, 2017 at 11:00:40PM +1000, Nicholas Piggin wrote:
quoted
On Sun, 20 Aug 2017 14:45:53 +1000
Nicholas Piggin [off-list ref] wrote:
quoted
On Wed, 16 Aug 2017 09:27:31 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Wed, Aug 16, 2017 at 05:56:17AM -0700, Paul E. McKenney wrote:
Thomas, John, am I misinterpreting the timer trace event messages?
So I did some digging, and what you find is that rcu_sched seems to do a
simple scheudle_timeout(1) and just goes out to lunch for many seconds.
The process_timeout timer never fires (when it finally does wake after
one of these events, it usually removes the timer with del_timer_sync).
So this patch seems to fix it. Testing, comments welcome.
Okay this had a problem of trying to forward the timer from a timer
callback function.
This was my other approach which also fixes the RCU warnings, but it's
a little more complex. I reworked it a bit so the mod_timer fast path
hopefully doesn't have much more overhead (actually by reading jiffies
only when needed, it probably saves a load).
Giving this one a whirl!
No joy here, but then again there are other reasons to believe that I
am seeing a different bug than Dave and Jonathan are.
OK, not -entirely- without joy -- 10 of 14 runs were error-free, which
is a good improvement over 0 of 84 for your earlier patch. ;-) But
not statistically different from what I see without either patch.
But no statistical difference compared to without patch, and I still
see the "rcu_sched kthread starved" messages. For whatever it is worth,
by the way, I also see this: "hrtimer: interrupt took 5712368 ns".
Hmmm... I am also seeing that without any of your patches. Might
be hypervisor preemption, I guess.
Thanx, Paul
PS. I will be off the grid for the next day or so. Eclipse day here...
On Sun, 20 Aug 2017 14:14:29 -0700
"Paul E. McKenney" [off-list ref] wrote:
On Sun, Aug 20, 2017 at 11:35:14AM -0700, Paul E. McKenney wrote:
quoted
On Sun, Aug 20, 2017 at 11:00:40PM +1000, Nicholas Piggin wrote:
quoted
On Sun, 20 Aug 2017 14:45:53 +1000
Nicholas Piggin [off-list ref] wrote:
quoted
On Wed, 16 Aug 2017 09:27:31 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Wed, Aug 16, 2017 at 05:56:17AM -0700, Paul E. McKenney wrote:
Thomas, John, am I misinterpreting the timer trace event messages?
So I did some digging, and what you find is that rcu_sched seems to do a
simple scheudle_timeout(1) and just goes out to lunch for many seconds.
The process_timeout timer never fires (when it finally does wake after
one of these events, it usually removes the timer with del_timer_sync).
So this patch seems to fix it. Testing, comments welcome.
Okay this had a problem of trying to forward the timer from a timer
callback function.
This was my other approach which also fixes the RCU warnings, but it's
a little more complex. I reworked it a bit so the mod_timer fast path
hopefully doesn't have much more overhead (actually by reading jiffies
only when needed, it probably saves a load).
Giving this one a whirl!
No joy here, but then again there are other reasons to believe that I
am seeing a different bug than Dave and Jonathan are.
OK, not -entirely- without joy -- 10 of 14 runs were error-free, which
is a good improvement over 0 of 84 for your earlier patch. ;-) But
not statistically different from what I see without either patch.
But no statistical difference compared to without patch, and I still
see the "rcu_sched kthread starved" messages. For whatever it is worth,
by the way, I also see this: "hrtimer: interrupt took 5712368 ns".
Hmmm... I am also seeing that without any of your patches. Might
be hypervisor preemption, I guess.
Okay it makes the warnings go away for me, but I'm just booting then
leaving the system idle. You're doing some CPU hotplug activity?
Thanks,
Nick
On Mon, 21 Aug 2017 10:52:58 +1000
Nicholas Piggin [off-list ref] wrote:
On Sun, 20 Aug 2017 14:14:29 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Sun, Aug 20, 2017 at 11:35:14AM -0700, Paul E. McKenney wrote:
quoted
On Sun, Aug 20, 2017 at 11:00:40PM +1000, Nicholas Piggin wrote:
quoted
On Sun, 20 Aug 2017 14:45:53 +1000
Nicholas Piggin [off-list ref] wrote:
quoted
On Wed, 16 Aug 2017 09:27:31 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Wed, Aug 16, 2017 at 05:56:17AM -0700, Paul E. McKenney wrote:
Thomas, John, am I misinterpreting the timer trace event messages?
So I did some digging, and what you find is that rcu_sched seems to do a
simple scheudle_timeout(1) and just goes out to lunch for many seconds.
The process_timeout timer never fires (when it finally does wake after
one of these events, it usually removes the timer with del_timer_sync).
So this patch seems to fix it. Testing, comments welcome.
Okay this had a problem of trying to forward the timer from a timer
callback function.
This was my other approach which also fixes the RCU warnings, but it's
a little more complex. I reworked it a bit so the mod_timer fast path
hopefully doesn't have much more overhead (actually by reading jiffies
only when needed, it probably saves a load).
Giving this one a whirl!
No joy here, but then again there are other reasons to believe that I
am seeing a different bug than Dave and Jonathan are.
OK, not -entirely- without joy -- 10 of 14 runs were error-free, which
is a good improvement over 0 of 84 for your earlier patch. ;-) But
not statistically different from what I see without either patch.
But no statistical difference compared to without patch, and I still
see the "rcu_sched kthread starved" messages. For whatever it is worth,
by the way, I also see this: "hrtimer: interrupt took 5712368 ns".
Hmmm... I am also seeing that without any of your patches. Might
be hypervisor preemption, I guess.
Okay it makes the warnings go away for me, but I'm just booting then
leaving the system idle. You're doing some CPU hotplug activity?
Okay found a bug in the patch (it was not forwarding properly before
adding the first timer after an idle) and a few other concerns.
There's still a problem of a timer function doing a mod timer from
within expire_timers. It can't forward the base, which might currently
be quite a way behind. I *think* after we close these gaps and get
timely wakeups for timers on there, it should not get too far behind
for standard timers.
Deferrable is a different story. Firstly it has no idle tracking so we
never forward it. Even if we wanted to, we can't do it reliably because
it could contain timers way behind the base. They are "deferrable", so
you get what you pay for, but this still means there's a window where
you can add a deferrable timer and get a far later expiry than you
asked for despite the CPU never going idle after you added it.
All these problems would seem to go away if mod_timer just queued up
the timer to a single list on the base then pushed them into the
wheel during your wheel processing softirq... Although maybe you end
up with excessive passes over big queue of timers. Anyway that
wouldn't be suitable for 4.13 even if it could work.
I'll send out an updated minimal fix after some more testing...
Thanks,
Nick
On Mon, 21 Aug 2017 16:06:05 +1000
Nicholas Piggin [off-list ref] wrote:
On Mon, 21 Aug 2017 10:52:58 +1000
Nicholas Piggin [off-list ref] wrote:
quoted
On Sun, 20 Aug 2017 14:14:29 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Sun, Aug 20, 2017 at 11:35:14AM -0700, Paul E. McKenney wrote:
quoted
On Sun, Aug 20, 2017 at 11:00:40PM +1000, Nicholas Piggin wrote:
quoted
On Sun, 20 Aug 2017 14:45:53 +1000
Nicholas Piggin [off-list ref] wrote:
quoted
On Wed, 16 Aug 2017 09:27:31 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Wed, Aug 16, 2017 at 05:56:17AM -0700, Paul E. McKenney wrote:
Thomas, John, am I misinterpreting the timer trace event messages?
So I did some digging, and what you find is that rcu_sched seems to do a
simple scheudle_timeout(1) and just goes out to lunch for many seconds.
The process_timeout timer never fires (when it finally does wake after
one of these events, it usually removes the timer with del_timer_sync).
So this patch seems to fix it. Testing, comments welcome.
Okay this had a problem of trying to forward the timer from a timer
callback function.
This was my other approach which also fixes the RCU warnings, but it's
a little more complex. I reworked it a bit so the mod_timer fast path
hopefully doesn't have much more overhead (actually by reading jiffies
only when needed, it probably saves a load).
Giving this one a whirl!
No joy here, but then again there are other reasons to believe that I
am seeing a different bug than Dave and Jonathan are.
OK, not -entirely- without joy -- 10 of 14 runs were error-free, which
is a good improvement over 0 of 84 for your earlier patch. ;-) But
not statistically different from what I see without either patch.
But no statistical difference compared to without patch, and I still
see the "rcu_sched kthread starved" messages. For whatever it is worth,
by the way, I also see this: "hrtimer: interrupt took 5712368 ns".
Hmmm... I am also seeing that without any of your patches. Might
be hypervisor preemption, I guess.
Okay it makes the warnings go away for me, but I'm just booting then
leaving the system idle. You're doing some CPU hotplug activity?
Okay found a bug in the patch (it was not forwarding properly before
adding the first timer after an idle) and a few other concerns.
There's still a problem of a timer function doing a mod timer from
within expire_timers. It can't forward the base, which might currently
be quite a way behind. I *think* after we close these gaps and get
timely wakeups for timers on there, it should not get too far behind
for standard timers.
Deferrable is a different story. Firstly it has no idle tracking so we
never forward it. Even if we wanted to, we can't do it reliably because
it could contain timers way behind the base. They are "deferrable", so
you get what you pay for, but this still means there's a window where
you can add a deferrable timer and get a far later expiry than you
asked for despite the CPU never going idle after you added it.
All these problems would seem to go away if mod_timer just queued up
the timer to a single list on the base then pushed them into the
wheel during your wheel processing softirq... Although maybe you end
up with excessive passes over big queue of timers. Anyway that
wouldn't be suitable for 4.13 even if it could work.
I'll send out an updated minimal fix after some more testing...
Hi All,
I'm back in the office with hardware access on our D05 64 core ARM64
boards.
I think we still have by far the quickest test cases for this so
feel free to ping me anything you want tested quickly (we were
looking at an average of less than 10 minutes to trigger
with machine idling).
Nick, I'm currently running your previous version and we are over an
hour so even without any instances of the issue so it looks like a
considerable improvement. I'll see if I can line a couple of boards
up for an overnight run if you have your updated version out by then.
Be great to finally put this one to bed.
Thanks,
Jonathan
On Mon, 21 Aug 2017 11:18:33 +0100
Jonathan Cameron [off-list ref] wrote:
On Mon, 21 Aug 2017 16:06:05 +1000
Nicholas Piggin [off-list ref] wrote:
quoted
On Mon, 21 Aug 2017 10:52:58 +1000
Nicholas Piggin [off-list ref] wrote:
quoted
On Sun, 20 Aug 2017 14:14:29 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Sun, Aug 20, 2017 at 11:35:14AM -0700, Paul E. McKenney wrote:
quoted
On Sun, Aug 20, 2017 at 11:00:40PM +1000, Nicholas Piggin wrote:
quoted
On Sun, 20 Aug 2017 14:45:53 +1000
Nicholas Piggin [off-list ref] wrote:
quoted
On Wed, 16 Aug 2017 09:27:31 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Wed, Aug 16, 2017 at 05:56:17AM -0700, Paul E. McKenney wrote:
Thomas, John, am I misinterpreting the timer trace event messages?
So I did some digging, and what you find is that rcu_sched seems to do a
simple scheudle_timeout(1) and just goes out to lunch for many seconds.
The process_timeout timer never fires (when it finally does wake after
one of these events, it usually removes the timer with del_timer_sync).
So this patch seems to fix it. Testing, comments welcome.
Okay this had a problem of trying to forward the timer from a timer
callback function.
This was my other approach which also fixes the RCU warnings, but it's
a little more complex. I reworked it a bit so the mod_timer fast path
hopefully doesn't have much more overhead (actually by reading jiffies
only when needed, it probably saves a load).
Giving this one a whirl!
No joy here, but then again there are other reasons to believe that I
am seeing a different bug than Dave and Jonathan are.
OK, not -entirely- without joy -- 10 of 14 runs were error-free, which
is a good improvement over 0 of 84 for your earlier patch. ;-) But
not statistically different from what I see without either patch.
But no statistical difference compared to without patch, and I still
see the "rcu_sched kthread starved" messages. For whatever it is worth,
by the way, I also see this: "hrtimer: interrupt took 5712368 ns".
Hmmm... I am also seeing that without any of your patches. Might
be hypervisor preemption, I guess.
Okay it makes the warnings go away for me, but I'm just booting then
leaving the system idle. You're doing some CPU hotplug activity?
Okay found a bug in the patch (it was not forwarding properly before
adding the first timer after an idle) and a few other concerns.
There's still a problem of a timer function doing a mod timer from
within expire_timers. It can't forward the base, which might currently
be quite a way behind. I *think* after we close these gaps and get
timely wakeups for timers on there, it should not get too far behind
for standard timers.
Deferrable is a different story. Firstly it has no idle tracking so we
never forward it. Even if we wanted to, we can't do it reliably because
it could contain timers way behind the base. They are "deferrable", so
you get what you pay for, but this still means there's a window where
you can add a deferrable timer and get a far later expiry than you
asked for despite the CPU never going idle after you added it.
All these problems would seem to go away if mod_timer just queued up
the timer to a single list on the base then pushed them into the
wheel during your wheel processing softirq... Although maybe you end
up with excessive passes over big queue of timers. Anyway that
wouldn't be suitable for 4.13 even if it could work.
I'll send out an updated minimal fix after some more testing...
Hi All,
I'm back in the office with hardware access on our D05 64 core ARM64
boards.
I think we still have by far the quickest test cases for this so
feel free to ping me anything you want tested quickly (we were
looking at an average of less than 10 minutes to trigger
with machine idling).
Nick, I'm currently running your previous version and we are over an
hour so even without any instances of the issue so it looks like a
considerable improvement. I'll see if I can line a couple of boards
up for an overnight run if you have your updated version out by then.
Be great to finally put this one to bed.
Hi Jonathan,
Thanks here's an updated version with a couple more bugs fixed. If
you could try testing, that would be much appreciated.
Thanks,
Nick
---
kernel/time/timer.c | 43 +++++++++++++++++++++++++++++++++++--------
1 file changed, 35 insertions(+), 8 deletions(-)
@@ -203,6 +203,7 @@ struct timer_base {boolmigration_enabled;boolnohz_active;boolis_idle;+boolwas_idle;/* was it idle since last run/fwded */DECLARE_BITMAP(pending_map,WHEEL_SIZE);structhlist_headvectors[WHEEL_SIZE];}____cacheline_aligned;
@@ -991,12 +1007,10 @@ __mod_timer(struct timer_list *timer, unsigned long expires, bool pending_only)raw_spin_lock(&base->lock);WRITE_ONCE(timer->flags,(timer->flags&~TIMER_BASEMASK)|base->cpu);+forward_timer_base(base);}}-/* Try to forward a stale timer base clock */-forward_timer_base(base);-timer->expires=expires;/**If'idx'wascalculatedaboveandthebasetimedidnotadvance
@@ -1499,8 +1513,10 @@ u64 get_next_timer_interrupt(unsigned long basej, u64 basem)/**Ifweexpecttosleepmorethanatick,markthebaseidle:*/-if((expires-basem)>TICK_NSEC)+if((expires-basem)>TICK_NSEC){+base->was_idle=true;base->is_idle=true;+}}raw_spin_unlock(&base->lock);
On Tue, 22 Aug 2017 00:19:28 +1000
Nicholas Piggin [off-list ref] wrote:
On Mon, 21 Aug 2017 11:18:33 +0100
Jonathan Cameron [off-list ref] wrote:
quoted
On Mon, 21 Aug 2017 16:06:05 +1000
Nicholas Piggin [off-list ref] wrote:
quoted
On Mon, 21 Aug 2017 10:52:58 +1000
Nicholas Piggin [off-list ref] wrote:
quoted
On Sun, 20 Aug 2017 14:14:29 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Sun, Aug 20, 2017 at 11:35:14AM -0700, Paul E. McKenney wrote:
quoted
On Sun, Aug 20, 2017 at 11:00:40PM +1000, Nicholas Piggin wrote:
quoted
On Sun, 20 Aug 2017 14:45:53 +1000
Nicholas Piggin [off-list ref] wrote:
quoted
On Wed, 16 Aug 2017 09:27:31 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Wed, Aug 16, 2017 at 05:56:17AM -0700, Paul E. McKenney wrote:
Thomas, John, am I misinterpreting the timer trace event messages?
So I did some digging, and what you find is that rcu_sched seems to do a
simple scheudle_timeout(1) and just goes out to lunch for many seconds.
The process_timeout timer never fires (when it finally does wake after
one of these events, it usually removes the timer with del_timer_sync).
So this patch seems to fix it. Testing, comments welcome.
Okay this had a problem of trying to forward the timer from a timer
callback function.
This was my other approach which also fixes the RCU warnings, but it's
a little more complex. I reworked it a bit so the mod_timer fast path
hopefully doesn't have much more overhead (actually by reading jiffies
only when needed, it probably saves a load).
Giving this one a whirl!
No joy here, but then again there are other reasons to believe that I
am seeing a different bug than Dave and Jonathan are.
OK, not -entirely- without joy -- 10 of 14 runs were error-free, which
is a good improvement over 0 of 84 for your earlier patch. ;-) But
not statistically different from what I see without either patch.
But no statistical difference compared to without patch, and I still
see the "rcu_sched kthread starved" messages. For whatever it is worth,
by the way, I also see this: "hrtimer: interrupt took 5712368 ns".
Hmmm... I am also seeing that without any of your patches. Might
be hypervisor preemption, I guess.
Okay it makes the warnings go away for me, but I'm just booting then
leaving the system idle. You're doing some CPU hotplug activity?
Okay found a bug in the patch (it was not forwarding properly before
adding the first timer after an idle) and a few other concerns.
There's still a problem of a timer function doing a mod timer from
within expire_timers. It can't forward the base, which might currently
be quite a way behind. I *think* after we close these gaps and get
timely wakeups for timers on there, it should not get too far behind
for standard timers.
Deferrable is a different story. Firstly it has no idle tracking so we
never forward it. Even if we wanted to, we can't do it reliably because
it could contain timers way behind the base. They are "deferrable", so
you get what you pay for, but this still means there's a window where
you can add a deferrable timer and get a far later expiry than you
asked for despite the CPU never going idle after you added it.
All these problems would seem to go away if mod_timer just queued up
the timer to a single list on the base then pushed them into the
wheel during your wheel processing softirq... Although maybe you end
up with excessive passes over big queue of timers. Anyway that
wouldn't be suitable for 4.13 even if it could work.
I'll send out an updated minimal fix after some more testing...
Hi All,
I'm back in the office with hardware access on our D05 64 core ARM64
boards.
I think we still have by far the quickest test cases for this so
feel free to ping me anything you want tested quickly (we were
looking at an average of less than 10 minutes to trigger
with machine idling).
Nick, I'm currently running your previous version and we are over an
hour so even without any instances of the issue so it looks like a
considerable improvement. I'll see if I can line a couple of boards
up for an overnight run if you have your updated version out by then.
Be great to finally put this one to bed.
Hi Jonathan,
Thanks here's an updated version with a couple more bugs fixed. If
you could try testing, that would be much appreciated.
Thanks,
Nick
Running now on 1 board. I'll grab another in a few hours and report back
in the morning if we don't see issues before I head off.
We got to about 5 hours on previous version without a problem vs
sub 10 minutes on the two baseline tests I ran without it, so even
with bugs that seemed to have dealt with the issue itself.
On 15 mins so far and all good.
Jonathan
@@ -203,6 +203,7 @@ struct timer_base {boolmigration_enabled;boolnohz_active;boolis_idle;+boolwas_idle;/* was it idle since last run/fwded */DECLARE_BITMAP(pending_map,WHEEL_SIZE);structhlist_headvectors[WHEEL_SIZE];}____cacheline_aligned;
@@ -991,12 +1007,10 @@ __mod_timer(struct timer_list *timer, unsigned long expires, bool pending_only)raw_spin_lock(&base->lock);WRITE_ONCE(timer->flags,(timer->flags&~TIMER_BASEMASK)|base->cpu);+forward_timer_base(base);}}-/* Try to forward a stale timer base clock */-forward_timer_base(base);-timer->expires=expires;/**If'idx'wascalculatedaboveandthebasetimedidnotadvance
@@ -1499,8 +1513,10 @@ u64 get_next_timer_interrupt(unsigned long basej, u64 basem)/**Ifweexpecttosleepmorethanatick,markthebaseidle:*/-if((expires-basem)>TICK_NSEC)+if((expires-basem)>TICK_NSEC){+base->was_idle=true;base->is_idle=true;+}}raw_spin_unlock(&base->lock);
From: Nicholas Piggin <npiggin@gmail.com>
Date: Tue, 22 Aug 2017 00:19:28 +1000
Thanks here's an updated version with a couple more bugs fixed. If
you could try testing, that would be much appreciated.
I'm not getting RCU stalls on sparc64 any longer with this patch.
I'm really happy you guys were able to figure out what was going
wrong. :-)
Feel free to add my Tested-by:
From: Paul E. McKenney <hidden> Date: 2017-08-22 00:38:17
On Mon, Aug 21, 2017 at 10:52:58AM +1000, Nicholas Piggin wrote:
On Sun, 20 Aug 2017 14:14:29 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Sun, Aug 20, 2017 at 11:35:14AM -0700, Paul E. McKenney wrote:
quoted
On Sun, Aug 20, 2017 at 11:00:40PM +1000, Nicholas Piggin wrote:
quoted
On Sun, 20 Aug 2017 14:45:53 +1000
Nicholas Piggin [off-list ref] wrote:
quoted
On Wed, 16 Aug 2017 09:27:31 -0700
"Paul E. McKenney" [off-list ref] wrote:
quoted
On Wed, Aug 16, 2017 at 05:56:17AM -0700, Paul E. McKenney wrote:
Thomas, John, am I misinterpreting the timer trace event messages?
So I did some digging, and what you find is that rcu_sched seems to do a
simple scheudle_timeout(1) and just goes out to lunch for many seconds.
The process_timeout timer never fires (when it finally does wake after
one of these events, it usually removes the timer with del_timer_sync).
So this patch seems to fix it. Testing, comments welcome.
Okay this had a problem of trying to forward the timer from a timer
callback function.
This was my other approach which also fixes the RCU warnings, but it's
a little more complex. I reworked it a bit so the mod_timer fast path
hopefully doesn't have much more overhead (actually by reading jiffies
only when needed, it probably saves a load).
Giving this one a whirl!
No joy here, but then again there are other reasons to believe that I
am seeing a different bug than Dave and Jonathan are.
OK, not -entirely- without joy -- 10 of 14 runs were error-free, which
is a good improvement over 0 of 84 for your earlier patch. ;-) But
not statistically different from what I see without either patch.
But no statistical difference compared to without patch, and I still
see the "rcu_sched kthread starved" messages. For whatever it is worth,
by the way, I also see this: "hrtimer: interrupt took 5712368 ns".
Hmmm... I am also seeing that without any of your patches. Might
be hypervisor preemption, I guess.
Okay it makes the warnings go away for me, but I'm just booting then
leaving the system idle. You're doing some CPU hotplug activity?
Yes, along with rcutorture, so a very different workload.
Thanx, Paul
On Mon, 21 Aug 2017 13:55:04 -0700
David Miller [off-list ref] wrote:
From: Nicholas Piggin <npiggin@gmail.com>
Date: Tue, 22 Aug 2017 00:19:28 +1000
quoted
Thanks here's an updated version with a couple more bugs fixed. If
you could try testing, that would be much appreciated.
I'm not getting RCU stalls on sparc64 any longer with this patch.
I'm really happy you guys were able to figure out what was going
wrong. :-)
Feel free to add my Tested-by:
Like wise - 16 hours of clean run with the latest
Tested-by: Jonathan Cameron <Jonathan.Cameron@huawei.com>
Thanks for all the hard work everyone put into this one, great to
cross it off the list!
Jonathan
From: Abdul Haleem <hidden> Date: 2017-08-22 08:51:32
On Tue, 2017-08-22 at 08:49 +0100, Jonathan Cameron wrote:
On Mon, 21 Aug 2017 13:55:04 -0700
David Miller [off-list ref] wrote:
quoted
From: Nicholas Piggin <npiggin@gmail.com>
Date: Tue, 22 Aug 2017 00:19:28 +1000
quoted
Thanks here's an updated version with a couple more bugs fixed. If
you could try testing, that would be much appreciated.
I'm not getting RCU stalls on sparc64 any longer with this patch.
I'm really happy you guys were able to figure out what was going
wrong. :-)
Feel free to add my Tested-by:
Like wise - 16 hours of clean run with the latest
Tested-by: Jonathan Cameron <Jonathan.Cameron@huawei.com>
Thanks for all the hard work everyone put into this one, great to
cross it off the list!
Jonathan
No more RCU stalls on PowerPC, system is clean when idle or with some
test runs.
Thank you all for your time and efforts in fixing this.
Reported-and-Tested-by: Abdul Haleem <redacted>
--
Regard's
Abdul Haleem
IBM Linux Technology Centre
From: Paul E. McKenney <hidden> Date: 2017-08-22 15:26:37
On Tue, Aug 22, 2017 at 02:21:32PM +0530, Abdul Haleem wrote:
On Tue, 2017-08-22 at 08:49 +0100, Jonathan Cameron wrote:
quoted
On Mon, 21 Aug 2017 13:55:04 -0700
David Miller [off-list ref] wrote:
quoted
From: Nicholas Piggin <npiggin@gmail.com>
Date: Tue, 22 Aug 2017 00:19:28 +1000
quoted
Thanks here's an updated version with a couple more bugs fixed. If
you could try testing, that would be much appreciated.
I'm not getting RCU stalls on sparc64 any longer with this patch.
I'm really happy you guys were able to figure out what was going
wrong. :-)
Feel free to add my Tested-by:
Like wise - 16 hours of clean run with the latest
Tested-by: Jonathan Cameron <Jonathan.Cameron@huawei.com>
Thanks for all the hard work everyone put into this one, great to
cross it off the list!
Jonathan
No more RCU stalls on PowerPC, system is clean when idle or with some
test runs.
Thank you all for your time and efforts in fixing this.
Reported-and-Tested-by: Abdul Haleem <redacted>
I am still seeing failures, but then again I am running rcutorture with
lots of CPU hotplug activity. So I am probably seeing some other bug,
though it still looks a lot like a lost timer.
Thanx, Paul
From: Paul E. McKenney <hidden> Date: 2017-09-06 12:28:44
On Tue, Aug 22, 2017 at 08:26:37AM -0700, Paul E. McKenney wrote:
On Tue, Aug 22, 2017 at 02:21:32PM +0530, Abdul Haleem wrote:
quoted
On Tue, 2017-08-22 at 08:49 +0100, Jonathan Cameron wrote:
[ . . . ]
quoted
No more RCU stalls on PowerPC, system is clean when idle or with some
test runs.
Thank you all for your time and efforts in fixing this.
Reported-and-Tested-by: Abdul Haleem <redacted>
I am still seeing failures, but then again I am running rcutorture with
lots of CPU hotplug activity. So I am probably seeing some other bug,
though it still looks a lot like a lost timer.
So one problem appears to be a timing-related deadlock between RCU and
timers. The way that this can happen is that the outgoing CPU goes
offline (as in cpuhp_report_idle_dead() invoked from do_idle()) with
one of RCU's grace-period kthread's timers queued. Now, if someone
waits for a grace period, either directly or indirectly, in a way that
blocks the hotplug notifiers, execution will never reach timers_dead_cpu(),
which means that the grace-period kthread will never wake, which will
mean that the grace period will never complete. Classic deadlock.
I currently have an extremely ugly workaround for this deadlock, which
is to periodically and (usually) redundantly wake up all the RCU
grace-period kthreads from the scheduling-interrupt handler. This is
of course completely inappropriate for mainline, but it does reliably
prevent the "kthread starved for %ld jiffies!" type of RCU CPU stall
warning that I would otherwise see.
To mainline this, one approach would be to make the timers switch to
add_timer_on() to a surviving CPU once the offlining process starts.
Alternatively, I suppose that RCU could do the redundant-wakeup kludge,
but with checks to prevent it from happening unless (1) there is a CPU
in the process of going offline (2) there is an RCU grace period in
progress, and (3) the RCU grace period kthread has been blocked for
(say) three times longer than it should have.
Unfortunately, this is not sufficient to make rcutorture run reliably,
though it does help, which is of course to say that it makes debugging
slower. ;-)
What happens now is that random rcutorture kthreads will hang waiting for
timeouts to complete. This confused me for awhile because I expected
that the timeouts would be delayed during offline processing, but that
my crude deadlock-resolution approach would eventually get things going.
My current suspicion is that the problem is due to a potential delay
between the time an outgoing CPU hits cpuhp_report_idle_dead() and the
timers get migrated from timers_dead_cpu(). This means that the CPU
adopting the timers might be a few ticks ahead of where the outgoing CPU
last processed timers. My current guess is that any timers queued in
intervening indexes are going to wait one good long time. And I don't see
any code in the timers_dead_cpu() that would account for this possibility,
though I of course cannot claim to fully understand this code..
Is this plausible, or am I confused? (Either way, -something- besides
just me is rather thoroughly confused!)
If this is plausible, my guess is that timers_dead_cpu() needs to check
for mismatched indexes (in timer->flags?) and force any intervening
timers to expire if so.
Thoughts?
Thanx, Paul