Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1360929 > unrolled thread
| Started by | Josh Triplett <josh@joshtriplett.org> |
|---|---|
| First post | 2016-03-18 22:10 +0100 |
| Last post | 2016-03-28 18:40 +0200 |
| Articles | 20 on this page of 44 — 6 participants |
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.
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Josh Triplett <josh@joshtriplett.org> - 2016-03-18 22:10 +0100
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-19 01:00 +0100
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Jacob Pan <jacob.jun.pan@linux.intel.com> - 2016-03-21 17:30 +0100
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-21 18:30 +0100
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-22 18:50 +0100
RE: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Chatre, Reinette" <reinette.chatre@intel.com> - 2016-03-22 22:10 +0100
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-22 22:20 +0100
RE: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Chatre, Reinette" <reinette.chatre@intel.com> - 2016-03-23 18:20 +0100
RE: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Chatre, Reinette" <reinette.chatre@intel.com> - 2016-03-23 19:30 +0100
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-23 21:00 +0100
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-23 19:30 +0100
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-25 22:50 +0100
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Mathieu Desnoyers <mathieu.desnoyers@efficios.com> - 2016-03-26 13:30 +0100
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-26 16:30 +0100
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-26 19:50 +0100
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Mathieu Desnoyers <mathieu.desnoyers@efficios.com> - 2016-03-26 23:30 +0100
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-27 03:40 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Mathieu Desnoyers <mathieu.desnoyers@efficios.com> - 2016-03-27 15:50 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-27 17:50 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-27 22:10 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Peter Zijlstra <peterz@infradead.org> - 2016-03-27 22:50 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-27 23:10 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Peter Zijlstra <peterz@infradead.org> - 2016-03-28 08:30 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-28 15:10 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-29 02:30 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-29 15:50 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-30 17:00 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-31 17:50 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-29 02:30 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Mathieu Desnoyers <mathieu.desnoyers@efficios.com> - 2016-03-28 03:50 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Mathieu Desnoyers <mathieu.desnoyers@efficios.com> - 2016-03-28 04:30 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Peter Zijlstra <peterz@infradead.org> - 2016-03-28 08:20 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-28 16:00 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Mathieu Desnoyers <mathieu.desnoyers@efficios.com> - 2016-03-28 16:20 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Peter Zijlstra <peterz@infradead.org> - 2016-03-27 23:00 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-27 23:10 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Peter Zijlstra <peterz@infradead.org> - 2016-03-27 23:00 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-27 23:10 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Peter Zijlstra <peterz@infradead.org> - 2016-03-28 08:40 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-28 15:30 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Mathieu Desnoyers <mathieu.desnoyers@efficios.com> - 2016-03-28 17:10 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-28 18:10 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 Mathieu Desnoyers <mathieu.desnoyers@efficios.com> - 2016-03-28 18:20 +0200
Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2016-03-28 18:40 +0200
Page 1 of 3 [1] 2 3 Next page →
| From | Josh Triplett <josh@joshtriplett.org> |
|---|---|
| Date | 2016-03-18 22:10 +0100 |
| Subject | Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 |
| Message-ID | <re9OG-ey-19@gated-at.bofh.it> |
On Thu, Feb 25, 2016 at 04:56:38PM -0800, Paul E. McKenney wrote:
> On Thu, Feb 25, 2016 at 04:13:11PM +1100, Ross Green wrote:
> > On Wed, Feb 24, 2016 at 8:28 AM, Ross Green <rgkernel@gmail.com> wrote:
> > > On Wed, Feb 24, 2016 at 7:55 AM, Paul E. McKenney
> > > <paulmck@linux.vnet.ibm.com> wrote:
>
> [ . . . ]
>
> > >> Still working on getting decent traces...
>
> And I might have succeeded, see below.
>
> > >>
> > >> Thanx, Paul
> > >>
> > >
> > > G'day all,
> > >
> > > Here is another dmesg output for 4.5-rc5 showing another rcu_preempt stall.
> > > This one appeared after only a day of running. CONFIG_DEBUG_TIMING is
> > > turned on, but can't see any output that shows from this.
> > >
> > > Again testing as before,
> > >
> > > Boot, run a series of small benchmarks, then just let the system be
> > > and idle away.
> > >
> > > I notice in the stack trace there is mention of hrtimer_run_queues and
> > > hrtimer_interrupt.
> > >
> > > Anyway, leave this for a few more eyes to look at.
> > >
> > > Open to any other suggestions of things to test.
> > >
> > > Regards,
> > >
> > > Ross Green
> >
> >
> > G'day Paul,
> >
> > I left the pandaboard running and captured another stall.
> >
> > the attachment is the dmesg output.
> >
> > Again there is no apparent output from any CONFIG_DEBUG_TIMING so I
> > assume there is nothing happening there.
>
> I agree, looks like this is not due to time skew.
>
> > I just saw the updates for 4.6 RCU code.
> > Is the patch in [PATCH tip/core/rcu 04/13] valid here?
>
> I doubt that it will help, but you never know.
>
> > do you want me try the new patch set with this configuration?
>
> Even better would be to try Daniel Wagner's swait patchset. I have
> attached them in UNIX mbox format, or you can get them from the
> -tip tree.
>
> And I -finally- got some tracing that -might- be useful. The dmesg, all
> 67MB of it, is here:
>
> http://www.rdrop.com/~paulmck/submission/console.2016.02.23a.log
>
> This failure mode is less likely to happen, and looks a bit different
> than the ones that I was seeing before enabling tracing. Then, an
> additional wakeup would actually wake the task up. In contrast, with
> tracing enabled, the RCU grace-period kthread goes into "teenager mode",
> refusing to wake up despite repeated attempts. However, this might
> be a side-effect of the ftrace dump.
>
> On line 525,132, we see that the rcu_preempt grace-period kthread has
> been starved for 1,188,154 jiffies, or about 20 minutes. This seems
> unlikely... The kthread is waiting for no more than a three-jiffy
> timeout ("RCU_GP_WAIT_FQS(3)") and is in TASK_INTERRUPTIBLE state
> ("0x1").
We're seeing a similar stall (~60 seconds) on an x86 development system
here. Any luck tracking down the cause of this? If not, any
suggestions for traces that might be helpful?
- Josh Triplett
[toc] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-03-19 01:00 +0100 |
| Message-ID | <rectb-46A-1@gated-at.bofh.it> |
| In reply to | #1360929 |
On Fri, Mar 18, 2016 at 02:00:11PM -0700, Josh Triplett wrote:
> On Thu, Feb 25, 2016 at 04:56:38PM -0800, Paul E. McKenney wrote:
> > On Thu, Feb 25, 2016 at 04:13:11PM +1100, Ross Green wrote:
> > > On Wed, Feb 24, 2016 at 8:28 AM, Ross Green <rgkernel@gmail.com> wrote:
> > > > On Wed, Feb 24, 2016 at 7:55 AM, Paul E. McKenney
> > > > <paulmck@linux.vnet.ibm.com> wrote:
> >
> > [ . . . ]
> >
> > > >> Still working on getting decent traces...
> >
> > And I might have succeeded, see below.
> >
> > > >>
> > > >> Thanx, Paul
> > > >>
> > > >
> > > > G'day all,
> > > >
> > > > Here is another dmesg output for 4.5-rc5 showing another rcu_preempt stall.
> > > > This one appeared after only a day of running. CONFIG_DEBUG_TIMING is
> > > > turned on, but can't see any output that shows from this.
> > > >
> > > > Again testing as before,
> > > >
> > > > Boot, run a series of small benchmarks, then just let the system be
> > > > and idle away.
> > > >
> > > > I notice in the stack trace there is mention of hrtimer_run_queues and
> > > > hrtimer_interrupt.
> > > >
> > > > Anyway, leave this for a few more eyes to look at.
> > > >
> > > > Open to any other suggestions of things to test.
> > > >
> > > > Regards,
> > > >
> > > > Ross Green
> > >
> > >
> > > G'day Paul,
> > >
> > > I left the pandaboard running and captured another stall.
> > >
> > > the attachment is the dmesg output.
> > >
> > > Again there is no apparent output from any CONFIG_DEBUG_TIMING so I
> > > assume there is nothing happening there.
> >
> > I agree, looks like this is not due to time skew.
> >
> > > I just saw the updates for 4.6 RCU code.
> > > Is the patch in [PATCH tip/core/rcu 04/13] valid here?
> >
> > I doubt that it will help, but you never know.
> >
> > > do you want me try the new patch set with this configuration?
> >
> > Even better would be to try Daniel Wagner's swait patchset. I have
> > attached them in UNIX mbox format, or you can get them from the
> > -tip tree.
> >
> > And I -finally- got some tracing that -might- be useful. The dmesg, all
> > 67MB of it, is here:
> >
> > http://www.rdrop.com/~paulmck/submission/console.2016.02.23a.log
> >
> > This failure mode is less likely to happen, and looks a bit different
> > than the ones that I was seeing before enabling tracing. Then, an
> > additional wakeup would actually wake the task up. In contrast, with
> > tracing enabled, the RCU grace-period kthread goes into "teenager mode",
> > refusing to wake up despite repeated attempts. However, this might
> > be a side-effect of the ftrace dump.
> >
> > On line 525,132, we see that the rcu_preempt grace-period kthread has
> > been starved for 1,188,154 jiffies, or about 20 minutes. This seems
> > unlikely... The kthread is waiting for no more than a three-jiffy
> > timeout ("RCU_GP_WAIT_FQS(3)") and is in TASK_INTERRUPTIBLE state
> > ("0x1").
>
> We're seeing a similar stall (~60 seconds) on an x86 development system
> here. Any luck tracking down the cause of this? If not, any
> suggestions for traces that might be helpful?
The dmesg containing the stall, the kernel version, and the .config would
be helpful! Working on a torture test specific to this bug...
Thanx, Paul
[toc] | [prev] | [next] | [standalone]
| From | Jacob Pan <jacob.jun.pan@linux.intel.com> |
|---|---|
| Date | 2016-03-21 17:30 +0100 |
| Message-ID | <rfaSm-8fz-9@gated-at.bofh.it> |
| In reply to | #1361013 |
On Fri, 18 Mar 2016 16:56:41 -0700
"Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> On Fri, Mar 18, 2016 at 02:00:11PM -0700, Josh Triplett wrote:
> > On Thu, Feb 25, 2016 at 04:56:38PM -0800, Paul E. McKenney wrote:
> > > On Thu, Feb 25, 2016 at 04:13:11PM +1100, Ross Green wrote:
> > > > On Wed, Feb 24, 2016 at 8:28 AM, Ross Green
> > > > <rgkernel@gmail.com> wrote:
> > > > > On Wed, Feb 24, 2016 at 7:55 AM, Paul E. McKenney
> > > > > <paulmck@linux.vnet.ibm.com> wrote:
> > >
> > > [ . . . ]
> > >
> > > > >> Still working on getting decent traces...
> > >
> > > And I might have succeeded, see below.
> > >
> > > > >>
> > > > >> Thanx,
> > > > >> Paul
> > > > >>
> > > > >
> > > > > G'day all,
> > > > >
> > > > > Here is another dmesg output for 4.5-rc5 showing another
> > > > > rcu_preempt stall. This one appeared after only a day of
> > > > > running. CONFIG_DEBUG_TIMING is turned on, but can't see any
> > > > > output that shows from this.
> > > > >
> > > > > Again testing as before,
> > > > >
> > > > > Boot, run a series of small benchmarks, then just let the
> > > > > system be and idle away.
> > > > >
> > > > > I notice in the stack trace there is mention of
> > > > > hrtimer_run_queues and hrtimer_interrupt.
> > > > >
> > > > > Anyway, leave this for a few more eyes to look at.
> > > > >
> > > > > Open to any other suggestions of things to test.
> > > > >
> > > > > Regards,
> > > > >
> > > > > Ross Green
> > > >
> > > >
> > > > G'day Paul,
> > > >
> > > > I left the pandaboard running and captured another stall.
> > > >
> > > > the attachment is the dmesg output.
> > > >
> > > > Again there is no apparent output from any CONFIG_DEBUG_TIMING
> > > > so I assume there is nothing happening there.
> > >
> > > I agree, looks like this is not due to time skew.
> > >
> > > > I just saw the updates for 4.6 RCU code.
> > > > Is the patch in [PATCH tip/core/rcu 04/13] valid here?
> > >
> > > I doubt that it will help, but you never know.
> > >
> > > > do you want me try the new patch set with this configuration?
> > >
> > > Even better would be to try Daniel Wagner's swait patchset. I
> > > have attached them in UNIX mbox format, or you can get them from
> > > the -tip tree.
> > >
> > > And I -finally- got some tracing that -might- be useful. The
> > > dmesg, all 67MB of it, is here:
> > >
> > > http://www.rdrop.com/~paulmck/submission/console.2016.02.23a.log
> > >
> > > This failure mode is less likely to happen, and looks a bit
> > > different than the ones that I was seeing before enabling
> > > tracing. Then, an additional wakeup would actually wake the task
> > > up. In contrast, with tracing enabled, the RCU grace-period
> > > kthread goes into "teenager mode", refusing to wake up despite
> > > repeated attempts. However, this might be a side-effect of the
> > > ftrace dump.
> > >
> > > On line 525,132, we see that the rcu_preempt grace-period kthread
> > > has been starved for 1,188,154 jiffies, or about 20 minutes.
> > > This seems unlikely... The kthread is waiting for no more than a
> > > three-jiffy timeout ("RCU_GP_WAIT_FQS(3)") and is in
> > > TASK_INTERRUPTIBLE state ("0x1").
> >
> > We're seeing a similar stall (~60 seconds) on an x86 development
> > system here. Any luck tracking down the cause of this? If not, any
> > suggestions for traces that might be helpful?
>
> The dmesg containing the stall, the kernel version, and the .config
> would be helpful! Working on a torture test specific to this bug...
>
> Thanx, Paul
>
+Reinette, she has the system that can reproduce the issue. I
believe she is having some other problems with it at the moment. But
the .config should be available. Version is v4.5.
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-03-21 18:30 +0100 |
| Message-ID | <rfbOq-qS-13@gated-at.bofh.it> |
| In reply to | #1361976 |
On Mon, Mar 21, 2016 at 09:22:30AM -0700, Jacob Pan wrote: > On Fri, 18 Mar 2016 16:56:41 -0700 > "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote: > > On Fri, Mar 18, 2016 at 02:00:11PM -0700, Josh Triplett wrote: > > > On Thu, Feb 25, 2016 at 04:56:38PM -0800, Paul E. McKenney wrote: [ . . . ] > > > We're seeing a similar stall (~60 seconds) on an x86 development > > > system here. Any luck tracking down the cause of this? If not, any > > > suggestions for traces that might be helpful? > > > > The dmesg containing the stall, the kernel version, and the .config > > would be helpful! Working on a torture test specific to this bug... > > > > Thanx, Paul > > > +Reinette, she has the system that can reproduce the issue. I > believe she is having some other problems with it at the moment. But > the .config should be available. Version is v4.5. A couple of additional questions: 1. Is the test running on bare metal or virtualized? If the latter, what is the host? 2. Does the workload involve CPU hotplug? 3. Are you seeing things like this in dmesg? "rcu_preempt kthread starved for 21033 jiffies" "rcu_sched kthread starved for 32103 jiffies" "rcu_bh kthread starved for 84031 jiffies" If not, you are probably facing some other bug, and should proceed debugging as described in Documentation/RCU/stallwarn.txt. Thanx, Paul
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-03-22 18:50 +0100 |
| Message-ID | <rfyBk-82p-17@gated-at.bofh.it> |
| In reply to | #1362026 |
On Tue, Mar 22, 2016 at 04:35:32PM +0000, Chatre, Reinette wrote:
> Hi Paul,
Hello, Reinette!
> On 2016-03-21, Paul E. McKenney wrote:
> > On Mon, Mar 21, 2016 at 09:22:30AM -0700, Jacob Pan wrote:
> >> On Fri, 18 Mar 2016 16:56:41 -0700
> >> "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> >>> On Fri, Mar 18, 2016 at 02:00:11PM -0700, Josh Triplett wrote:
> >>>> On Thu, Feb 25, 2016 at 04:56:38PM -0800, Paul E. McKenney wrote:
> >
> > [ . . . ]
> >
> >>>> We're seeing a similar stall (~60 seconds) on an x86 development
> >>>> system here. Any luck tracking down the cause of this? If not, any
> >>>> suggestions for traces that might be helpful?
> >>>
> >>> The dmesg containing the stall, the kernel version, and the .config
> >>> would be helpful! Working on a torture test specific to this bug...
And thank you for the .config. Your kenrle version looks to be 4.5.0.
> >> +Reinette, she has the system that can reproduce the issue. I
> >> believe she is having some other problems with it at the moment. But
> >> the .config should be available. Version is v4.5.
> >
> > A couple of additional questions:
> >
> > 1. Is the test running on bare metal or virtualized? If the
> > latter, what is the host?
>
> Bare metal.
OK, you are ahead of me. Mine is virtualized.
> > 2. Does the workload involve CPU hotplug?
>
> No.
Again, you are ahead of me. Mine makes extremely heavy use of CPU hotplug.
> > 3. Are you seeing things like this in dmesg?
> >
> > "rcu_preempt kthread starved for 21033 jiffies"
> > "rcu_sched kthread starved for 32103 jiffies"
> > "rcu_bh kthread starved for 84031 jiffies"
> >
> > If not, you are probably facing some other bug, and should
> > proceed debugging as described in Documentation/RCU/stallwarn.txt.
>
> Below is a sample of what I see as captured with v4.5. The kernel configuration is attached.
>
> [ 135.456197] INFO: rcu_preempt detected stalls on CPUs/tasks:
> [ 135.457729] 3-...: (0 ticks this GP) idle=722/0/0 softirq=5532/5532 fqs=0
> [ 135.459604] (detected by 2, t=60004 jiffies, g=2105, c=2104, q=165)
> [ 135.461318] Task dump for CPU 3:
> [ 135.461321] swapper/3 R running task 0 0 1 0x00200000
> [ 135.461325] 00000078560040e5 ffff88017846fed0 ffffffff818af2cc ffff880100000000
> [ 135.461330] 0000000600000003 ffff880178470000 ffff880072f32200 ffffffff822dcec0
> [ 135.461334] ffff88017846c000 ffff88017846c000 ffff88017846fee0 ffffffff818af517
> [ 135.461338] Call Trace:
> [ 135.461345] [<ffffffff818af2cc>] ? cpuidle_enter_state+0xfc/0x310
> [ 135.461349] [<ffffffff818af517>] ? cpuidle_enter+0x17/0x20
> [ 135.461353] [<ffffffff811515aa>] ? call_cpuidle+0x2a/0x40
> [ 135.461355] [<ffffffff8115197d>] ? cpu_startup_entry+0x28d/0x360
> [ 135.461360] [<ffffffff8108c874>] ? start_secondary+0x114/0x140
> [ 135.461365] rcu_preempt kthread starved for 60004 jiffies! g2105 c2104 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1
And yes, it looks like you are seeing the same bug that I am tracing.
The kthread is blocked on a schedule_timeout_interruptible(). Given
default configuration, this would have a three-jiffy timeout.
You set CONFIG_RCU_CPU_STALL_TIMEOUT=60, which matches the 60004 jiffies
above. Is that value due to a distro setting or something? Mainline
uses CONFIG_RCU_CPU_STALL_TIMEOUT=21.
> [ 135.463965] rcu_preempt S ffff88017844fd68 0 7 2 0x00000000
> [ 135.463969] ffff88017844fd68 ffff88017dd8cc80 ffff880177ff0000 ffff880178443b80
> [ 135.463973] ffff880178450000 ffff88017844fda0 ffff88017dd8cc80 ffff88017dd8cc80
> [ 135.463977] 0000000000000003 ffff88017844fd80 ffffffff81ab031f 0000000100031504
> [ 135.463981] Call Trace:
> [ 135.463986] [<ffffffff81ab031f>] schedule+0x3f/0xa0
> [ 135.463989] [<ffffffff81ab42d7>] schedule_timeout+0x127/0x270
> [ 135.463993] [<ffffffff81171a50>] ? detach_if_pending+0x120/0x120
> [ 135.463997] [<ffffffff8116da5d>] rcu_gp_kthread+0x6bd/0xa30
> [ 135.464000] [<ffffffff81151390>] ? wake_atomic_t_function+0x70/0x70
> [ 135.464003] [<ffffffff8116d3a0>] ? force_qs_rnp+0x1b0/0x1b0
> [ 135.464006] [<ffffffff8112f846>] kthread+0xe6/0x100
> [ 135.464009] [<ffffffff8112f760>] ? kthread_worker_fn+0x190/0x190
> [ 135.464012] [<ffffffff81ab5c0f>] ret_from_fork+0x3f/0x70
> [ 135.464015] [<ffffffff8112f760>] ? kthread_worker_fn+0x190/0x190
How long does it take to reproduce this? If it reproduces in minutes
or hours, could you please boot with the following on the kernel command
line and dump the trace buffer shortly after the stall?
ftrace trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi
If dumping manually shortly after the stall is at all non-trivial
(for example, if your reproduction time is many minute or hours),
I can supply some patches that automate this. Or you can pick
them up from -rcu:
git://git.kernel.org/pub/scm/linux/kernel/git/paulmck/linux-rcu.git
Branch rcu/dev has these patches (and much else besides).
Thanx, Paul
PS: In case you are curious, when I enable those tracepoints, it
shows me that the timer is firing every three jiffies, as it
should, but that something happens between the sched_waking
and the IPI handler that should actually do the wakeup.
However, adding the traces significantly slows reproduction,
so I am writing a stress test specific to this bug to try to
speed things up, hopefully allowing more tracing to be added
while still retaining non-geologic reproduction times.
[toc] | [prev] | [next] | [standalone]
| From | "Chatre, Reinette" <reinette.chatre@intel.com> |
|---|---|
| Date | 2016-03-22 22:10 +0100 |
| Message-ID | <rfBIS-1Lk-35@gated-at.bofh.it> |
| In reply to | #1362878 |
Hi Paul, On 2016-03-22, Paul E. McKenney wrote: > On Tue, Mar 22, 2016 at 04:35:32PM +0000, Chatre, Reinette wrote: >> On 2016-03-21, Paul E. McKenney wrote: >>> On Mon, Mar 21, 2016 at 09:22:30AM -0700, Jacob Pan wrote: >>>> On Fri, 18 Mar 2016 16:56:41 -0700 >>>> "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote: >>>>> On Fri, Mar 18, 2016 at 02:00:11PM -0700, Josh Triplett wrote: >>>>>> On Thu, Feb 25, 2016 at 04:56:38PM -0800, Paul E. McKenney wrote: >>> >>> [ . . . ] >>> >>>>>> We're seeing a similar stall (~60 seconds) on an x86 development >>>>>> system here. Any luck tracking down the cause of this? If not, any >>>>>> suggestions for traces that might be helpful? >>>>> >>>>> The dmesg containing the stall, the kernel version, and the .config >>>>> would be helpful! Working on a torture test specific to this bug... > > And thank you for the .config. Your kenrle version looks to be 4.5.0. > >>>> +Reinette, she has the system that can reproduce the issue. I >>>> believe she is having some other problems with it at the moment. But >>>> the .config should be available. Version is v4.5. >>> >>> A couple of additional questions: >>> >>> 1. Is the test running on bare metal or virtualized? If the >>> latter, what is the host? >> >> Bare metal. > > OK, you are ahead of me. Mine is virtualized. > >>> 2. Does the workload involve CPU hotplug? >> >> No. > > Again, you are ahead of me. Mine makes extremely heavy use of CPU hotplug. > >>> 3. Are you seeing things like this in dmesg? >>> >>> "rcu_preempt kthread starved for 21033 jiffies" >>> "rcu_sched kthread starved for 32103 jiffies" >>> "rcu_bh kthread starved for 84031 jiffies" >>> >>> If not, you are probably facing some other bug, and should >>> proceed debugging as described in Documentation/RCU/stallwarn.txt. >> >> Below is a sample of what I see as captured with v4.5. The kernel >> configuration is attached. >> >> [ 135.456197] INFO: rcu_preempt detected stalls on CPUs/tasks: [ >> 135.457729] 3-...: (0 ticks this GP) idle=722/0/0 softirq=5532/5532 >> fqs=0 [ 135.459604] (detected by 2, t=60004 jiffies, g=2105, c=2104, >> q=165) [ 135.461318] Task dump for CPU 3: [ 135.461321] swapper/3 >> R running task 0 0 1 0x00200000 [ 135.461325] >> 00000078560040e5 ffff88017846fed0 ffffffff818af2cc ffff880100000000 [ >> 135.461330] 0000000600000003 ffff880178470000 ffff880072f32200 >> ffffffff822dcec0 [ 135.461334] ffff88017846c000 ffff88017846c000 >> ffff88017846fee0 ffffffff818af517 [ 135.461338] Call Trace: [ >> 135.461345] [<ffffffff818af2cc>] ? cpuidle_enter_state+0xfc/0x310 [ >> 135.461349] [<ffffffff818af517>] ? cpuidle_enter+0x17/0x20 [ >> 135.461353] [<ffffffff811515aa>] ? call_cpuidle+0x2a/0x40 [ >> 135.461355] [<ffffffff8115197d>] ? cpu_startup_entry+0x28d/0x360 [ >> 135.461360] [<ffffffff8108c874>] ? start_secondary+0x114/0x140 [ >> 135.461365] rcu_preempt kthread starved for 60004 jiffies! g2105 c2104 > f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 > > And yes, it looks like you are seeing the same bug that I am tracing. > > The kthread is blocked on a schedule_timeout_interruptible(). Given > default configuration, this would have a three-jiffy timeout. > > You set CONFIG_RCU_CPU_STALL_TIMEOUT=60, which matches the 60004 jiffies > above. Is that value due to a distro setting or something? Mainline > uses CONFIG_RCU_CPU_STALL_TIMEOUT=21. Indeed ... this value originated from a Fedora configuration. >> [ 135.463965] rcu_preempt S ffff88017844fd68 0 7 2 >> 0x00000000 [ 135.463969] ffff88017844fd68 ffff88017dd8cc80 >> ffff880177ff0000 ffff880178443b80 [ 135.463973] ffff880178450000 >> ffff88017844fda0 ffff88017dd8cc80 ffff88017dd8cc80 [ 135.463977] >> 0000000000000003 ffff88017844fd80 ffffffff81ab031f 0000000100031504 [ >> 135.463981] Call Trace: [ 135.463986] [<ffffffff81ab031f>] >> schedule+0x3f/0xa0 [ 135.463989] [<ffffffff81ab42d7>] >> schedule_timeout+0x127/0x270 [ 135.463993] [<ffffffff81171a50>] ? >> detach_if_pending+0x120/0x120 [ 135.463997] [<ffffffff8116da5d>] >> rcu_gp_kthread+0x6bd/0xa30 [ 135.464000] [<ffffffff81151390>] ? >> wake_atomic_t_function+0x70/0x70 [ 135.464003] [<ffffffff8116d3a0>] ? >> force_qs_rnp+0x1b0/0x1b0 [ 135.464006] [<ffffffff8112f846>] >> kthread+0xe6/0x100 [ 135.464009] [<ffffffff8112f760>] ? >> kthread_worker_fn+0x190/0x190 [ 135.464012] [<ffffffff81ab5c0f>] >> ret_from_fork+0x3f/0x70 [ 135.464015] [<ffffffff8112f760>] ? >> kthread_worker_fn+0x190/0x190 > > How long does it take to reproduce this? If it reproduces in minutes > or hours, could you please boot with the following on the kernel command > line and dump the trace buffer shortly after the stall? > > ftrace trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi The trace I provided above appeared after a few minutes and not again. On previous occasions I had to wait a few hours. I tried running with the above added to the kernel command line but I have not seen the trace yet. I will leave the system overnight but then may risk not capturing the data you need so ... > If dumping manually shortly after the stall is at all non-trivial > (for example, if your reproduction time is many minute or hours), > I can supply some patches that automate this. Or you can pick > them up from -rcu: ... could you please point me to the patches you refer to? Or would you like me to try with the entire kernel from rcu/dev? > > git://git.kernel.org/pub/scm/linux/kernel/git/paulmck/linux-rcu.git > > Branch rcu/dev has these patches (and much else besides). > > Thanx, Paul > > PS: In case you are curious, when I enable those tracepoints, it > shows me that the timer is firing every three jiffies, as it > should, but that something happens between the sched_waking > and the IPI handler that should actually do the wakeup. > However, adding the traces significantly slows reproduction, > so I am writing a stress test specific to this bug to try to > speed things up, hopefully allowing more tracing to be added > while still retaining non-geologic reproduction times. Thank you very much for these details. Reinette
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-03-22 22:20 +0100 |
| Message-ID | <rfBSy-1PB-3@gated-at.bofh.it> |
| In reply to | #1362984 |
On Tue, Mar 22, 2016 at 09:04:47PM +0000, Chatre, Reinette wrote: > Hi Paul, > > On 2016-03-22, Paul E. McKenney wrote: > > On Tue, Mar 22, 2016 at 04:35:32PM +0000, Chatre, Reinette wrote: > >> On 2016-03-21, Paul E. McKenney wrote: > >>> On Mon, Mar 21, 2016 at 09:22:30AM -0700, Jacob Pan wrote: > >>>> On Fri, 18 Mar 2016 16:56:41 -0700 > >>>> "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote: > >>>>> On Fri, Mar 18, 2016 at 02:00:11PM -0700, Josh Triplett wrote: > >>>>>> On Thu, Feb 25, 2016 at 04:56:38PM -0800, Paul E. McKenney wrote: > >>> > >>> [ . . . ] > >>> > >>>>>> We're seeing a similar stall (~60 seconds) on an x86 development > >>>>>> system here. Any luck tracking down the cause of this? If not, any > >>>>>> suggestions for traces that might be helpful? > >>>>> > >>>>> The dmesg containing the stall, the kernel version, and the .config > >>>>> would be helpful! Working on a torture test specific to this bug... > > > > And thank you for the .config. Your kenrle version looks to be 4.5.0. > > > >>>> +Reinette, she has the system that can reproduce the issue. I > >>>> believe she is having some other problems with it at the moment. But > >>>> the .config should be available. Version is v4.5. > >>> > >>> A couple of additional questions: > >>> > >>> 1. Is the test running on bare metal or virtualized? If the > >>> latter, what is the host? > >> > >> Bare metal. > > > > OK, you are ahead of me. Mine is virtualized. > > > >>> 2. Does the workload involve CPU hotplug? > >> > >> No. > > > > Again, you are ahead of me. Mine makes extremely heavy use of CPU hotplug. > > > >>> 3. Are you seeing things like this in dmesg? > >>> > >>> "rcu_preempt kthread starved for 21033 jiffies" > >>> "rcu_sched kthread starved for 32103 jiffies" > >>> "rcu_bh kthread starved for 84031 jiffies" > >>> > >>> If not, you are probably facing some other bug, and should > >>> proceed debugging as described in Documentation/RCU/stallwarn.txt. > >> > >> Below is a sample of what I see as captured with v4.5. The kernel > >> configuration is attached. > >> > >> [ 135.456197] INFO: rcu_preempt detected stalls on CPUs/tasks: [ > >> 135.457729] 3-...: (0 ticks this GP) idle=722/0/0 softirq=5532/5532 > >> fqs=0 [ 135.459604] (detected by 2, t=60004 jiffies, g=2105, c=2104, > >> q=165) [ 135.461318] Task dump for CPU 3: [ 135.461321] swapper/3 > >> R running task 0 0 1 0x00200000 [ 135.461325] > >> 00000078560040e5 ffff88017846fed0 ffffffff818af2cc ffff880100000000 [ > >> 135.461330] 0000000600000003 ffff880178470000 ffff880072f32200 > >> ffffffff822dcec0 [ 135.461334] ffff88017846c000 ffff88017846c000 > >> ffff88017846fee0 ffffffff818af517 [ 135.461338] Call Trace: [ > >> 135.461345] [<ffffffff818af2cc>] ? cpuidle_enter_state+0xfc/0x310 [ > >> 135.461349] [<ffffffff818af517>] ? cpuidle_enter+0x17/0x20 [ > >> 135.461353] [<ffffffff811515aa>] ? call_cpuidle+0x2a/0x40 [ > >> 135.461355] [<ffffffff8115197d>] ? cpu_startup_entry+0x28d/0x360 [ > >> 135.461360] [<ffffffff8108c874>] ? start_secondary+0x114/0x140 [ > >> 135.461365] rcu_preempt kthread starved for 60004 jiffies! g2105 c2104 > > f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 > > > > And yes, it looks like you are seeing the same bug that I am tracing. > > > > The kthread is blocked on a schedule_timeout_interruptible(). Given > > default configuration, this would have a three-jiffy timeout. > > > > You set CONFIG_RCU_CPU_STALL_TIMEOUT=60, which matches the 60004 jiffies > > above. Is that value due to a distro setting or something? Mainline > > uses CONFIG_RCU_CPU_STALL_TIMEOUT=21. > > Indeed ... this value originated from a Fedora configuration. OK. Setting it shorter might (or might not) make it reproduce more quickly. This can be set at boot time via rcupdate.rcu_cpu_stall_timeout. Or at compile time via CONFIG_RCU_CPU_STALL_TIMEOUT. > >> [ 135.463965] rcu_preempt S ffff88017844fd68 0 7 2 > >> 0x00000000 [ 135.463969] ffff88017844fd68 ffff88017dd8cc80 > >> ffff880177ff0000 ffff880178443b80 [ 135.463973] ffff880178450000 > >> ffff88017844fda0 ffff88017dd8cc80 ffff88017dd8cc80 [ 135.463977] > >> 0000000000000003 ffff88017844fd80 ffffffff81ab031f 0000000100031504 [ > >> 135.463981] Call Trace: [ 135.463986] [<ffffffff81ab031f>] > >> schedule+0x3f/0xa0 [ 135.463989] [<ffffffff81ab42d7>] > >> schedule_timeout+0x127/0x270 [ 135.463993] [<ffffffff81171a50>] ? > >> detach_if_pending+0x120/0x120 [ 135.463997] [<ffffffff8116da5d>] > >> rcu_gp_kthread+0x6bd/0xa30 [ 135.464000] [<ffffffff81151390>] ? > >> wake_atomic_t_function+0x70/0x70 [ 135.464003] [<ffffffff8116d3a0>] ? > >> force_qs_rnp+0x1b0/0x1b0 [ 135.464006] [<ffffffff8112f846>] > >> kthread+0xe6/0x100 [ 135.464009] [<ffffffff8112f760>] ? > >> kthread_worker_fn+0x190/0x190 [ 135.464012] [<ffffffff81ab5c0f>] > >> ret_from_fork+0x3f/0x70 [ 135.464015] [<ffffffff8112f760>] ? > >> kthread_worker_fn+0x190/0x190 > > > > How long does it take to reproduce this? If it reproduces in minutes > > or hours, could you please boot with the following on the kernel command > > line and dump the trace buffer shortly after the stall? > > > > ftrace trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi > > The trace I provided above appeared after a few minutes and not again. On previous occasions I had to wait a few hours. I tried running with the above added to the kernel command line but I have not seen the trace yet. I will leave the system overnight but then may risk not capturing the data you need so ... Fair enough... Sounds like you might have the same geologic-time problem that I do when adding tracing. :-/ > > If dumping manually shortly after the stall is at all non-trivial > > (for example, if your reproduction time is many minute or hours), > > I can supply some patches that automate this. Or you can pick > > them up from -rcu: > > ... could you please point me to the patches you refer to? Or would you like me to try with the entire kernel from rcu/dev? 2dc92e2a86b9 (rcu: Awaken grace-period kthread if too long since FQS) c3fd2095d015 (rcu: Dump ftrace buffer when kicking grace-period kthread) There might be other dependencies, but these are the two that you need. Thanx, Paul > > git://git.kernel.org/pub/scm/linux/kernel/git/paulmck/linux-rcu.git > > > > Branch rcu/dev has these patches (and much else besides). > > > > Thanx, Paul > > > > PS: In case you are curious, when I enable those tracepoints, it > > shows me that the timer is firing every three jiffies, as it > > should, but that something happens between the sched_waking > > and the IPI handler that should actually do the wakeup. > > However, adding the traces significantly slows reproduction, > > so I am writing a stress test specific to this bug to try to > > speed things up, hopefully allowing more tracing to be added > > while still retaining non-geologic reproduction times. > > Thank you very much for these details. > > Reinette >
[toc] | [prev] | [next] | [standalone]
| From | "Chatre, Reinette" <reinette.chatre@intel.com> |
|---|---|
| Date | 2016-03-23 18:20 +0100 |
| Message-ID | <rfUBQ-6HY-11@gated-at.bofh.it> |
| In reply to | #1363000 |
Hi Paul, On 2016-03-22, Paul E. McKenney wrote: > On Tue, Mar 22, 2016 at 09:04:47PM +0000, Chatre, Reinette wrote: >> On 2016-03-22, Paul E. McKenney wrote: >>> You set CONFIG_RCU_CPU_STALL_TIMEOUT=60, which matches the 60004 >>> jiffies above. Is that value due to a distro setting or something? >>> Mainline uses CONFIG_RCU_CPU_STALL_TIMEOUT=21. >> >> Indeed ... this value originated from a Fedora configuration. > > OK. Setting it shorter might (or might not) make it reproduce more > quickly. This can be set at boot time via rcupdate.rcu_cpu_stall_timeout. > Or at compile time via CONFIG_RCU_CPU_STALL_TIMEOUT. I kept the original configuration and seem to be able to reproduce with that. >>> If dumping manually shortly after the stall is at all non-trivial >>> (for example, if your reproduction time is many minute or hours), >>> I can supply some patches that automate this. Or you can pick >>> them up from -rcu: >> >> ... could you please point me to the patches you refer to? Or would you like > me to try with the entire kernel from rcu/dev? > > 2dc92e2a86b9 (rcu: Awaken grace-period kthread if too long since FQS) > c3fd2095d015 (rcu: Dump ftrace buffer when kicking grace-period kthread) > > There might be other dependencies, but these are the two that you need. I did not look closely at the patches when I applied them and because of that missed that they need a kernel parameter to be activated. After leaving the system idle overnight with these patches the stalls occurred but without the parameter I did not capture the data you need. I will try again tonight. Below are the traces from last night just in case they have value to you. [10154.635318] INFO: rcu_preempt detected stalls on CPUs/tasks: [10154.639218] 1-...: (0 ticks this GP) idle=c4e/0/0 softirq=99936/99936 fqs=0 [10154.643497] (detected by 0, t=60005 jiffies, g=24190, c=24189, q=79) [10154.647596] Task dump for CPU 1: [10154.650818] swapper/1 R running task 0 0 1 0x00200000 [10154.655052] 00002656bf74de5e ffff8801785cfed0 ffffffff818af34c ffff880100000000 [10154.659349] 0000000600000003 ffff8801785d0000 ffff880072f0bc00 ffffffff822dcf80 [10154.663636] ffff8801785cc000 ffff8801785cc000 ffff8801785cfee0 ffffffff818af597 [10154.667916] Call Trace: [10154.670845] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 [10154.674802] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 [10154.678564] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 [10154.682295] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 [10154.686187] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 [10154.690040] rcu_preempt kthread starved for 60005 jiffies! g24190 c24189 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 [10154.694944] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 [10154.699062] ffff8801785b7d68 ffff88017dc8cc80 ffff8801785c3b80 ffff8801785abb80 [10154.703275] ffff8801785b8000 ffff8801785b7da0 ffff88017dc8cc80 ffff88017dc8cc80 [10154.707481] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 00000001027e21aa [10154.711692] Call Trace: [10154.714548] [<ffffffff81ab03df>] schedule+0x3f/0xa0 [10154.718075] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 [10154.721832] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 [10154.725659] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 [10154.729379] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 [10154.733235] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 [10154.736854] [<ffffffff8112f856>] kthread+0xe6/0x100 [10154.740267] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 [10154.743980] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 [10154.747511] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 [11348.912706] INFO: rcu_preempt detected stalls on CPUs/tasks: [11348.916346] 2-...: (0 ticks this GP) idle=586/0/0 softirq=133504/133504 fqs=0 [11348.920407] (detected by 3, t=60002 jiffies, g=26799, c=26798, q=72) [11348.924244] Task dump for CPU 2: [11348.927205] swapper/2 R running task 0 0 1 0x00200000 [11348.931178] 00002adc83427a76 ffff8801785d3ed0 ffffffff818af34c ffff880100000000 [11348.935217] 0000000600000003 ffff8801785d4000 ffff880177d01e00 ffffffff822dcf80 [11348.939237] ffff8801785d0000 ffff8801785d0000 ffff8801785d3ee0 ffffffff818af597 [11348.943252] Call Trace: [11348.945921] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 [11348.949615] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 [11348.953115] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 [11348.956584] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 [11348.960215] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 [11348.963808] rcu_preempt kthread starved for 60002 jiffies! g26799 c26798 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 [11348.968452] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 [11348.972309] ffff8801785b7d68 ffff88017dd0cc80 ffff8801785c5940 ffff8801785abb80 [11348.976266] ffff8801785b8000 ffff8801785b7da0 ffff88017dd0cc80 ffff88017dd0cc80 [11348.980207] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 0000000102c9d45e [11348.984142] Call Trace: [11348.986714] [<ffffffff81ab03df>] schedule+0x3f/0xa0 [11348.989974] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 [11348.993453] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 [11348.997000] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 [11349.000431] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 [11349.004040] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 [11349.007449] [<ffffffff8112f856>] kthread+0xe6/0x100 [11349.010676] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 [11349.014216] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 [11349.017568] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 [11790.539207] INFO: rcu_preempt detected stalls on CPUs/tasks: [11790.542652] 2-...: (0 ticks this GP) idle=944/0/0 softirq=133668/133668 fqs=0 [11790.546505] (detected by 3, t=60003 jiffies, g=27589, c=27588, q=72) [11790.550124] Task dump for CPU 2: [11790.552871] swapper/2 R running task 0 0 1 0x00200000 [11790.556678] 00002c8422fed65e ffff8801785d3ed0 ffffffff818af34c ffff880100000000 [11790.560580] 0000000600000003 ffff8801785d4000 ffff880177d01e00 ffffffff822dcf80 [11790.564485] ffff8801785d0000 ffff8801785d0000 ffff8801785d3ee0 ffffffff818af597 [11790.568389] Call Trace: [11790.570942] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 [11790.574525] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 [11790.577934] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 [11790.581311] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 [11790.584853] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 [11790.588350] rcu_preempt kthread starved for 60003 jiffies! g27589 c27588 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 [11790.592945] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 [11790.596808] ffff8801785b7d68 ffff88017dd0cc80 ffff8801785c5940 ffff8801785abb80 [11790.600751] ffff8801785b8000 ffff8801785b7da0 ffff88017dd0cc80 ffff88017dd0cc80 [11790.604688] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 0000000102e5d253 [11790.608635] Call Trace: [11790.611220] [<ffffffff81ab03df>] schedule+0x3f/0xa0 [11790.614480] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 [11790.617971] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 [11790.621530] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 [11790.624972] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 [11790.628558] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 [11790.631904] [<ffffffff8112f856>] kthread+0xe6/0x100 [11790.635043] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 [11790.638485] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 [11790.641745] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 [11820.319166] INFO: rcu_preempt detected stalls on CPUs/tasks: [11820.322523] 2-...: (0 ticks this GP) idle=9b4/0/0 softirq=133674/133674 fqs=0 [11820.326301] (detected by 3, t=60002 jiffies, g=27620, c=27619, q=64) [11820.329856] Task dump for CPU 2: [11820.332536] swapper/2 R running task 0 0 1 0x00200000 [11820.336228] 00002ca4dc6b2bb1 ffff8801785d3ed0 ffffffff818af34c ffff880100000000 [11820.339990] 0000000600000003 ffff8801785d4000 ffff880177d01e00 ffffffff822dcf80 [11820.343749] ffff8801785d0000 ffff8801785d0000 ffff8801785d3ee0 ffffffff818af597 [11820.347483] Call Trace: [11820.349852] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 [11820.353250] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 [11820.356463] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 [11820.359637] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 [11820.362973] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 [11820.366264] rcu_preempt kthread starved for 60002 jiffies! g27620 c27619 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 [11820.370643] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 [11820.374276] ffff8801785b7d68 ffff88017dd0cc80 ffff8801785c5940 ffff8801785abb80 [11820.378026] ffff8801785b8000 ffff8801785b7da0 ffff88017dd0cc80 ffff88017dd0cc80 [11820.381775] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 0000000102e7b58c [11820.385537] Call Trace: [11820.387940] [<ffffffff81ab03df>] schedule+0x3f/0xa0 [11820.391005] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 [11820.394286] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 [11820.397626] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 [11820.400853] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 [11820.404269] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 [11820.407478] [<ffffffff8112f856>] kthread+0xe6/0x100 [11820.410493] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 [11820.413824] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 [11820.416966] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 [11903.292474] INFO: rcu_preempt detected stalls on CPUs/tasks: [11903.295736] 2-...: (0 ticks this GP) idle=bd2/0/0 softirq=133700/133700 fqs=0 [11903.299427] (detected by 3, t=60003 jiffies, g=27759, c=27758, q=277) [11903.302921] Task dump for CPU 2: [11903.305513] swapper/2 R running task 0 0 1 0x00200000 [11903.309164] 00002cf65a063204 ffff8801785d3ed0 ffffffff818af34c ffff880100000000 [11903.312931] 0000000600000003 ffff8801785d4000 ffff880177d01e00 ffffffff822dcf80 [11903.316685] ffff8801785d0000 ffff8801785d0000 ffff8801785d3ee0 ffffffff818af597 [11903.320426] Call Trace: [11903.322802] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 [11903.326199] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 [11903.329416] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 [11903.332591] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 [11903.335931] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 [11903.339226] rcu_preempt kthread starved for 60003 jiffies! g27759 c27758 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 [11903.343607] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 [11903.347246] ffff8801785b7d68 ffff88017dd0cc80 ffff8801785c5940 ffff8801785abb80 [11903.350999] ffff8801785b8000 ffff8801785b7da0 ffff88017dd0cc80 ffff88017dd0cc80 [11903.354750] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 0000000102ecf7e4 [11903.358508] Call Trace: [11903.360909] [<ffffffff81ab03df>] schedule+0x3f/0xa0 [11903.363979] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 [11903.367259] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 [11903.370601] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 [11903.373829] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 [11903.377243] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 [11903.380455] [<ffffffff8112f856>] kthread+0xe6/0x100 [11903.383473] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 [11903.386804] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 [11903.389942] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 [12101.322638] INFO: rcu_preempt detected stalls on CPUs/tasks: [12101.325902] 2-...: (19 GPs behind) idle=880/0/0 softirq=133768/133768 fqs=1 [12101.329542] (detected by 1, t=60004 jiffies, g=28170, c=28169, q=41) [12101.333009] Task dump for CPU 2: [12101.335599] swapper/2 R running task 0 0 1 0x00200000 [12101.339248] 00002db4171b61e1 ffff8801785d3ed0 ffffffff818af34c ffff880100000000 [12101.343008] 0000000600000003 ffff8801785d4000 ffff880177d01e00 ffffffff822dcf80 [12101.346763] ffff8801785d0000 ffff8801785d0000 ffff8801785d3ee0 ffffffff818af597 [12101.350501] Call Trace: [12101.352868] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 [12101.356262] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 [12101.359475] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 [12101.362645] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 [12101.365980] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 [12101.369270] rcu_preempt kthread starved for 60000 jiffies! g28170 c28169 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 [12101.373646] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 [12101.377281] ffff8801785b7d68 ffff88017dd0cc80 ffff8801785c5940 ffff8801785abb80 [12101.381030] ffff8801785b8000 ffff8801785b7da0 ffff88017dd0cc80 ffff88017dd0cc80 [12101.384778] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 0000000102f98533 [12101.388532] Call Trace: [12101.390927] [<ffffffff81ab03df>] schedule+0x3f/0xa0 [12101.393991] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 [12101.397266] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 [12101.400602] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 [12101.403825] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 [12101.407240] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 [12101.410450] [<ffffffff8112f856>] kthread+0xe6/0x100 [12101.413465] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 [12101.416793] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 [12101.419930] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 [12269.411058] INFO: rcu_preempt detected stalls on CPUs/tasks: [12269.414316] 2-...: (27 GPs behind) idle=daa/0/0 softirq=133902/133902 fqs=1 [12269.417947] (detected by 0, t=60003 jiffies, g=28504, c=28503, q=347) [12269.421426] Task dump for CPU 2: [12269.424012] swapper/2 R running task 0 0 1 0x00200000 [12269.427656] 00002e58b5f8d033 ffff8801785d3ed0 ffffffff818af34c ffff880100000000 [12269.431405] 0000000600000003 ffff8801785d4000 ffff880177d01e00 ffffffff822dcf80 [12269.435153] ffff8801785d0000 ffff8801785d0000 ffff8801785d3ee0 ffffffff818af597 [12269.438886] Call Trace: [12269.441252] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 [12269.444638] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 [12269.447850] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 [12269.451014] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 [12269.454348] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 [12269.457634] rcu_preempt kthread starved for 59872 jiffies! g28504 c28503 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 [12269.462008] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 [12269.465636] ffff8801785b7d68 ffff88017dd0cc80 ffff8801785c5940 ffff8801785abb80 [12269.469380] ffff8801785b8000 ffff8801785b7da0 ffff88017dd0cc80 ffff88017dd0cc80 [12269.473121] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 0000000103042d26 [12269.476868] Call Trace: [12269.479262] [<ffffffff81ab03df>] schedule+0x3f/0xa0 [12269.482321] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 [12269.485592] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 [12269.488926] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 [12269.492144] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 [12269.495554] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 [12269.498756] [<ffffffff8112f856>] kthread+0xe6/0x100 [12269.501764] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 [12269.505090] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 [12269.508224] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 [12426.587923] INFO: rcu_preempt detected stalls on CPUs/tasks: [12426.591181] 2-...: (17 GPs behind) idle=15c/0/0 softirq=134033/134034 fqs=1 [12426.594815] (detected by 0, t=60002 jiffies, g=28804, c=28803, q=396) [12426.598296] Task dump for CPU 2: [12426.600881] swapper/2 R running task 0 0 1 0x00200000 [12426.604528] 00002eed4414d5d4 ffff8801785d3ed0 ffffffff818af34c ffff880100000000 [12426.608284] 0000000600000003 ffff8801785d4000 ffff880177d01e00 ffffffff822dcf80 [12426.612030] ffff8801785d0000 ffff8801785d0000 ffff8801785d3ee0 ffffffff818af597 [12426.615762] Call Trace: [12426.618131] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 [12426.621522] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 [12426.624733] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 [12426.627903] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 [12426.631238] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 [12426.634527] rcu_preempt kthread starved for 59998 jiffies! g28804 c28803 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 [12426.638900] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 [12426.642535] ffff8801785b7d68 ffff88017dd0cc80 ffff8801785c5940 ffff8801785abb80 [12426.646285] ffff8801785b8000 ffff8801785b7da0 ffff88017dd0cc80 ffff88017dd0cc80 [12426.650031] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 00000001030e230e [12426.653787] Call Trace: [12426.656186] [<ffffffff81ab03df>] schedule+0x3f/0xa0 [12426.659251] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 [12426.662528] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 [12426.665868] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 [12426.669091] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 [12426.672502] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 [12426.675710] [<ffffffff8112f856>] kthread+0xe6/0x100 [12426.678724] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 [12426.682052] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 [12426.685188] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190
[toc] | [prev] | [next] | [standalone]
| From | "Chatre, Reinette" <reinette.chatre@intel.com> |
|---|---|
| Date | 2016-03-23 19:30 +0100 |
| Message-ID | <rfVHz-7rS-1@gated-at.bofh.it> |
| In reply to | #1363565 |
Hi Paul, On 2016-03-23, Paul E. McKenney wrote: > Please boot with the following parameters: > > rcu_tree.rcu_kick_kthreads ftrace > trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi > > Or was this run with tracing? If so, less than three hours isn't too bad. This was with tracing enabled, only missing the crucial rcu_tree.rcu_kick_kthreads Reinette
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-03-23 21:00 +0100 |
| Message-ID | <rfX6G-8f8-17@gated-at.bofh.it> |
| In reply to | #1363597 |
On Wed, Mar 23, 2016 at 06:25:50PM +0000, Chatre, Reinette wrote: > Hi Paul, > > On 2016-03-23, Paul E. McKenney wrote: > > Please boot with the following parameters: > > > > rcu_tree.rcu_kick_kthreads ftrace > > trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi > > > > Or was this run with tracing? If so, less than three hours isn't too bad. > > This was with tracing enabled, only missing the crucial > rcu_tree.rcu_kick_kthreads Good, then the condition did trigger with tracing enabled! ;-) Thanx, Paul
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-03-23 19:30 +0100 |
| Message-ID | <rfVHA-7rS-3@gated-at.bofh.it> |
| In reply to | #1363565 |
On Wed, Mar 23, 2016 at 05:15:11PM +0000, Chatre, Reinette wrote: > Hi Paul, > > On 2016-03-22, Paul E. McKenney wrote: > > On Tue, Mar 22, 2016 at 09:04:47PM +0000, Chatre, Reinette wrote: > >> On 2016-03-22, Paul E. McKenney wrote: > >>> You set CONFIG_RCU_CPU_STALL_TIMEOUT=60, which matches the 60004 > >>> jiffies above. Is that value due to a distro setting or something? > >>> Mainline uses CONFIG_RCU_CPU_STALL_TIMEOUT=21. > >> > >> Indeed ... this value originated from a Fedora configuration. > > > > OK. Setting it shorter might (or might not) make it reproduce more > > quickly. This can be set at boot time via rcupdate.rcu_cpu_stall_timeout. > > Or at compile time via CONFIG_RCU_CPU_STALL_TIMEOUT. > > I kept the original configuration and seem to be able to reproduce with that. > > > >>> If dumping manually shortly after the stall is at all non-trivial > >>> (for example, if your reproduction time is many minute or hours), > >>> I can supply some patches that automate this. Or you can pick > >>> them up from -rcu: > >> > >> ... could you please point me to the patches you refer to? Or would you like > > me to try with the entire kernel from rcu/dev? > > > > 2dc92e2a86b9 (rcu: Awaken grace-period kthread if too long since FQS) > > c3fd2095d015 (rcu: Dump ftrace buffer when kicking grace-period kthread) > > > > There might be other dependencies, but these are the two that you need. > > I did not look closely at the patches when I applied them and because > of that missed that they need a kernel parameter to be activated. After > leaving the system idle overnight with these patches the stalls occurred > but without the parameter I did not capture the data you need. I will > try again tonight. Below are the traces from last night just in case > they have value to you. I know that feeling! Please boot with the following parameters: rcu_tree.rcu_kick_kthreads ftrace trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi Or was this run with tracing? If so, less than three hours isn't too bad. > [10154.635318] INFO: rcu_preempt detected stalls on CPUs/tasks: > [10154.639218] 1-...: (0 ticks this GP) idle=c4e/0/0 softirq=99936/99936 fqs=0 > [10154.643497] (detected by 0, t=60005 jiffies, g=24190, c=24189, q=79) > [10154.647596] Task dump for CPU 1: > [10154.650818] swapper/1 R running task 0 0 1 0x00200000 > [10154.655052] 00002656bf74de5e ffff8801785cfed0 ffffffff818af34c ffff880100000000 > [10154.659349] 0000000600000003 ffff8801785d0000 ffff880072f0bc00 ffffffff822dcf80 > [10154.663636] ffff8801785cc000 ffff8801785cc000 ffff8801785cfee0 ffffffff818af597 > [10154.667916] Call Trace: > [10154.670845] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 > [10154.674802] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 > [10154.678564] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 > [10154.682295] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 > [10154.686187] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 > [10154.690040] rcu_preempt kthread starved for 60005 jiffies! g24190 c24189 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 Still the same type of failure, which is reassuring. Thanx, Paul > [10154.694944] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 > [10154.699062] ffff8801785b7d68 ffff88017dc8cc80 ffff8801785c3b80 ffff8801785abb80 > [10154.703275] ffff8801785b8000 ffff8801785b7da0 ffff88017dc8cc80 ffff88017dc8cc80 > [10154.707481] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 00000001027e21aa > [10154.711692] Call Trace: > [10154.714548] [<ffffffff81ab03df>] schedule+0x3f/0xa0 > [10154.718075] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 > [10154.721832] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 > [10154.725659] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 > [10154.729379] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 > [10154.733235] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 > [10154.736854] [<ffffffff8112f856>] kthread+0xe6/0x100 > [10154.740267] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [10154.743980] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 > [10154.747511] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [11348.912706] INFO: rcu_preempt detected stalls on CPUs/tasks: > [11348.916346] 2-...: (0 ticks this GP) idle=586/0/0 softirq=133504/133504 fqs=0 > [11348.920407] (detected by 3, t=60002 jiffies, g=26799, c=26798, q=72) > [11348.924244] Task dump for CPU 2: > [11348.927205] swapper/2 R running task 0 0 1 0x00200000 > [11348.931178] 00002adc83427a76 ffff8801785d3ed0 ffffffff818af34c ffff880100000000 > [11348.935217] 0000000600000003 ffff8801785d4000 ffff880177d01e00 ffffffff822dcf80 > [11348.939237] ffff8801785d0000 ffff8801785d0000 ffff8801785d3ee0 ffffffff818af597 > [11348.943252] Call Trace: > [11348.945921] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 > [11348.949615] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 > [11348.953115] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 > [11348.956584] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 > [11348.960215] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 > [11348.963808] rcu_preempt kthread starved for 60002 jiffies! g26799 c26798 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 > [11348.968452] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 > [11348.972309] ffff8801785b7d68 ffff88017dd0cc80 ffff8801785c5940 ffff8801785abb80 > [11348.976266] ffff8801785b8000 ffff8801785b7da0 ffff88017dd0cc80 ffff88017dd0cc80 > [11348.980207] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 0000000102c9d45e > [11348.984142] Call Trace: > [11348.986714] [<ffffffff81ab03df>] schedule+0x3f/0xa0 > [11348.989974] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 > [11348.993453] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 > [11348.997000] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 > [11349.000431] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 > [11349.004040] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 > [11349.007449] [<ffffffff8112f856>] kthread+0xe6/0x100 > [11349.010676] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [11349.014216] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 > [11349.017568] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [11790.539207] INFO: rcu_preempt detected stalls on CPUs/tasks: > [11790.542652] 2-...: (0 ticks this GP) idle=944/0/0 softirq=133668/133668 fqs=0 > [11790.546505] (detected by 3, t=60003 jiffies, g=27589, c=27588, q=72) > [11790.550124] Task dump for CPU 2: > [11790.552871] swapper/2 R running task 0 0 1 0x00200000 > [11790.556678] 00002c8422fed65e ffff8801785d3ed0 ffffffff818af34c ffff880100000000 > [11790.560580] 0000000600000003 ffff8801785d4000 ffff880177d01e00 ffffffff822dcf80 > [11790.564485] ffff8801785d0000 ffff8801785d0000 ffff8801785d3ee0 ffffffff818af597 > [11790.568389] Call Trace: > [11790.570942] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 > [11790.574525] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 > [11790.577934] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 > [11790.581311] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 > [11790.584853] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 > [11790.588350] rcu_preempt kthread starved for 60003 jiffies! g27589 c27588 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 > [11790.592945] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 > [11790.596808] ffff8801785b7d68 ffff88017dd0cc80 ffff8801785c5940 ffff8801785abb80 > [11790.600751] ffff8801785b8000 ffff8801785b7da0 ffff88017dd0cc80 ffff88017dd0cc80 > [11790.604688] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 0000000102e5d253 > [11790.608635] Call Trace: > [11790.611220] [<ffffffff81ab03df>] schedule+0x3f/0xa0 > [11790.614480] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 > [11790.617971] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 > [11790.621530] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 > [11790.624972] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 > [11790.628558] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 > [11790.631904] [<ffffffff8112f856>] kthread+0xe6/0x100 > [11790.635043] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [11790.638485] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 > [11790.641745] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [11820.319166] INFO: rcu_preempt detected stalls on CPUs/tasks: > [11820.322523] 2-...: (0 ticks this GP) idle=9b4/0/0 softirq=133674/133674 fqs=0 > [11820.326301] (detected by 3, t=60002 jiffies, g=27620, c=27619, q=64) > [11820.329856] Task dump for CPU 2: > [11820.332536] swapper/2 R running task 0 0 1 0x00200000 > [11820.336228] 00002ca4dc6b2bb1 ffff8801785d3ed0 ffffffff818af34c ffff880100000000 > [11820.339990] 0000000600000003 ffff8801785d4000 ffff880177d01e00 ffffffff822dcf80 > [11820.343749] ffff8801785d0000 ffff8801785d0000 ffff8801785d3ee0 ffffffff818af597 > [11820.347483] Call Trace: > [11820.349852] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 > [11820.353250] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 > [11820.356463] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 > [11820.359637] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 > [11820.362973] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 > [11820.366264] rcu_preempt kthread starved for 60002 jiffies! g27620 c27619 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 > [11820.370643] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 > [11820.374276] ffff8801785b7d68 ffff88017dd0cc80 ffff8801785c5940 ffff8801785abb80 > [11820.378026] ffff8801785b8000 ffff8801785b7da0 ffff88017dd0cc80 ffff88017dd0cc80 > [11820.381775] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 0000000102e7b58c > [11820.385537] Call Trace: > [11820.387940] [<ffffffff81ab03df>] schedule+0x3f/0xa0 > [11820.391005] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 > [11820.394286] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 > [11820.397626] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 > [11820.400853] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 > [11820.404269] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 > [11820.407478] [<ffffffff8112f856>] kthread+0xe6/0x100 > [11820.410493] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [11820.413824] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 > [11820.416966] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [11903.292474] INFO: rcu_preempt detected stalls on CPUs/tasks: > [11903.295736] 2-...: (0 ticks this GP) idle=bd2/0/0 softirq=133700/133700 fqs=0 > [11903.299427] (detected by 3, t=60003 jiffies, g=27759, c=27758, q=277) > [11903.302921] Task dump for CPU 2: > [11903.305513] swapper/2 R running task 0 0 1 0x00200000 > [11903.309164] 00002cf65a063204 ffff8801785d3ed0 ffffffff818af34c ffff880100000000 > [11903.312931] 0000000600000003 ffff8801785d4000 ffff880177d01e00 ffffffff822dcf80 > [11903.316685] ffff8801785d0000 ffff8801785d0000 ffff8801785d3ee0 ffffffff818af597 > [11903.320426] Call Trace: > [11903.322802] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 > [11903.326199] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 > [11903.329416] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 > [11903.332591] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 > [11903.335931] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 > [11903.339226] rcu_preempt kthread starved for 60003 jiffies! g27759 c27758 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 > [11903.343607] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 > [11903.347246] ffff8801785b7d68 ffff88017dd0cc80 ffff8801785c5940 ffff8801785abb80 > [11903.350999] ffff8801785b8000 ffff8801785b7da0 ffff88017dd0cc80 ffff88017dd0cc80 > [11903.354750] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 0000000102ecf7e4 > [11903.358508] Call Trace: > [11903.360909] [<ffffffff81ab03df>] schedule+0x3f/0xa0 > [11903.363979] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 > [11903.367259] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 > [11903.370601] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 > [11903.373829] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 > [11903.377243] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 > [11903.380455] [<ffffffff8112f856>] kthread+0xe6/0x100 > [11903.383473] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [11903.386804] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 > [11903.389942] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [12101.322638] INFO: rcu_preempt detected stalls on CPUs/tasks: > [12101.325902] 2-...: (19 GPs behind) idle=880/0/0 softirq=133768/133768 fqs=1 > [12101.329542] (detected by 1, t=60004 jiffies, g=28170, c=28169, q=41) > [12101.333009] Task dump for CPU 2: > [12101.335599] swapper/2 R running task 0 0 1 0x00200000 > [12101.339248] 00002db4171b61e1 ffff8801785d3ed0 ffffffff818af34c ffff880100000000 > [12101.343008] 0000000600000003 ffff8801785d4000 ffff880177d01e00 ffffffff822dcf80 > [12101.346763] ffff8801785d0000 ffff8801785d0000 ffff8801785d3ee0 ffffffff818af597 > [12101.350501] Call Trace: > [12101.352868] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 > [12101.356262] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 > [12101.359475] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 > [12101.362645] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 > [12101.365980] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 > [12101.369270] rcu_preempt kthread starved for 60000 jiffies! g28170 c28169 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 > [12101.373646] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 > [12101.377281] ffff8801785b7d68 ffff88017dd0cc80 ffff8801785c5940 ffff8801785abb80 > [12101.381030] ffff8801785b8000 ffff8801785b7da0 ffff88017dd0cc80 ffff88017dd0cc80 > [12101.384778] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 0000000102f98533 > [12101.388532] Call Trace: > [12101.390927] [<ffffffff81ab03df>] schedule+0x3f/0xa0 > [12101.393991] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 > [12101.397266] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 > [12101.400602] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 > [12101.403825] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 > [12101.407240] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 > [12101.410450] [<ffffffff8112f856>] kthread+0xe6/0x100 > [12101.413465] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [12101.416793] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 > [12101.419930] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [12269.411058] INFO: rcu_preempt detected stalls on CPUs/tasks: > [12269.414316] 2-...: (27 GPs behind) idle=daa/0/0 softirq=133902/133902 fqs=1 > [12269.417947] (detected by 0, t=60003 jiffies, g=28504, c=28503, q=347) > [12269.421426] Task dump for CPU 2: > [12269.424012] swapper/2 R running task 0 0 1 0x00200000 > [12269.427656] 00002e58b5f8d033 ffff8801785d3ed0 ffffffff818af34c ffff880100000000 > [12269.431405] 0000000600000003 ffff8801785d4000 ffff880177d01e00 ffffffff822dcf80 > [12269.435153] ffff8801785d0000 ffff8801785d0000 ffff8801785d3ee0 ffffffff818af597 > [12269.438886] Call Trace: > [12269.441252] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 > [12269.444638] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 > [12269.447850] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 > [12269.451014] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 > [12269.454348] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 > [12269.457634] rcu_preempt kthread starved for 59872 jiffies! g28504 c28503 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 > [12269.462008] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 > [12269.465636] ffff8801785b7d68 ffff88017dd0cc80 ffff8801785c5940 ffff8801785abb80 > [12269.469380] ffff8801785b8000 ffff8801785b7da0 ffff88017dd0cc80 ffff88017dd0cc80 > [12269.473121] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 0000000103042d26 > [12269.476868] Call Trace: > [12269.479262] [<ffffffff81ab03df>] schedule+0x3f/0xa0 > [12269.482321] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 > [12269.485592] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 > [12269.488926] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 > [12269.492144] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 > [12269.495554] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 > [12269.498756] [<ffffffff8112f856>] kthread+0xe6/0x100 > [12269.501764] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [12269.505090] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 > [12269.508224] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [12426.587923] INFO: rcu_preempt detected stalls on CPUs/tasks: > [12426.591181] 2-...: (17 GPs behind) idle=15c/0/0 softirq=134033/134034 fqs=1 > [12426.594815] (detected by 0, t=60002 jiffies, g=28804, c=28803, q=396) > [12426.598296] Task dump for CPU 2: > [12426.600881] swapper/2 R running task 0 0 1 0x00200000 > [12426.604528] 00002eed4414d5d4 ffff8801785d3ed0 ffffffff818af34c ffff880100000000 > [12426.608284] 0000000600000003 ffff8801785d4000 ffff880177d01e00 ffffffff822dcf80 > [12426.612030] ffff8801785d0000 ffff8801785d0000 ffff8801785d3ee0 ffffffff818af597 > [12426.615762] Call Trace: > [12426.618131] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 > [12426.621522] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 > [12426.624733] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 > [12426.627903] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 > [12426.631238] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 > [12426.634527] rcu_preempt kthread starved for 59998 jiffies! g28804 c28803 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 > [12426.638900] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 > [12426.642535] ffff8801785b7d68 ffff88017dd0cc80 ffff8801785c5940 ffff8801785abb80 > [12426.646285] ffff8801785b8000 ffff8801785b7da0 ffff88017dd0cc80 ffff88017dd0cc80 > [12426.650031] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 00000001030e230e > [12426.653787] Call Trace: > [12426.656186] [<ffffffff81ab03df>] schedule+0x3f/0xa0 > [12426.659251] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 > [12426.662528] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 > [12426.665868] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 > [12426.669091] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 > [12426.672502] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 > [12426.675710] [<ffffffff8112f856>] kthread+0xe6/0x100 > [12426.678724] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [12426.682052] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 > [12426.685188] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > >
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-03-25 22:50 +0100 |
| Message-ID | <rgHMd-7UL-1@gated-at.bofh.it> |
| In reply to | #1363600 |
On Fri, Mar 25, 2016 at 09:24:14PM +0000, Chatre, Reinette wrote: > Hi Paul, > > On 2016-03-23, Paul E. McKenney wrote: > > Please boot with the following parameters: > > > > rcu_tree.rcu_kick_kthreads ftrace > > trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi > > With these parameters I expected more details to show up in the kernel logs but cannot find any. Even so, today I left the machine running again and when this happened I think I was able to capture the trace data for the event. Please find attached the trace information for the kernel message below. Since the complete trace file is very big I trimmed it to show the time around this event - hopefully this will contain the information you need. I would also like to provide some additional information. The system on which I see these events had a time that was _very_ wrong. I noticed that this issue occurs when system-timesynd was one of the tasks calling the functions of interest to your tracing and am wondering if a very out of sync time in process of being corrected could be the cause of this issue? As an experiment I ensured the system time was accurate before leaving the system idle overnight and I did not see the issue the next morning. Ah! Yes, a sudden jump in time or a disagreement about the time among different components of the system can definitely cause these symptoms. We have sometimes seen these problems occur when a pair of CPUs have wildly different ideas about what time it is, for example. Please let me know how it goes. Also, in your trace, there are no sched_waking events for the rcu_preempt process that are not immediately followed by sched_wakeup, so your trace isn't showing the problem that I am seeing. Still beating up on my stress test, which is not yet proving to be all that stressful. :-/ Thanx, Paul > [ 957.396537] INFO: rcu_preempt detected stalls on CPUs/tasks: > [ 957.399933] 1-...: (0 ticks this GP) idle=4d6/0/0 softirq=6311/6311 fqs=0 > [ 957.403661] (detected by 0, t=60002 jiffies, g=3583, c=3582, q=47) > [ 957.407227] Task dump for CPU 1: > [ 957.409964] swapper/1 R running task 0 0 1 0x00200000 > [ 957.413770] 0000039daa9a7eb9 ffff8801785cfed0 ffffffff818af34c ffff880100000000 > [ 957.417696] 0000000600000003 ffff8801785d0000 ffff880072f9ea00 ffffffff822dcf80 > [ 957.421631] ffff8801785cc000 ffff8801785cc000 ffff8801785cfee0 ffffffff818af597 > [ 957.425562] Call Trace: > [ 957.428124] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 > [ 957.431713] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 > [ 957.435122] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 > [ 957.438467] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 > [ 957.441949] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 > [ 957.445378] rcu_preempt kthread starved for 60002 jiffies! g3583 c3582 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 > [ 957.449834] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 > [ 957.453579] ffff8801785b7d68 ffff88017dc8cc80 ffff88016fe6bb80 ffff8801785abb80 > [ 957.457428] ffff8801785b8000 ffff8801785b7da0 ffff88017dc8cc80 ffff88017dc8cc80 > [ 957.461249] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df 0000000100373021 > [ 957.465055] Call Trace: > [ 957.467493] [<ffffffff81ab03df>] schedule+0x3f/0xa0 > [ 957.470613] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 > [ 957.473976] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 > [ 957.477387] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 > [ 957.480659] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 > [ 957.484123] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 > [ 957.487392] [<ffffffff8112f856>] kthread+0xe6/0x100 > [ 957.490470] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > [ 957.493859] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 > [ 957.497044] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > > Reinette
[toc] | [prev] | [next] | [standalone]
| From | Mathieu Desnoyers <mathieu.desnoyers@efficios.com> |
|---|---|
| Date | 2016-03-26 13:30 +0100 |
| Message-ID | <rgVvQ-Kf-15@gated-at.bofh.it> |
| In reply to | #1364852 |
----- On Mar 25, 2016, at 5:46 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com wrote:
> On Fri, Mar 25, 2016 at 09:24:14PM +0000, Chatre, Reinette wrote:
>> Hi Paul,
>>
>> On 2016-03-23, Paul E. McKenney wrote:
>> > Please boot with the following parameters:
>> >
>> > rcu_tree.rcu_kick_kthreads ftrace
>> > trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi
>>
>> With these parameters I expected more details to show up in the kernel logs but
>> cannot find any. Even so, today I left the machine running again and when this
>> happened I think I was able to capture the trace data for the event. Please
>> find attached the trace information for the kernel message below. Since the
>> complete trace file is very big I trimmed it to show the time around this event
>> - hopefully this will contain the information you need. I would also like to
>> provide some additional information. The system on which I see these events had
>> a time that was _very_ wrong. I noticed that this issue occurs when
>> system-timesynd was one of the tasks calling the functions of interest to your
>> tracing and am wondering if a very out of sync time in process of being
>> corrected could be the cause of this issue? As an experiment I ensured the
>> system time was accurate before leaving the system idle overnight and I did not
>> see the issue the next morning.
>
> Ah! Yes, a sudden jump in time or a disagreement about the time among
> different components of the system can definitely cause these symptoms.
> We have sometimes seen these problems occur when a pair of CPUs have
> wildly different ideas about what time it is, for example. Please let
> me know how it goes.
>
> Also, in your trace, there are no sched_waking events for the rcu_preempt
> process that are not immediately followed by sched_wakeup, so your trace
> isn't showing the problem that I am seeing.
This is interesting.
Perhaps we could try with those commits reverted ?
commit e3baac47f0e82c4be632f4f97215bb93bf16b342
Author: Peter Zijlstra <peterz@infradead.org>
Date: Wed Jun 4 10:31:18 2014 -0700
sched/idle: Optimize try-to-wake-up IPI
commit fd99f91aa007ba255aac44fe6cf21c1db398243a
Author: Peter Zijlstra <peterz@infradead.org>
Date: Wed Apr 9 15:35:08 2014 +0200
sched/idle: Avoid spurious wakeup IPIs
They appeared in 3.16.
Thanks,
Mathieu
>
> Still beating up on my stress test, which is not yet proving to be all
> that stressful. :-/
>
> Thanx, Paul
>
>> [ 957.396537] INFO: rcu_preempt detected stalls on CPUs/tasks:
>> [ 957.399933] 1-...: (0 ticks this GP) idle=4d6/0/0 softirq=6311/6311 fqs=0
>> [ 957.403661] (detected by 0, t=60002 jiffies, g=3583, c=3582, q=47)
>> [ 957.407227] Task dump for CPU 1:
>> [ 957.409964] swapper/1 R running task 0 0 1 0x00200000
>> [ 957.413770] 0000039daa9a7eb9 ffff8801785cfed0 ffffffff818af34c
>> ffff880100000000
>> [ 957.417696] 0000000600000003 ffff8801785d0000 ffff880072f9ea00
>> ffffffff822dcf80
>> [ 957.421631] ffff8801785cc000 ffff8801785cc000 ffff8801785cfee0
>> ffffffff818af597
>> [ 957.425562] Call Trace:
>> [ 957.428124] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310
>> [ 957.431713] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20
>> [ 957.435122] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40
>> [ 957.438467] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360
>> [ 957.441949] [<ffffffff8108c864>] ? start_secondary+0x114/0x140
>> [ 957.445378] rcu_preempt kthread starved for 60002 jiffies! g3583 c3582 f0x0
>> RCU_GP_WAIT_FQS(3) ->state=0x1
>> [ 957.449834] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000
>> [ 957.453579] ffff8801785b7d68 ffff88017dc8cc80 ffff88016fe6bb80
>> ffff8801785abb80
>> [ 957.457428] ffff8801785b8000 ffff8801785b7da0 ffff88017dc8cc80
>> ffff88017dc8cc80
>> [ 957.461249] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df
>> 0000000100373021
>> [ 957.465055] Call Trace:
>> [ 957.467493] [<ffffffff81ab03df>] schedule+0x3f/0xa0
>> [ 957.470613] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270
>> [ 957.473976] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120
>> [ 957.477387] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40
>> [ 957.480659] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70
>> [ 957.484123] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0
>> [ 957.487392] [<ffffffff8112f856>] kthread+0xe6/0x100
>> [ 957.490470] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190
>> [ 957.493859] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70
>> [ 957.497044] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190
>>
> > Reinette
--
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-03-26 16:30 +0100 |
| Message-ID | <rgYk2-2G4-11@gated-at.bofh.it> |
| In reply to | #1364937 |
On Sat, Mar 26, 2016 at 12:29:31PM +0000, Mathieu Desnoyers wrote: > ----- On Mar 25, 2016, at 5:46 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com wrote: > > > On Fri, Mar 25, 2016 at 09:24:14PM +0000, Chatre, Reinette wrote: > >> Hi Paul, > >> > >> On 2016-03-23, Paul E. McKenney wrote: > >> > Please boot with the following parameters: > >> > > >> > rcu_tree.rcu_kick_kthreads ftrace > >> > trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi > >> > >> With these parameters I expected more details to show up in the kernel logs but > >> cannot find any. Even so, today I left the machine running again and when this > >> happened I think I was able to capture the trace data for the event. Please > >> find attached the trace information for the kernel message below. Since the > >> complete trace file is very big I trimmed it to show the time around this event > >> - hopefully this will contain the information you need. I would also like to > >> provide some additional information. The system on which I see these events had > >> a time that was _very_ wrong. I noticed that this issue occurs when > >> system-timesynd was one of the tasks calling the functions of interest to your > >> tracing and am wondering if a very out of sync time in process of being > >> corrected could be the cause of this issue? As an experiment I ensured the > >> system time was accurate before leaving the system idle overnight and I did not > >> see the issue the next morning. > > > > Ah! Yes, a sudden jump in time or a disagreement about the time among > > different components of the system can definitely cause these symptoms. > > We have sometimes seen these problems occur when a pair of CPUs have > > wildly different ideas about what time it is, for example. Please let > > me know how it goes. > > > > Also, in your trace, there are no sched_waking events for the rcu_preempt > > process that are not immediately followed by sched_wakeup, so your trace > > isn't showing the problem that I am seeing. > > This is interesting. > > Perhaps we could try with those commits reverted ? > > commit e3baac47f0e82c4be632f4f97215bb93bf16b342 > Author: Peter Zijlstra <peterz@infradead.org> > Date: Wed Jun 4 10:31:18 2014 -0700 > > sched/idle: Optimize try-to-wake-up IPI > > commit fd99f91aa007ba255aac44fe6cf21c1db398243a > Author: Peter Zijlstra <peterz@infradead.org> > Date: Wed Apr 9 15:35:08 2014 +0200 > > sched/idle: Avoid spurious wakeup IPIs > > They appeared in 3.16. At this point, I am up for trying pretty much anything. ;-) Will give it a go. Thanx, Paul > Thanks, > > Mathieu > > > > > Still beating up on my stress test, which is not yet proving to be all > > that stressful. :-/ > > > > Thanx, Paul > > > >> [ 957.396537] INFO: rcu_preempt detected stalls on CPUs/tasks: > >> [ 957.399933] 1-...: (0 ticks this GP) idle=4d6/0/0 softirq=6311/6311 fqs=0 > >> [ 957.403661] (detected by 0, t=60002 jiffies, g=3583, c=3582, q=47) > >> [ 957.407227] Task dump for CPU 1: > >> [ 957.409964] swapper/1 R running task 0 0 1 0x00200000 > >> [ 957.413770] 0000039daa9a7eb9 ffff8801785cfed0 ffffffff818af34c > >> ffff880100000000 > >> [ 957.417696] 0000000600000003 ffff8801785d0000 ffff880072f9ea00 > >> ffffffff822dcf80 > >> [ 957.421631] ffff8801785cc000 ffff8801785cc000 ffff8801785cfee0 > >> ffffffff818af597 > >> [ 957.425562] Call Trace: > >> [ 957.428124] [<ffffffff818af34c>] ? cpuidle_enter_state+0xfc/0x310 > >> [ 957.431713] [<ffffffff818af597>] ? cpuidle_enter+0x17/0x20 > >> [ 957.435122] [<ffffffff811515ba>] ? call_cpuidle+0x2a/0x40 > >> [ 957.438467] [<ffffffff8115198d>] ? cpu_startup_entry+0x28d/0x360 > >> [ 957.441949] [<ffffffff8108c864>] ? start_secondary+0x114/0x140 > >> [ 957.445378] rcu_preempt kthread starved for 60002 jiffies! g3583 c3582 f0x0 > >> RCU_GP_WAIT_FQS(3) ->state=0x1 > >> [ 957.449834] rcu_preempt S ffff8801785b7d68 0 7 2 0x00000000 > >> [ 957.453579] ffff8801785b7d68 ffff88017dc8cc80 ffff88016fe6bb80 > >> ffff8801785abb80 > >> [ 957.457428] ffff8801785b8000 ffff8801785b7da0 ffff88017dc8cc80 > >> ffff88017dc8cc80 > >> [ 957.461249] 0000000000000003 ffff8801785b7d80 ffffffff81ab03df > >> 0000000100373021 > >> [ 957.465055] Call Trace: > >> [ 957.467493] [<ffffffff81ab03df>] schedule+0x3f/0xa0 > >> [ 957.470613] [<ffffffff81ab4397>] schedule_timeout+0x127/0x270 > >> [ 957.473976] [<ffffffff81171a00>] ? detach_if_pending+0x120/0x120 > >> [ 957.477387] [<ffffffff8116d983>] rcu_gp_kthread+0x6d3/0xa40 > >> [ 957.480659] [<ffffffff811513a0>] ? wake_atomic_t_function+0x70/0x70 > >> [ 957.484123] [<ffffffff8116d2b0>] ? force_qs_rnp+0x1b0/0x1b0 > >> [ 957.487392] [<ffffffff8112f856>] kthread+0xe6/0x100 > >> [ 957.490470] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > >> [ 957.493859] [<ffffffff81ab5ccf>] ret_from_fork+0x3f/0x70 > >> [ 957.497044] [<ffffffff8112f770>] ? kthread_worker_fn+0x190/0x190 > >> > > > Reinette > > -- > Mathieu Desnoyers > EfficiOS Inc. > http://www.efficios.com >
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-03-26 19:50 +0100 |
| Message-ID | <rh1rA-4Jn-11@gated-at.bofh.it> |
| In reply to | #1364952 |
On Sat, Mar 26, 2016 at 08:28:16AM -0700, Paul E. McKenney wrote: > On Sat, Mar 26, 2016 at 12:29:31PM +0000, Mathieu Desnoyers wrote: > > ----- On Mar 25, 2016, at 5:46 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com wrote: > > > > > On Fri, Mar 25, 2016 at 09:24:14PM +0000, Chatre, Reinette wrote: > > >> Hi Paul, > > >> > > >> On 2016-03-23, Paul E. McKenney wrote: > > >> > Please boot with the following parameters: > > >> > > > >> > rcu_tree.rcu_kick_kthreads ftrace > > >> > trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi > > >> > > >> With these parameters I expected more details to show up in the kernel logs but > > >> cannot find any. Even so, today I left the machine running again and when this > > >> happened I think I was able to capture the trace data for the event. Please > > >> find attached the trace information for the kernel message below. Since the > > >> complete trace file is very big I trimmed it to show the time around this event > > >> - hopefully this will contain the information you need. I would also like to > > >> provide some additional information. The system on which I see these events had > > >> a time that was _very_ wrong. I noticed that this issue occurs when > > >> system-timesynd was one of the tasks calling the functions of interest to your > > >> tracing and am wondering if a very out of sync time in process of being > > >> corrected could be the cause of this issue? As an experiment I ensured the > > >> system time was accurate before leaving the system idle overnight and I did not > > >> see the issue the next morning. > > > > > > Ah! Yes, a sudden jump in time or a disagreement about the time among > > > different components of the system can definitely cause these symptoms. > > > We have sometimes seen these problems occur when a pair of CPUs have > > > wildly different ideas about what time it is, for example. Please let > > > me know how it goes. > > > > > > Also, in your trace, there are no sched_waking events for the rcu_preempt > > > process that are not immediately followed by sched_wakeup, so your trace > > > isn't showing the problem that I am seeing. > > > > This is interesting. > > > > Perhaps we could try with those commits reverted ? > > > > commit e3baac47f0e82c4be632f4f97215bb93bf16b342 > > Author: Peter Zijlstra <peterz@infradead.org> > > Date: Wed Jun 4 10:31:18 2014 -0700 > > > > sched/idle: Optimize try-to-wake-up IPI > > > > commit fd99f91aa007ba255aac44fe6cf21c1db398243a > > Author: Peter Zijlstra <peterz@infradead.org> > > Date: Wed Apr 9 15:35:08 2014 +0200 > > > > sched/idle: Avoid spurious wakeup IPIs > > > > They appeared in 3.16. > > At this point, I am up for trying pretty much anything. ;-) > > Will give it a go. And those certainly don't revert cleanly! Would patching the kernel to remove the definition of TIF_POLLING_NRFLAG be useful? Or, more to the point, is there some other course of action that would be more useful? At this point, the test times are measured in weeks... Thanx, Paul
[toc] | [prev] | [next] | [standalone]
| From | Mathieu Desnoyers <mathieu.desnoyers@efficios.com> |
|---|---|
| Date | 2016-03-26 23:30 +0100 |
| Message-ID | <rh4Su-7nB-11@gated-at.bofh.it> |
| In reply to | #1364972 |
----- On Mar 26, 2016, at 2:49 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com wrote: > On Sat, Mar 26, 2016 at 08:28:16AM -0700, Paul E. McKenney wrote: >> On Sat, Mar 26, 2016 at 12:29:31PM +0000, Mathieu Desnoyers wrote: >> > ----- On Mar 25, 2016, at 5:46 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com >> > wrote: >> > >> > > On Fri, Mar 25, 2016 at 09:24:14PM +0000, Chatre, Reinette wrote: >> > >> Hi Paul, >> > >> >> > >> On 2016-03-23, Paul E. McKenney wrote: >> > >> > Please boot with the following parameters: >> > >> > >> > >> > rcu_tree.rcu_kick_kthreads ftrace >> > >> > trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi >> > >> >> > >> With these parameters I expected more details to show up in the kernel logs but >> > >> cannot find any. Even so, today I left the machine running again and when this >> > >> happened I think I was able to capture the trace data for the event. Please >> > >> find attached the trace information for the kernel message below. Since the >> > >> complete trace file is very big I trimmed it to show the time around this event >> > >> - hopefully this will contain the information you need. I would also like to >> > >> provide some additional information. The system on which I see these events had >> > >> a time that was _very_ wrong. I noticed that this issue occurs when >> > >> system-timesynd was one of the tasks calling the functions of interest to your >> > >> tracing and am wondering if a very out of sync time in process of being >> > >> corrected could be the cause of this issue? As an experiment I ensured the >> > >> system time was accurate before leaving the system idle overnight and I did not >> > >> see the issue the next morning. >> > > >> > > Ah! Yes, a sudden jump in time or a disagreement about the time among >> > > different components of the system can definitely cause these symptoms. >> > > We have sometimes seen these problems occur when a pair of CPUs have >> > > wildly different ideas about what time it is, for example. Please let >> > > me know how it goes. >> > > >> > > Also, in your trace, there are no sched_waking events for the rcu_preempt >> > > process that are not immediately followed by sched_wakeup, so your trace >> > > isn't showing the problem that I am seeing. >> > >> > This is interesting. >> > >> > Perhaps we could try with those commits reverted ? >> > >> > commit e3baac47f0e82c4be632f4f97215bb93bf16b342 >> > Author: Peter Zijlstra <peterz@infradead.org> >> > Date: Wed Jun 4 10:31:18 2014 -0700 >> > >> > sched/idle: Optimize try-to-wake-up IPI >> > >> > commit fd99f91aa007ba255aac44fe6cf21c1db398243a >> > Author: Peter Zijlstra <peterz@infradead.org> >> > Date: Wed Apr 9 15:35:08 2014 +0200 >> > >> > sched/idle: Avoid spurious wakeup IPIs >> > >> > They appeared in 3.16. >> >> At this point, I am up for trying pretty much anything. ;-) >> >> Will give it a go. > > And those certainly don't revert cleanly! Would patching the kernel > to remove the definition of TIF_POLLING_NRFLAG be useful? Or, more > to the point, is there some other course of action that would be more > useful? At this point, the test times are measured in weeks... Indeed, patching the kernel to remove the TIF_POLLING_NRFLAG definition would have an effect similar to reverting those two commits. Since testing takes a while, we could take a more aggressive approach towards reproducing a possible race condition: we could re-implement the _TIF_POLLING_NRFLAG vs _TIF_NEED_RESCHED dance, along with the ttwu pending lock-list queue, within a dummy test module, with custom data structures, and stress-test the invariants. We could also create a Promela model of these ipi-skip optimisations trying to validate progress: whenever a wakeup is requested, there should always be a scheduling performed, even if no further wakeup is encountered. Each of the two approaches proposed above might be a significant endeavor, and would only validate my specific hunch. So it might be a good idea to just let a test run for a few weeks with TIF_POLLING_NRFLAG disabled meanwhile. Thoughts ? Thanks, Mathieu -- Mathieu Desnoyers EfficiOS Inc. http://www.efficios.com
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-03-27 03:40 +0200 |
| Message-ID | <rh7Qm-181-3@gated-at.bofh.it> |
| In reply to | #1365023 |
On Sat, Mar 26, 2016 at 10:22:57PM +0000, Mathieu Desnoyers wrote: > ----- On Mar 26, 2016, at 2:49 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com wrote: > > > On Sat, Mar 26, 2016 at 08:28:16AM -0700, Paul E. McKenney wrote: > >> On Sat, Mar 26, 2016 at 12:29:31PM +0000, Mathieu Desnoyers wrote: > >> > ----- On Mar 25, 2016, at 5:46 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com > >> > wrote: > >> > > >> > > On Fri, Mar 25, 2016 at 09:24:14PM +0000, Chatre, Reinette wrote: > >> > >> Hi Paul, > >> > >> > >> > >> On 2016-03-23, Paul E. McKenney wrote: > >> > >> > Please boot with the following parameters: > >> > >> > > >> > >> > rcu_tree.rcu_kick_kthreads ftrace > >> > >> > trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi > >> > >> > >> > >> With these parameters I expected more details to show up in the kernel logs but > >> > >> cannot find any. Even so, today I left the machine running again and when this > >> > >> happened I think I was able to capture the trace data for the event. Please > >> > >> find attached the trace information for the kernel message below. Since the > >> > >> complete trace file is very big I trimmed it to show the time around this event > >> > >> - hopefully this will contain the information you need. I would also like to > >> > >> provide some additional information. The system on which I see these events had > >> > >> a time that was _very_ wrong. I noticed that this issue occurs when > >> > >> system-timesynd was one of the tasks calling the functions of interest to your > >> > >> tracing and am wondering if a very out of sync time in process of being > >> > >> corrected could be the cause of this issue? As an experiment I ensured the > >> > >> system time was accurate before leaving the system idle overnight and I did not > >> > >> see the issue the next morning. > >> > > > >> > > Ah! Yes, a sudden jump in time or a disagreement about the time among > >> > > different components of the system can definitely cause these symptoms. > >> > > We have sometimes seen these problems occur when a pair of CPUs have > >> > > wildly different ideas about what time it is, for example. Please let > >> > > me know how it goes. > >> > > > >> > > Also, in your trace, there are no sched_waking events for the rcu_preempt > >> > > process that are not immediately followed by sched_wakeup, so your trace > >> > > isn't showing the problem that I am seeing. > >> > > >> > This is interesting. > >> > > >> > Perhaps we could try with those commits reverted ? > >> > > >> > commit e3baac47f0e82c4be632f4f97215bb93bf16b342 > >> > Author: Peter Zijlstra <peterz@infradead.org> > >> > Date: Wed Jun 4 10:31:18 2014 -0700 > >> > > >> > sched/idle: Optimize try-to-wake-up IPI > >> > > >> > commit fd99f91aa007ba255aac44fe6cf21c1db398243a > >> > Author: Peter Zijlstra <peterz@infradead.org> > >> > Date: Wed Apr 9 15:35:08 2014 +0200 > >> > > >> > sched/idle: Avoid spurious wakeup IPIs > >> > > >> > They appeared in 3.16. > >> > >> At this point, I am up for trying pretty much anything. ;-) > >> > >> Will give it a go. > > > > And those certainly don't revert cleanly! Would patching the kernel > > to remove the definition of TIF_POLLING_NRFLAG be useful? Or, more > > to the point, is there some other course of action that would be more > > useful? At this point, the test times are measured in weeks... > > Indeed, patching the kernel to remove the TIF_POLLING_NRFLAG > definition would have an effect similar to reverting those two > commits. > > Since testing takes a while, we could take a more aggressive > approach towards reproducing a possible race condition: we > could re-implement the _TIF_POLLING_NRFLAG vs _TIF_NEED_RESCHED > dance, along with the ttwu pending lock-list queue, within > a dummy test module, with custom data structures, and > stress-test the invariants. We could also create a Promela > model of these ipi-skip optimisations trying to validate > progress: whenever a wakeup is requested, there should > always be a scheduling performed, even if no further wakeup > is encountered. > > Each of the two approaches proposed above might be a significant > endeavor, and would only validate my specific hunch. So it might > be a good idea to just let a test run for a few weeks with > TIF_POLLING_NRFLAG disabled meanwhile. This makes a lot of sense. I did some short runs, and nothing broke too badly. However, I left some diagnostic stuff in that obscured the outcome. I disabled the diagnostic stuff and am running overnight. I might need to go further and revert some of my diagnostic patches, but let's see where it is in the morning. Thanx, Paul
[toc] | [prev] | [next] | [standalone]
| From | Mathieu Desnoyers <mathieu.desnoyers@efficios.com> |
|---|---|
| Date | 2016-03-27 15:50 +0200 |
| Message-ID | <rhjeN-AP-3@gated-at.bofh.it> |
| In reply to | #1365036 |
----- On Mar 26, 2016, at 9:34 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com wrote: > On Sat, Mar 26, 2016 at 10:22:57PM +0000, Mathieu Desnoyers wrote: >> ----- On Mar 26, 2016, at 2:49 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com >> wrote: >> >> > On Sat, Mar 26, 2016 at 08:28:16AM -0700, Paul E. McKenney wrote: >> >> On Sat, Mar 26, 2016 at 12:29:31PM +0000, Mathieu Desnoyers wrote: >> >> > ----- On Mar 25, 2016, at 5:46 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com >> >> > wrote: >> >> > >> >> > > On Fri, Mar 25, 2016 at 09:24:14PM +0000, Chatre, Reinette wrote: >> >> > >> Hi Paul, >> >> > >> >> >> > >> On 2016-03-23, Paul E. McKenney wrote: >> >> > >> > Please boot with the following parameters: >> >> > >> > >> >> > >> > rcu_tree.rcu_kick_kthreads ftrace >> >> > >> > trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi >> >> > >> >> >> > >> With these parameters I expected more details to show up in the kernel logs but >> >> > >> cannot find any. Even so, today I left the machine running again and when this >> >> > >> happened I think I was able to capture the trace data for the event. Please >> >> > >> find attached the trace information for the kernel message below. Since the >> >> > >> complete trace file is very big I trimmed it to show the time around this event >> >> > >> - hopefully this will contain the information you need. I would also like to >> >> > >> provide some additional information. The system on which I see these events had >> >> > >> a time that was _very_ wrong. I noticed that this issue occurs when >> >> > >> system-timesynd was one of the tasks calling the functions of interest to your >> >> > >> tracing and am wondering if a very out of sync time in process of being >> >> > >> corrected could be the cause of this issue? As an experiment I ensured the >> >> > >> system time was accurate before leaving the system idle overnight and I did not >> >> > >> see the issue the next morning. >> >> > > >> >> > > Ah! Yes, a sudden jump in time or a disagreement about the time among >> >> > > different components of the system can definitely cause these symptoms. >> >> > > We have sometimes seen these problems occur when a pair of CPUs have >> >> > > wildly different ideas about what time it is, for example. Please let >> >> > > me know how it goes. >> >> > > >> >> > > Also, in your trace, there are no sched_waking events for the rcu_preempt >> >> > > process that are not immediately followed by sched_wakeup, so your trace >> >> > > isn't showing the problem that I am seeing. >> >> > >> >> > This is interesting. >> >> > >> >> > Perhaps we could try with those commits reverted ? >> >> > >> >> > commit e3baac47f0e82c4be632f4f97215bb93bf16b342 >> >> > Author: Peter Zijlstra <peterz@infradead.org> >> >> > Date: Wed Jun 4 10:31:18 2014 -0700 >> >> > >> >> > sched/idle: Optimize try-to-wake-up IPI >> >> > >> >> > commit fd99f91aa007ba255aac44fe6cf21c1db398243a >> >> > Author: Peter Zijlstra <peterz@infradead.org> >> >> > Date: Wed Apr 9 15:35:08 2014 +0200 >> >> > >> >> > sched/idle: Avoid spurious wakeup IPIs >> >> > >> >> > They appeared in 3.16. >> >> >> >> At this point, I am up for trying pretty much anything. ;-) >> >> >> >> Will give it a go. >> > >> > And those certainly don't revert cleanly! Would patching the kernel >> > to remove the definition of TIF_POLLING_NRFLAG be useful? Or, more >> > to the point, is there some other course of action that would be more >> > useful? At this point, the test times are measured in weeks... >> >> Indeed, patching the kernel to remove the TIF_POLLING_NRFLAG >> definition would have an effect similar to reverting those two >> commits. >> >> Since testing takes a while, we could take a more aggressive >> approach towards reproducing a possible race condition: we >> could re-implement the _TIF_POLLING_NRFLAG vs _TIF_NEED_RESCHED >> dance, along with the ttwu pending lock-list queue, within >> a dummy test module, with custom data structures, and >> stress-test the invariants. We could also create a Promela >> model of these ipi-skip optimisations trying to validate >> progress: whenever a wakeup is requested, there should >> always be a scheduling performed, even if no further wakeup >> is encountered. >> >> Each of the two approaches proposed above might be a significant >> endeavor, and would only validate my specific hunch. So it might >> be a good idea to just let a test run for a few weeks with >> TIF_POLLING_NRFLAG disabled meanwhile. > > This makes a lot of sense. I did some short runs, and nothing broke > too badly. However, I left some diagnostic stuff in that obscured > the outcome. I disabled the diagnostic stuff and am running overnight. > I might need to go further and revert some of my diagnostic patches, > but let's see where it is in the morning. Here is another idea that might help us reproduce this issue faster. If you can afford it, you might want to just throw more similar hardware at the problem. Assuming the problem shows up randomly, but its odds of showing up make it happen only once per week, if we have 100 machines idling in the same way in parallel, we should be able to reproduce it within about 1-2 hours. Of course, if the problem really need each machine to "degrade" for a week (e.g. memory fragmentation), that would not help. It's only for races that appear to be showing up randomly. Thoughts ? Thanks, Mathieu -- Mathieu Desnoyers EfficiOS Inc. http://www.efficios.com
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-03-27 17:50 +0200 |
| Message-ID | <rhl6W-21I-29@gated-at.bofh.it> |
| In reply to | #1365114 |
On Sun, Mar 27, 2016 at 01:48:55PM +0000, Mathieu Desnoyers wrote:
> ----- On Mar 26, 2016, at 9:34 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com wrote:
>
> > On Sat, Mar 26, 2016 at 10:22:57PM +0000, Mathieu Desnoyers wrote:
> >> ----- On Mar 26, 2016, at 2:49 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com
> >> wrote:
> >>
> >> > On Sat, Mar 26, 2016 at 08:28:16AM -0700, Paul E. McKenney wrote:
> >> >> On Sat, Mar 26, 2016 at 12:29:31PM +0000, Mathieu Desnoyers wrote:
> >> >> > ----- On Mar 25, 2016, at 5:46 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com
> >> >> > wrote:
> >> >> >
> >> >> > > On Fri, Mar 25, 2016 at 09:24:14PM +0000, Chatre, Reinette wrote:
> >> >> > >> Hi Paul,
> >> >> > >>
> >> >> > >> On 2016-03-23, Paul E. McKenney wrote:
> >> >> > >> > Please boot with the following parameters:
> >> >> > >> >
> >> >> > >> > rcu_tree.rcu_kick_kthreads ftrace
> >> >> > >> > trace_event=sched_waking,sched_wakeup,sched_wake_idle_without_ipi
> >> >> > >>
> >> >> > >> With these parameters I expected more details to show up in the kernel logs but
> >> >> > >> cannot find any. Even so, today I left the machine running again and when this
> >> >> > >> happened I think I was able to capture the trace data for the event. Please
> >> >> > >> find attached the trace information for the kernel message below. Since the
> >> >> > >> complete trace file is very big I trimmed it to show the time around this event
> >> >> > >> - hopefully this will contain the information you need. I would also like to
> >> >> > >> provide some additional information. The system on which I see these events had
> >> >> > >> a time that was _very_ wrong. I noticed that this issue occurs when
> >> >> > >> system-timesynd was one of the tasks calling the functions of interest to your
> >> >> > >> tracing and am wondering if a very out of sync time in process of being
> >> >> > >> corrected could be the cause of this issue? As an experiment I ensured the
> >> >> > >> system time was accurate before leaving the system idle overnight and I did not
> >> >> > >> see the issue the next morning.
> >> >> > >
> >> >> > > Ah! Yes, a sudden jump in time or a disagreement about the time among
> >> >> > > different components of the system can definitely cause these symptoms.
> >> >> > > We have sometimes seen these problems occur when a pair of CPUs have
> >> >> > > wildly different ideas about what time it is, for example. Please let
> >> >> > > me know how it goes.
> >> >> > >
> >> >> > > Also, in your trace, there are no sched_waking events for the rcu_preempt
> >> >> > > process that are not immediately followed by sched_wakeup, so your trace
> >> >> > > isn't showing the problem that I am seeing.
> >> >> >
> >> >> > This is interesting.
> >> >> >
> >> >> > Perhaps we could try with those commits reverted ?
> >> >> >
> >> >> > commit e3baac47f0e82c4be632f4f97215bb93bf16b342
> >> >> > Author: Peter Zijlstra <peterz@infradead.org>
> >> >> > Date: Wed Jun 4 10:31:18 2014 -0700
> >> >> >
> >> >> > sched/idle: Optimize try-to-wake-up IPI
> >> >> >
> >> >> > commit fd99f91aa007ba255aac44fe6cf21c1db398243a
> >> >> > Author: Peter Zijlstra <peterz@infradead.org>
> >> >> > Date: Wed Apr 9 15:35:08 2014 +0200
> >> >> >
> >> >> > sched/idle: Avoid spurious wakeup IPIs
> >> >> >
> >> >> > They appeared in 3.16.
> >> >>
> >> >> At this point, I am up for trying pretty much anything. ;-)
> >> >>
> >> >> Will give it a go.
> >> >
> >> > And those certainly don't revert cleanly! Would patching the kernel
> >> > to remove the definition of TIF_POLLING_NRFLAG be useful? Or, more
> >> > to the point, is there some other course of action that would be more
> >> > useful? At this point, the test times are measured in weeks...
> >>
> >> Indeed, patching the kernel to remove the TIF_POLLING_NRFLAG
> >> definition would have an effect similar to reverting those two
> >> commits.
> >>
> >> Since testing takes a while, we could take a more aggressive
> >> approach towards reproducing a possible race condition: we
> >> could re-implement the _TIF_POLLING_NRFLAG vs _TIF_NEED_RESCHED
> >> dance, along with the ttwu pending lock-list queue, within
> >> a dummy test module, with custom data structures, and
> >> stress-test the invariants. We could also create a Promela
> >> model of these ipi-skip optimisations trying to validate
> >> progress: whenever a wakeup is requested, there should
> >> always be a scheduling performed, even if no further wakeup
> >> is encountered.
> >>
> >> Each of the two approaches proposed above might be a significant
> >> endeavor, and would only validate my specific hunch. So it might
> >> be a good idea to just let a test run for a few weeks with
> >> TIF_POLLING_NRFLAG disabled meanwhile.
> >
> > This makes a lot of sense. I did some short runs, and nothing broke
> > too badly. However, I left some diagnostic stuff in that obscured
> > the outcome. I disabled the diagnostic stuff and am running overnight.
> > I might need to go further and revert some of my diagnostic patches,
> > but let's see where it is in the morning.
>
> Here is another idea that might help us reproduce this issue faster.
> If you can afford it, you might want to just throw more similar hardware
> at the problem. Assuming the problem shows up randomly, but its odds
> of showing up make it happen only once per week, if we have 100 machines
> idling in the same way in parallel, we should be able to reproduce it
> within about 1-2 hours.
>
> Of course, if the problem really need each machine to "degrade" for
> a week (e.g. memory fragmentation), that would not help. It's only for
> races that appear to be showing up randomly.
Certain rcutorture tests sometimes hit it within an hour (TREE03).
Last night's TREE03 ran six hours without incident, which is unusual
given that I didn't enable any tracepoints, but does not any significant
level of statitstical confidence. The set will finish in a few hours,
at which point I will start parallel batches of TREE03 to see what
comes up.
Feel free to take a look at kernel/rcu/waketorture.c for my (feeble
thus far) attempt to speed things up. I am thinking that I need to
push sleeping tasks onto idle CPUs to make it happen more often.
My current approach to this is to run with CPU utilizations of about
40% and using hrtimer with a prime number of microseconds to avoid
synchronization. That should in theory get me a 40% chance of hitting
an idle CPU with a wakeup, and a reasonable chance of racing with a
CPU-hotplug operation. But maybe the wakeup needs to be remote or
some such, in which case waketorture also needs to move stuff around.
Oh, and the patch I am running with is below. I am running x86, and so
some other architectures would of course need the corresponding patch
on that architecture.
Thanx, Paul
------------------------------------------------------------------------
diff --git a/arch/x86/include/asm/thread_info.h b/arch/x86/include/asm/thread_info.h
index c7b5510..062ae53 100644
--- a/arch/x86/include/asm/thread_info.h
+++ b/arch/x86/include/asm/thread_info.h
@@ -102,7 +102,7 @@ struct thread_info {
#define TIF_FORK 18 /* ret_from_fork */
#define TIF_NOHZ 19 /* in adaptive nohz mode */
#define TIF_MEMDIE 20 /* is terminating due to OOM killer */
-#define TIF_POLLING_NRFLAG 21 /* idle is polling for TIF_NEED_RESCHED */
+/* #define TIF_POLLING_NRFLAG 21 idle is polling for TIF_NEED_RESCHED */
#define TIF_IO_BITMAP 22 /* uses I/O bitmap */
#define TIF_FORCED_TF 24 /* true if TF in eflags artificially */
#define TIF_BLOCKSTEP 25 /* set when we want DEBUGCTLMSR_BTF */
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-03-27 22:10 +0200 |
| Message-ID | <rhpay-4Ss-13@gated-at.bofh.it> |
| In reply to | #1365134 |
On Sun, Mar 27, 2016 at 08:40:18AM -0700, Paul E. McKenney wrote: > On Sun, Mar 27, 2016 at 01:48:55PM +0000, Mathieu Desnoyers wrote: > > ----- On Mar 26, 2016, at 9:34 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com wrote: > > > On Sat, Mar 26, 2016 at 10:22:57PM +0000, Mathieu Desnoyers wrote: > > >> ----- On Mar 26, 2016, at 2:49 PM, Paul E. McKenney paulmck@linux.vnet.ibm.com > > >> wrote: > > >> > On Sat, Mar 26, 2016 at 08:28:16AM -0700, Paul E. McKenney wrote: > > >> >> On Sat, Mar 26, 2016 at 12:29:31PM +0000, Mathieu Desnoyers wrote: [ . . . ] > > >> >> > Perhaps we could try with those commits reverted ? > > >> >> > > > >> >> > commit e3baac47f0e82c4be632f4f97215bb93bf16b342 > > >> >> > Author: Peter Zijlstra <peterz@infradead.org> > > >> >> > Date: Wed Jun 4 10:31:18 2014 -0700 > > >> >> > > > >> >> > sched/idle: Optimize try-to-wake-up IPI > > >> >> > > > >> >> > commit fd99f91aa007ba255aac44fe6cf21c1db398243a > > >> >> > Author: Peter Zijlstra <peterz@infradead.org> > > >> >> > Date: Wed Apr 9 15:35:08 2014 +0200 > > >> >> > > > >> >> > sched/idle: Avoid spurious wakeup IPIs > > >> >> > > > >> >> > They appeared in 3.16. > > >> >> > > >> >> At this point, I am up for trying pretty much anything. ;-) > > >> >> > > >> >> Will give it a go. > > >> > > > >> > And those certainly don't revert cleanly! Would patching the kernel > > >> > to remove the definition of TIF_POLLING_NRFLAG be useful? Or, more > > >> > to the point, is there some other course of action that would be more > > >> > useful? At this point, the test times are measured in weeks... > > >> > > >> Indeed, patching the kernel to remove the TIF_POLLING_NRFLAG > > >> definition would have an effect similar to reverting those two > > >> commits. > > >> > > >> Since testing takes a while, we could take a more aggressive > > >> approach towards reproducing a possible race condition: we > > >> could re-implement the _TIF_POLLING_NRFLAG vs _TIF_NEED_RESCHED > > >> dance, along with the ttwu pending lock-list queue, within > > >> a dummy test module, with custom data structures, and > > >> stress-test the invariants. We could also create a Promela > > >> model of these ipi-skip optimisations trying to validate > > >> progress: whenever a wakeup is requested, there should > > >> always be a scheduling performed, even if no further wakeup > > >> is encountered. > > >> > > >> Each of the two approaches proposed above might be a significant > > >> endeavor, and would only validate my specific hunch. So it might > > >> be a good idea to just let a test run for a few weeks with > > >> TIF_POLLING_NRFLAG disabled meanwhile. > > > > > > This makes a lot of sense. I did some short runs, and nothing broke > > > too badly. However, I left some diagnostic stuff in that obscured > > > the outcome. I disabled the diagnostic stuff and am running overnight. > > > I might need to go further and revert some of my diagnostic patches, > > > but let's see where it is in the morning. > > > > Here is another idea that might help us reproduce this issue faster. > > If you can afford it, you might want to just throw more similar hardware > > at the problem. Assuming the problem shows up randomly, but its odds > > of showing up make it happen only once per week, if we have 100 machines > > idling in the same way in parallel, we should be able to reproduce it > > within about 1-2 hours. > > > > Of course, if the problem really need each machine to "degrade" for > > a week (e.g. memory fragmentation), that would not help. It's only for > > races that appear to be showing up randomly. > > Certain rcutorture tests sometimes hit it within an hour (TREE03). > Last night's TREE03 ran six hours without incident, which is unusual > given that I didn't enable any tracepoints, but does not any significant > level of statitstical confidence. The set will finish in a few hours, > at which point I will start parallel batches of TREE03 to see what > comes up. > > Feel free to take a look at kernel/rcu/waketorture.c for my (feeble > thus far) attempt to speed things up. I am thinking that I need to > push sleeping tasks onto idle CPUs to make it happen more often. > My current approach to this is to run with CPU utilizations of about > 40% and using hrtimer with a prime number of microseconds to avoid > synchronization. That should in theory get me a 40% chance of hitting > an idle CPU with a wakeup, and a reasonable chance of racing with a > CPU-hotplug operation. But maybe the wakeup needs to be remote or > some such, in which case waketorture also needs to move stuff around. > > Oh, and the patch I am running with is below. I am running x86, and so > some other architectures would of course need the corresponding patch > on that architecture. And it passed a full set of six-hour runs. Unusual of late, but not unheard of. Next step is to focus on TREE03 overnight. Thanx, Paul
[toc] | [prev] | [next] | [standalone]
Page 1 of 3 [1] 2 3 Next page →
Back to top | Article view | linux.kernel
csiph-web