Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1455423 > unrolled thread

Re: rcu_sched stalls in idle task introduced in pre-4.8?

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: rcu_sched stalls in idle task introduced in pre-4.8? Rich Felker <dalias@libc.org> - 2016-08-02 21:30 +0200
    Re: rcu_sched stalls in idle task introduced in pre-4.8? Rich Felker <dalias@libc.org> - 2016-08-02 22:40 +0200
      Re: rcu_sched stalls in idle task introduced in pre-4.8? "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-08-02 22:50 +0200
        Re: rcu_sched stalls in idle task introduced in pre-4.8? "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-08-04 16:20 +0200
    Re: rcu_sched stalls in idle task introduced in pre-4.8? "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-08-03 00:10 +0200

#1455423 — Re: rcu_sched stalls in idle task introduced in pre-4.8?

On Tue, Aug 02, 2016 at 11:16:36AM -0700, Paul E. McKenney wrote:
> On Tue, Aug 02, 2016 at 01:04:15PM -0400, Rich Felker wrote:
> > Hi Paul,
> > 
> > As I mentioned on Twitter, I'm experiencing (otherwise benign) rcu
> > stall messages since rebasing my tree on Linus's in-progress merge for
> > 4.8, as part of updating both the arch/sh tree and drivers going
> > upstream through other maintainers to account for changes made to
> > infrastructure they depend on. The revisions I've tried rebasing on
> > are 194dc870a5890e855ecffb30f3b80ba7c88f96d6 and
> > 7f155c702677d057d03b192ce652311de5434697 (now using the latter).
> 
> Very helpful, thank you!
> 
> Oh, and you can boot with rcupdate.rcu_cpu_stall_suppress to prevent
> RCU CPU stall warnings from appearing, though that of course won't
> help with whatever the underlying problem might be.

Indeed, but I have found them quite useful in the past for tracking
down actual deadlocks, so it's nice to keep them enabled.

> > The system I'm testing on is an SMP configuration of the J2 SoC on
> > FPGA (see: j-core.org), and the SMP support and timer driver (most
> > relevant, imo) are new, but never exhibited this problem on 4.6 or
> > 4.7. A tree with all drivers merged is available in the development
> > branch of git://git.libc.org/linux-sh; it's regularly rebased but
> > there's a perma-tag devel-20160801 you can check out instead. Fetching
> > into an existing clone of Linus's tree is recommended since the server
> > has limited resources.
> > 
> > I doubt the code from my devel branch will be useful without hardware
> > to test on, though. Hopefully the issue is reproducible on other
> > systems. Very low cpu speed (50 MHz) could be a factor. The problem
> > seems to go away with dyntick disabled.
> 
> Indeed, it is quite possible that RCU's self-tuning needs a bit of help
> for CPUs below a few hundred MHz.  As might other pieces of the kernel.
> Should not be a big deal (famous last words...).  However, given that
> you are running HZ=100, it should be reasonably close.  So first, let's
> see what is going on here...
> 
> The following dmesg line usually indicates that RCU's kernel thread is
> stuck for some reason.
> 
> [42039.188293] rcu_sched kthread starved for 2152 jiffies! g70249 c70248 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
> 
> The RCU_GP_WAIT_FQS indicates that it is waiting for a timer to expire.
> The task is in TASK_INTERRUPTIBLE state, but it should have been awakened
> after only a few jiffies sleep time.  The stack trace looks like there
> might be trouble canceling the timer.

Can you offer any advice on tracking down what it's waiting for, or
what's going on with the timer? Is any arch- or clockevent-specific
stuff that might be my fault involved here?

> Is it possible that the timer
> handler is being prevented from making progress due to heavy interrupt
> load or some such?

Actually the stall messages are only appearing when the system is idle
and interrupts are infrequent. That's what leads me to believe it
might be a situation where, on every (infrequent) wake, both the rcu
task and something blocking its progress happen at roughly the same
time, and the slowness of the cpu leads the rcu task to decide to wait
for the next timer/schedule event and try again -- over and over. Of
course this hypothesis is just based on a very high-level
understanding of what's going on; I'm not sufficiently familiar wilth
the implementation specifics to offer more.

One observation I just made versus old kernels where this was not
happening: I've got a lot more timer interrupts happening than before.
In 6 minutes of uptime:

           CPU0       CPU1
 17:         38          0       AIC  17  abce0000.ethernet
 18:        811          0       AIC  18  uartlite
 20:        188        121       AIC  20  ipi
 72:      11295       6499       AIC  72  jcore_pit

That's 30+ timer interrupts per sec on cpu0. Previously it was more
like 1-5 per second when idle (with dyntick).

> > My .config and message log are below. Let me know if there are any
> > other details I can provide that would be helpful.
> 
> In case the timer issue I am suspecting is a red herring...
> 
> RCU does tune itself for different values of HZ, but it might need more
> help for 50MHz CPUs.  (Although if this were the problem, I would expect
> you to be seeing excessive CPU consumption by the rcu_sched kthread.)
> But it might be worthwhile booting with rcutree.jiffies_till_sched_qs=10
> and rcutree.jiffies_till_first_fqs=10 (or thereabouts).  It might also
> be necessary to use a longer RCU CPU stall warning timeout (assuming
> you don't just suppress it as above), for example, by booting with (say)
> rcupdate.rcu_cpu_stall_timeout=60.

With that in mind, it seems plausible that the problem existed before
and just went over the threshold for reporting the stall with a
non-bug change going into 4.8. Would building an older known-good
kernel with TREE_RCU_TRACE enabled and checking debugfs
rcu/rcu_sched/rcugp for max=??? be informative?

> Is there any way for RCU to determine at boot time what the nominal CPU
> speed is?  I suppose I could look at BogoMIPs, but is there something
> better?

I'm not aware of any clean cross-arch way to do it.

Rich

[toc] | [next] | [standalone]

#1455456

On Tue, Aug 02, 2016 at 12:48:02PM -0700, Paul E. McKenney wrote:
> > > > The system I'm testing on is an SMP configuration of the J2 SoC on
> > > > FPGA (see: j-core.org), and the SMP support and timer driver (most
> > > > relevant, imo) are new, but never exhibited this problem on 4.6 or
> > > > 4.7. A tree with all drivers merged is available in the development
> > > > branch of git://git.libc.org/linux-sh; it's regularly rebased but
> > > > there's a perma-tag devel-20160801 you can check out instead. Fetching
> > > > into an existing clone of Linus's tree is recommended since the server
> > > > has limited resources.
> > > > 
> > > > I doubt the code from my devel branch will be useful without hardware
> > > > to test on, though. Hopefully the issue is reproducible on other
> > > > systems. Very low cpu speed (50 MHz) could be a factor. The problem
> > > > seems to go away with dyntick disabled.
> > > 
> > > Indeed, it is quite possible that RCU's self-tuning needs a bit of help
> > > for CPUs below a few hundred MHz.  As might other pieces of the kernel.
> > > Should not be a big deal (famous last words...).  However, given that
> > > you are running HZ=100, it should be reasonably close.  So first, let's
> > > see what is going on here...
> > > 
> > > The following dmesg line usually indicates that RCU's kernel thread is
> > > stuck for some reason.
> > > 
> > > [42039.188293] rcu_sched kthread starved for 2152 jiffies! g70249 c70248 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
> > > 
> > > The RCU_GP_WAIT_FQS indicates that it is waiting for a timer to expire.
> > > The task is in TASK_INTERRUPTIBLE state, but it should have been awakened
> > > after only a few jiffies sleep time.  The stack trace looks like there
> > > might be trouble canceling the timer.
> > 
> > Can you offer any advice on tracking down what it's waiting for, or
> > what's going on with the timer? Is any arch- or clockevent-specific
> > stuff that might be my fault involved here?
> 
> It is in an swait_event_interruptible_timeout(), most likely waiting on
> a one-jiffy timer, as in __mod_timer().  If I understood your earlier
> email correctly, setting CONFIG_HZ_PERIODIC avoided this problem.
> If my understanding is correct, it might be worth reviewing any timer
> code that might be pushed along by the once-per-jiffy scheduler tick.

Is it possible that something wacky is going on with broadcast timers?
A dummy broadcast timer device gets initialized momentatily before the
percpu timer for the secondary cpu is initialized, and in my
experience these broadcast timers don't work when the real timer
device has a cpumask limiting it to a specific cpu (which seems like a
bug, but one I haven't had to care about since I'm not using it).

> Does the problem reproduces easily?

Yes, it happens right after boot and repeats every 30-90 seconds or
so.

> A bisection might be very helpful.

Bisection would require some manual work to setup because the whole
reason I was rebasing on Linus's tree was to adapt the drivers to
upstream infrastructure changes (the new cpuhp stuff replacing
notifier for cpu starting). The unfortunate way it was done, each
driver adds an enum to linux/cpuhotplug.h so all the patches have
gratuitous conflicts. In addition, for older revisions in Linus's
tree, there's at least one show-stopping (hang during boot) bug that
needs a cherry-pick to fix. There may be other small issues too. I
don't think they're at all insurmountible but it requires an annoying
amount of scripting.

> > > Is it possible that the timer
> > > handler is being prevented from making progress due to heavy interrupt
> > > load or some such?
> > 
> > Actually the stall messages are only appearing when the system is idle
> > and interrupts are infrequent. That's what leads me to believe it
> > might be a situation where, on every (infrequent) wake, both the rcu
> > task and something blocking its progress happen at roughly the same
> > time, and the slowness of the cpu leads the rcu task to decide to wait
> > for the next timer/schedule event and try again -- over and over. Of
> > course this hypothesis is just based on a very high-level
> > understanding of what's going on; I'm not sufficiently familiar wilth
> > the implementation specifics to offer more.
> > 
> > One observation I just made versus old kernels where this was not
> > happening: I've got a lot more timer interrupts happening than before.
> > In 6 minutes of uptime:
> > 
> >            CPU0       CPU1
> >  17:         38          0       AIC  17  abce0000.ethernet
> >  18:        811          0       AIC  18  uartlite
> >  20:        188        121       AIC  20  ipi
> >  72:      11295       6499       AIC  72  jcore_pit
> > 
> > That's 30+ timer interrupts per sec on cpu0. Previously it was more
> > like 1-5 per second when idle (with dyntick).
> 
> That is interesting, but I don't know what to make of it.  RCU does depend
> heavily on timed sleeps to make forward progress, so if timer interrupts
> were lost, that would be a smoking gun.  But you actually appear to have
> -more- timer interrupts in the failure case rather than fewer!

Could the extra interrupts be a symptom of the rcu task doing a
very-short sleep to retry over and over?

> > > > My .config and message log are below. Let me know if there are any
> > > > other details I can provide that would be helpful.
> > > 
> > > In case the timer issue I am suspecting is a red herring...
> > > 
> > > RCU does tune itself for different values of HZ, but it might need more
> > > help for 50MHz CPUs.  (Although if this were the problem, I would expect
> > > you to be seeing excessive CPU consumption by the rcu_sched kthread.)
> > > But it might be worthwhile booting with rcutree.jiffies_till_sched_qs=10
> > > and rcutree.jiffies_till_first_fqs=10 (or thereabouts).  It might also
> > > be necessary to use a longer RCU CPU stall warning timeout (assuming
> > > you don't just suppress it as above), for example, by booting with (say)
> > > rcupdate.rcu_cpu_stall_timeout=60.
> > 
> > With that in mind, it seems plausible that the problem existed before
> > and just went over the threshold for reporting the stall with a
> > non-bug change going into 4.8. Would building an older known-good
> > kernel with TREE_RCU_TRACE enabled and checking debugfs
> > rcu/rcu_sched/rcugp for max=??? be informative?
> 
> It might be.  However, if ftrace is enabled on your platform, getting
> a trace of the RCU-related events would be even more likely to be
> helpful.  And for that matter, the timer-related events.

It looks like ftrace is supported on sh. Looks like I have some
reading to do -- this could be very useful.

> One way to determine whether we were just on the edge on
> the older systems would be to boot them with smaller values of
> rcupdate.rcu_cpu_stall_timeout=60.  The default values of the other two
> boot parameters looks to already be at the minimum usefule value, though.

CONFIG_RCU_CPU_STALL_TIMEOUT=21 seems to be what it's hitting.

Rich

[toc] | [prev] | [next] | [standalone]

#1455462

On Tue, Aug 02, 2016 at 04:32:17PM -0400, Rich Felker wrote:
> On Tue, Aug 02, 2016 at 12:48:02PM -0700, Paul E. McKenney wrote:
> > > > > The system I'm testing on is an SMP configuration of the J2 SoC on
> > > > > FPGA (see: j-core.org), and the SMP support and timer driver (most
> > > > > relevant, imo) are new, but never exhibited this problem on 4.6 or
> > > > > 4.7. A tree with all drivers merged is available in the development
> > > > > branch of git://git.libc.org/linux-sh; it's regularly rebased but
> > > > > there's a perma-tag devel-20160801 you can check out instead. Fetching
> > > > > into an existing clone of Linus's tree is recommended since the server
> > > > > has limited resources.
> > > > > 
> > > > > I doubt the code from my devel branch will be useful without hardware
> > > > > to test on, though. Hopefully the issue is reproducible on other
> > > > > systems. Very low cpu speed (50 MHz) could be a factor. The problem
> > > > > seems to go away with dyntick disabled.
> > > > 
> > > > Indeed, it is quite possible that RCU's self-tuning needs a bit of help
> > > > for CPUs below a few hundred MHz.  As might other pieces of the kernel.
> > > > Should not be a big deal (famous last words...).  However, given that
> > > > you are running HZ=100, it should be reasonably close.  So first, let's
> > > > see what is going on here...
> > > > 
> > > > The following dmesg line usually indicates that RCU's kernel thread is
> > > > stuck for some reason.
> > > > 
> > > > [42039.188293] rcu_sched kthread starved for 2152 jiffies! g70249 c70248 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
> > > > 
> > > > The RCU_GP_WAIT_FQS indicates that it is waiting for a timer to expire.
> > > > The task is in TASK_INTERRUPTIBLE state, but it should have been awakened
> > > > after only a few jiffies sleep time.  The stack trace looks like there
> > > > might be trouble canceling the timer.
> > > 
> > > Can you offer any advice on tracking down what it's waiting for, or
> > > what's going on with the timer? Is any arch- or clockevent-specific
> > > stuff that might be my fault involved here?
> > 
> > It is in an swait_event_interruptible_timeout(), most likely waiting on
> > a one-jiffy timer, as in __mod_timer().  If I understood your earlier
> > email correctly, setting CONFIG_HZ_PERIODIC avoided this problem.
> > If my understanding is correct, it might be worth reviewing any timer
> > code that might be pushed along by the once-per-jiffy scheduler tick.
> 
> Is it possible that something wacky is going on with broadcast timers?
> A dummy broadcast timer device gets initialized momentatily before the
> percpu timer for the secondary cpu is initialized, and in my
> experience these broadcast timers don't work when the real timer
> device has a cpumask limiting it to a specific cpu (which seems like a
> bug, but one I haven't had to care about since I'm not using it).

I need to defer to the timer guys on this one, adding them on CC.

> > Does the problem reproduces easily?
> 
> Yes, it happens right after boot and repeats every 30-90 seconds or
> so.

Well, that at least makes it easier to test any patches!

> > A bisection might be very helpful.
> 
> Bisection would require some manual work to setup because the whole
> reason I was rebasing on Linus's tree was to adapt the drivers to
> upstream infrastructure changes (the new cpuhp stuff replacing
> notifier for cpu starting). The unfortunate way it was done, each
> driver adds an enum to linux/cpuhotplug.h so all the patches have
> gratuitous conflicts. In addition, for older revisions in Linus's
> tree, there's at least one show-stopping (hang during boot) bug that
> needs a cherry-pick to fix. There may be other small issues too. I
> don't think they're at all insurmountible but it requires an annoying
> amount of scripting.

I had to ask!  Might eventually be necessary, but let's see what we
can learn from what you currently have.

> > > > Is it possible that the timer
> > > > handler is being prevented from making progress due to heavy interrupt
> > > > load or some such?
> > > 
> > > Actually the stall messages are only appearing when the system is idle
> > > and interrupts are infrequent. That's what leads me to believe it
> > > might be a situation where, on every (infrequent) wake, both the rcu
> > > task and something blocking its progress happen at roughly the same
> > > time, and the slowness of the cpu leads the rcu task to decide to wait
> > > for the next timer/schedule event and try again -- over and over. Of
> > > course this hypothesis is just based on a very high-level
> > > understanding of what's going on; I'm not sufficiently familiar wilth
> > > the implementation specifics to offer more.
> > > 
> > > One observation I just made versus old kernels where this was not
> > > happening: I've got a lot more timer interrupts happening than before.
> > > In 6 minutes of uptime:
> > > 
> > >            CPU0       CPU1
> > >  17:         38          0       AIC  17  abce0000.ethernet
> > >  18:        811          0       AIC  18  uartlite
> > >  20:        188        121       AIC  20  ipi
> > >  72:      11295       6499       AIC  72  jcore_pit
> > > 
> > > That's 30+ timer interrupts per sec on cpu0. Previously it was more
> > > like 1-5 per second when idle (with dyntick).
> > 
> > That is interesting, but I don't know what to make of it.  RCU does depend
> > heavily on timed sleeps to make forward progress, so if timer interrupts
> > were lost, that would be a smoking gun.  But you actually appear to have
> > -more- timer interrupts in the failure case rather than fewer!
> 
> Could the extra interrupts be a symptom of the rcu task doing a
> very-short sleep to retry over and over?

Possibly.  One way to check for this is to set the kernel boot variables
rcutree.jiffies_till_sched_qs=10 and rcutree.jiffies_till_first_fqs=10.

> > > > > My .config and message log are below. Let me know if there are any
> > > > > other details I can provide that would be helpful.
> > > > 
> > > > In case the timer issue I am suspecting is a red herring...
> > > > 
> > > > RCU does tune itself for different values of HZ, but it might need more
> > > > help for 50MHz CPUs.  (Although if this were the problem, I would expect
> > > > you to be seeing excessive CPU consumption by the rcu_sched kthread.)
> > > > But it might be worthwhile booting with rcutree.jiffies_till_sched_qs=10
> > > > and rcutree.jiffies_till_first_fqs=10 (or thereabouts).  It might also
> > > > be necessary to use a longer RCU CPU stall warning timeout (assuming
> > > > you don't just suppress it as above), for example, by booting with (say)
> > > > rcupdate.rcu_cpu_stall_timeout=60.
> > > 
> > > With that in mind, it seems plausible that the problem existed before
> > > and just went over the threshold for reporting the stall with a
> > > non-bug change going into 4.8. Would building an older known-good
> > > kernel with TREE_RCU_TRACE enabled and checking debugfs
> > > rcu/rcu_sched/rcugp for max=??? be informative?
> > 
> > It might be.  However, if ftrace is enabled on your platform, getting
> > a trace of the RCU-related events would be even more likely to be
> > helpful.  And for that matter, the timer-related events.
> 
> It looks like ftrace is supported on sh. Looks like I have some
> reading to do -- this could be very useful.

Sounds good!

> > One way to determine whether we were just on the edge on
> > the older systems would be to boot them with smaller values of
> > rcupdate.rcu_cpu_stall_timeout=60.  The default values of the other two
> > boot parameters looks to already be at the minimum usefule value, though.
> 
> CONFIG_RCU_CPU_STALL_TIMEOUT=21 seems to be what it's hitting.

Confused.  If you set CONFIG_RCU_CPU_STALL_TIMEOUT to smaller values on
older kernels you see the RCU CPU stall warnings?

							Thanx, Paul

[toc] | [prev] | [next] | [standalone]

#1456428

On Tue, Aug 02, 2016 at 01:45:04PM -0700, Paul E. McKenney wrote:
> On Tue, Aug 02, 2016 at 04:32:17PM -0400, Rich Felker wrote:
> > On Tue, Aug 02, 2016 at 12:48:02PM -0700, Paul E. McKenney wrote:

[ . . . ]

> > > Does the problem reproduces easily?
> > 
> > Yes, it happens right after boot and repeats every 30-90 seconds or
> > so.
> 
> Well, that at least makes it easier to test any patches!
> 
> > > A bisection might be very helpful.
> > 
> > Bisection would require some manual work to setup because the whole
> > reason I was rebasing on Linus's tree was to adapt the drivers to
> > upstream infrastructure changes (the new cpuhp stuff replacing
> > notifier for cpu starting). The unfortunate way it was done, each
> > driver adds an enum to linux/cpuhotplug.h so all the patches have
> > gratuitous conflicts. In addition, for older revisions in Linus's
> > tree, there's at least one show-stopping (hang during boot) bug that
> > needs a cherry-pick to fix. There may be other small issues too. I
> > don't think they're at all insurmountible but it requires an annoying
> > amount of scripting.
> 
> I had to ask!  Might eventually be necessary, but let's see what we
> can learn from what you currently have.

And at first glance, my overnight run looks uglier than I would expect.
I am now running tests at v4.7, and will run other tests to see if
there really is a statistically significant degradation.  If there is,
then I might be able to bisect, though with nine-hour runs this could
take quite some time.

							Thanx, Paul

[toc] | [prev] | [next] | [standalone]

#1455500

On Tue, Aug 02, 2016 at 03:20:37PM -0400, Rich Felker wrote:
> On Tue, Aug 02, 2016 at 11:16:36AM -0700, Paul E. McKenney wrote:
> > On Tue, Aug 02, 2016 at 01:04:15PM -0400, Rich Felker wrote:
> > > Hi Paul,
> > > 
> > > As I mentioned on Twitter, I'm experiencing (otherwise benign) rcu
> > > stall messages since rebasing my tree on Linus's in-progress merge for
> > > 4.8, as part of updating both the arch/sh tree and drivers going
> > > upstream through other maintainers to account for changes made to
> > > infrastructure they depend on. The revisions I've tried rebasing on
> > > are 194dc870a5890e855ecffb30f3b80ba7c88f96d6 and
> > > 7f155c702677d057d03b192ce652311de5434697 (now using the latter).
> > 
> > Very helpful, thank you!
> > 
> > Oh, and you can boot with rcupdate.rcu_cpu_stall_suppress to prevent
> > RCU CPU stall warnings from appearing, though that of course won't
> > help with whatever the underlying problem might be.
> 
> Indeed, but I have found them quite useful in the past for tracking
> down actual deadlocks, so it's nice to keep them enabled.

Glad to hear that they have been helpful in the past!

> > > The system I'm testing on is an SMP configuration of the J2 SoC on
> > > FPGA (see: j-core.org), and the SMP support and timer driver (most
> > > relevant, imo) are new, but never exhibited this problem on 4.6 or
> > > 4.7. A tree with all drivers merged is available in the development
> > > branch of git://git.libc.org/linux-sh; it's regularly rebased but
> > > there's a perma-tag devel-20160801 you can check out instead. Fetching
> > > into an existing clone of Linus's tree is recommended since the server
> > > has limited resources.
> > > 
> > > I doubt the code from my devel branch will be useful without hardware
> > > to test on, though. Hopefully the issue is reproducible on other
> > > systems. Very low cpu speed (50 MHz) could be a factor. The problem
> > > seems to go away with dyntick disabled.
> > 
> > Indeed, it is quite possible that RCU's self-tuning needs a bit of help
> > for CPUs below a few hundred MHz.  As might other pieces of the kernel.
> > Should not be a big deal (famous last words...).  However, given that
> > you are running HZ=100, it should be reasonably close.  So first, let's
> > see what is going on here...
> > 
> > The following dmesg line usually indicates that RCU's kernel thread is
> > stuck for some reason.
> > 
> > [42039.188293] rcu_sched kthread starved for 2152 jiffies! g70249 c70248 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
> > 
> > The RCU_GP_WAIT_FQS indicates that it is waiting for a timer to expire.
> > The task is in TASK_INTERRUPTIBLE state, but it should have been awakened
> > after only a few jiffies sleep time.  The stack trace looks like there
> > might be trouble canceling the timer.
> 
> Can you offer any advice on tracking down what it's waiting for, or
> what's going on with the timer? Is any arch- or clockevent-specific
> stuff that might be my fault involved here?

It is in an swait_event_interruptible_timeout(), most likely waiting on
a one-jiffy timer, as in __mod_timer().  If I understood your earlier
email correctly, setting CONFIG_HZ_PERIODIC avoided this problem.
If my understanding is correct, it might be worth reviewing any timer
code that might be pushed along by the once-per-jiffy scheduler tick.

Does the problem reproduces easily?  A bisection might be very helpful.

> > Is it possible that the timer
> > handler is being prevented from making progress due to heavy interrupt
> > load or some such?
> 
> Actually the stall messages are only appearing when the system is idle
> and interrupts are infrequent. That's what leads me to believe it
> might be a situation where, on every (infrequent) wake, both the rcu
> task and something blocking its progress happen at roughly the same
> time, and the slowness of the cpu leads the rcu task to decide to wait
> for the next timer/schedule event and try again -- over and over. Of
> course this hypothesis is just based on a very high-level
> understanding of what's going on; I'm not sufficiently familiar wilth
> the implementation specifics to offer more.
> 
> One observation I just made versus old kernels where this was not
> happening: I've got a lot more timer interrupts happening than before.
> In 6 minutes of uptime:
> 
>            CPU0       CPU1
>  17:         38          0       AIC  17  abce0000.ethernet
>  18:        811          0       AIC  18  uartlite
>  20:        188        121       AIC  20  ipi
>  72:      11295       6499       AIC  72  jcore_pit
> 
> That's 30+ timer interrupts per sec on cpu0. Previously it was more
> like 1-5 per second when idle (with dyntick).

That is interesting, but I don't know what to make of it.  RCU does depend
heavily on timed sleeps to make forward progress, so if timer interrupts
were lost, that would be a smoking gun.  But you actually appear to have
-more- timer interrupts in the failure case rather than fewer!

> > > My .config and message log are below. Let me know if there are any
> > > other details I can provide that would be helpful.
> > 
> > In case the timer issue I am suspecting is a red herring...
> > 
> > RCU does tune itself for different values of HZ, but it might need more
> > help for 50MHz CPUs.  (Although if this were the problem, I would expect
> > you to be seeing excessive CPU consumption by the rcu_sched kthread.)
> > But it might be worthwhile booting with rcutree.jiffies_till_sched_qs=10
> > and rcutree.jiffies_till_first_fqs=10 (or thereabouts).  It might also
> > be necessary to use a longer RCU CPU stall warning timeout (assuming
> > you don't just suppress it as above), for example, by booting with (say)
> > rcupdate.rcu_cpu_stall_timeout=60.
> 
> With that in mind, it seems plausible that the problem existed before
> and just went over the threshold for reporting the stall with a
> non-bug change going into 4.8. Would building an older known-good
> kernel with TREE_RCU_TRACE enabled and checking debugfs
> rcu/rcu_sched/rcugp for max=??? be informative?

It might be.  However, if ftrace is enabled on your platform, getting
a trace of the RCU-related events would be even more likely to be
helpful.  And for that matter, the timer-related events.

One way to determine whether we were just on the edge on
the older systems would be to boot them with smaller values of
rcupdate.rcu_cpu_stall_timeout=60.  The default values of the other two
boot parameters looks to already be at the minimum usefule value, though.

> > Is there any way for RCU to determine at boot time what the nominal CPU
> > speed is?  I suppose I could look at BogoMIPs, but is there something
> > better?
> 
> I'm not aware of any clean cross-arch way to do it.

If it turns out that the problem is that RCU has to configure itself
differently on 50MHz systems, we will need to revisit this.

							Thanx, Paul

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web