Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1341012 > unrolled thread
| Started by | Mathieu Desnoyers <mathieu.desnoyers@efficios.com> |
|---|---|
| First post | 2016-02-23 21:40 +0100 |
| Last post | 2016-02-26 02:10 +0100 |
| Articles | 3 — 2 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 Mathieu Desnoyers <mathieu.desnoyers@efficios.com> - 2016-02-23 21:40 +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-02-23 22: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-02-26 02:10 +0100
| From | Mathieu Desnoyers <mathieu.desnoyers@efficios.com> |
|---|---|
| Date | 2016-02-23 21:40 +0100 |
| Subject | Re: rcu_preempt self-detected stall on CPU from 4.5-rc3, since 3.17 |
| Message-ID | <r5rUt-29C-9@gated-at.bofh.it> |
[Multipart message — attachments visible in raw view] — view raw
----- On Feb 21, 2016, at 1:15 PM, Ross Green rgkernel@gmail.com wrote: > On Sun, Feb 21, 2016 at 4:04 PM, Ross Green <rgkernel@gmail.com> wrote: >> On Sat, Feb 20, 2016 at 5:32 PM, Paul E. McKenney >> <paulmck@linux.vnet.ibm.com> wrote: >>> On Sat, Feb 20, 2016 at 03:34:30PM +1100, Ross Green wrote: >>>> On Sat, Feb 20, 2016 at 4:33 AM, Paul E. McKenney >>>> <paulmck@linux.vnet.ibm.com> wrote: >>>> > On Thu, Feb 18, 2016 at 08:13:18PM -0800, John Stultz wrote: >>>> >> On Thu, Feb 18, 2016 at 7:56 PM, Ross Green <rgkernel@gmail.com> wrote: >>>> >> > Well a bonus extra! >>>> >> > Kept everything running and there was another stall. >>>> >> > So i have included the demsg output for perusal. >>>> >> > >>>> >> > Just to clear things up there is no hotplug involved in this system. >>>> >> > It is a standard Pandaboard ES Ti4460 two processor system. >>>> >> > I use this for testing as a generic armv7 processor, plus can keep it >>>> >> > just running along for testing for a long time. the system has a total >>>> >> > of 23-25 process running on average. Mainly standard daemons. There is >>>> >> > certainly no heavy processing going on. I run a series of benchmarks >>>> >> > that are cpu intensive for the first 20 miinutes after boot and then >>>> >> > just leave it idle away. checking every so often to see how it has >>>> >> > gone. >>>> >> > As mentioned I have observed these stalls going back to 3.17 kernel. >>>> >> > It will often take up to a week to record such a stall. I will >>>> >> > typically test every new release kernel, so the -rc? series will get >>>> >> > around a weeks testing. >>>> >> >>>> >> Sorry. Kind of hopping in a bit late here. Is this always happening >>>> >> with just the pandaboard? Or are you seeing this on different >>>> >> machines? >>>> >> >>>> >> Have you tried enabling CONFIG_DEBUG_TIMEKEEPING just in case >>>> >> something is going awry there? >>>> > >>>> > Excellent point -- timekeeping issues have caused this sort of issue >>>> > in the past. >>>> > >>>> > Ross, on your next test, could you please enable CONFIG_DEBUG_TIMEKEEPING >>>> > as John suggests? >>>> > >>>> > Thanx, Paul >>>> > >>>> As John has suggested have already enabled CONFIG_DEBUG_TIMEKEEPING. >>>> >>>> So far just on 1 day running. >>>> >>>> Sigh...!! Nothing to report as yet, only one day on the clock. >>>> Its like watching grass grow! >>> >>> I hear you! Though I was thinking in terms of watching paint dry... >>> >>> Thanx, Paul >>> >> Yes, >> >> but with paint drying there is an end point! >> Grass just keeps on growing ... >> >> More like the children in the back of the car ... >> Are we there yet? ... >> >> Well still nothing .. to report. I have just built a 4.5-rc5, but will >> wait till I get some outcome from the previous test. That can't be too >> much longer! >> >> In hope, >> >> Ross Green > Patience little ones ... > > Well after 2 days plus running pulled another stall. > This is with 4.5-rc4 and CONFIG_DEBUG_TIMEKEEPING set. > > Can't see anything related to the TIMEKEEPING. > > Anyway here is the dmesg output for people to look at. > > Paul, I was going to move onto 4.5-rc5 kernel, is there something else > that you want me to test with that, Anyone else have any suggestions > or ideas? Starting from kernel 3.17, if we request a e.g. 1000 jiffies schedule_timeout on a HZ=1000 kernel, is there an upper bound to the number of jiffies it can actually take before the timeout happens, especially on idle systems ? I remember a talk from Thomas Gleixner on the new timer wheel which could add some imprecision to those timeouts. Not sure in which kernel version it got in though. My thinking is that it might be a good idea to try using hrtimers rather than a jiffies-based timeout to awaken the RCU thread if it's really important to run in a bounded amount of jiffies. Or else the jiffies-based sanity check that triggers the warning is perhaps too strict. Thoughts ? Thanks, Mathieu > > Regards, > > Ross Green -- Mathieu Desnoyers EfficiOS Inc. http://www.efficios.com
[toc] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-02-23 22:00 +0100 |
| Message-ID | <r5sdQ-2hS-9@gated-at.bofh.it> |
| In reply to | #1341012 |
On Tue, Feb 23, 2016 at 08:34:11PM +0000, Mathieu Desnoyers wrote: > ----- On Feb 21, 2016, at 1:15 PM, Ross Green rgkernel@gmail.com wrote: > > > On Sun, Feb 21, 2016 at 4:04 PM, Ross Green <rgkernel@gmail.com> wrote: > >> On Sat, Feb 20, 2016 at 5:32 PM, Paul E. McKenney > >> <paulmck@linux.vnet.ibm.com> wrote: > >>> On Sat, Feb 20, 2016 at 03:34:30PM +1100, Ross Green wrote: > >>>> On Sat, Feb 20, 2016 at 4:33 AM, Paul E. McKenney > >>>> <paulmck@linux.vnet.ibm.com> wrote: > >>>> > On Thu, Feb 18, 2016 at 08:13:18PM -0800, John Stultz wrote: > >>>> >> On Thu, Feb 18, 2016 at 7:56 PM, Ross Green <rgkernel@gmail.com> wrote: > >>>> >> > Well a bonus extra! > >>>> >> > Kept everything running and there was another stall. > >>>> >> > So i have included the demsg output for perusal. > >>>> >> > > >>>> >> > Just to clear things up there is no hotplug involved in this system. > >>>> >> > It is a standard Pandaboard ES Ti4460 two processor system. > >>>> >> > I use this for testing as a generic armv7 processor, plus can keep it > >>>> >> > just running along for testing for a long time. the system has a total > >>>> >> > of 23-25 process running on average. Mainly standard daemons. There is > >>>> >> > certainly no heavy processing going on. I run a series of benchmarks > >>>> >> > that are cpu intensive for the first 20 miinutes after boot and then > >>>> >> > just leave it idle away. checking every so often to see how it has > >>>> >> > gone. > >>>> >> > As mentioned I have observed these stalls going back to 3.17 kernel. > >>>> >> > It will often take up to a week to record such a stall. I will > >>>> >> > typically test every new release kernel, so the -rc? series will get > >>>> >> > around a weeks testing. > >>>> >> > >>>> >> Sorry. Kind of hopping in a bit late here. Is this always happening > >>>> >> with just the pandaboard? Or are you seeing this on different > >>>> >> machines? > >>>> >> > >>>> >> Have you tried enabling CONFIG_DEBUG_TIMEKEEPING just in case > >>>> >> something is going awry there? > >>>> > > >>>> > Excellent point -- timekeeping issues have caused this sort of issue > >>>> > in the past. > >>>> > > >>>> > Ross, on your next test, could you please enable CONFIG_DEBUG_TIMEKEEPING > >>>> > as John suggests? > >>>> > > >>>> > Thanx, Paul > >>>> > > >>>> As John has suggested have already enabled CONFIG_DEBUG_TIMEKEEPING. > >>>> > >>>> So far just on 1 day running. > >>>> > >>>> Sigh...!! Nothing to report as yet, only one day on the clock. > >>>> Its like watching grass grow! > >>> > >>> I hear you! Though I was thinking in terms of watching paint dry... > >>> > >>> Thanx, Paul > >>> > >> Yes, > >> > >> but with paint drying there is an end point! > >> Grass just keeps on growing ... > >> > >> More like the children in the back of the car ... > >> Are we there yet? ... > >> > >> Well still nothing .. to report. I have just built a 4.5-rc5, but will > >> wait till I get some outcome from the previous test. That can't be too > >> much longer! > >> > >> In hope, > >> > >> Ross Green > > Patience little ones ... > > > > Well after 2 days plus running pulled another stall. > > This is with 4.5-rc4 and CONFIG_DEBUG_TIMEKEEPING set. > > > > Can't see anything related to the TIMEKEEPING. > > > > Anyway here is the dmesg output for people to look at. > > > > Paul, I was going to move onto 4.5-rc5 kernel, is there something else > > that you want me to test with that, Anyone else have any suggestions > > or ideas? > > Starting from kernel 3.17, if we request a e.g. 1000 jiffies schedule_timeout > on a HZ=1000 kernel, is there an upper bound to the number of jiffies it > can actually take before the timeout happens, especially on idle systems ? > I remember a talk from Thomas Gleixner on the new timer wheel which could > add some imprecision to those timeouts. Not sure in which kernel version it > got in though. > > My thinking is that it might be a good idea to try using hrtimers rather than > a jiffies-based timeout to awaken the RCU thread if it's really important to > run in a bounded amount of jiffies. Or else the jiffies-based sanity check > that triggers the warning is perhaps too strict. Some imprecision I could well understand. 21 seconds of imprecision on a three-millisecond timeout I am having somewhat more difficulty understanding. ;-) But I would rather avoid hrtimers for the RCU grace-period kthread because a few milliseconds of adjustment for energy-efficiency reasons is a very good thing. Still working on getting decent traces... Thanx, Paul
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2016-02-26 02:10 +0100 |
| Message-ID | <r6f4T-3Xh-39@gated-at.bofh.it> |
| In reply to | #1341025 |
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"). I have replaced the old event-waiting with a straight
schedule_timeout_interruptible() as an (ineffective) desperation move.
But this dmesg also contains a trace with sched_waking and sched_wakeup
enabled. Here are the entries corresponding to the grace-period kthread
in reverse time order:
[ 1205.567414] rcu_pree-7 5d..2 1175375682us : sched_waking: comm=rcub/9 pid=34 prio=97 target_cpu=005
[ 1205.567414] rcu_pree-7 5dN.3 1175375685us : sched_wakeup: comm=rcub/9 pid=34 prio=97 target_cpu=005
This is the last sched_wakeup trace entry, 29 seconds before
the end of the trace. After this, we see a sched_waking event
about every three milliseconds.
[ 1205.567414] rcu_pree-7 4d..2 1175381643us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175384644us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175387662us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175390643us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175393644us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175396651us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175399665us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175402646us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175405647us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175408650us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175411669us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175414659us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175417654us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175420661us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175423679us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175426657us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175429660us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175432660us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175435681us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175460700us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175464687us : sched_waking: comm=rcub/14 pid=89 prio=97 target_cpu=014
[ 1205.567414] rcu_pree-7 4d..2 1175467728us : sched_waking: comm=rcub/14 pid=89 prio=97 target_cpu=014
[ 1205.567414] rcu_pree-7 4d..2 1175477679us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175477696us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175493687us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175506686us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175516696us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175516714us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175529700us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175536704us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175539737us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175542707us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175545704us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175548709us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175551740us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175554709us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175566714us : sched_waking: comm=rcub/7 pid=11 prio=97 target_cpu=000
[ 1205.567414] rcu_pree-7 4d..2 1175566732us : sched_waking: comm=rcub/10 pid=45 prio=97 target_cpu=006
[ 1205.567414] rcu_pree-7 4d..2 1175569724us : sched_waking: comm=rcub/10 pid=45 prio=97 target_cpu=006
[ 1205.567414] rcu_pree-7 4d..2 1175572719us : sched_waking: comm=rcub/10 pid=45 prio=97 target_cpu=006
[ 1205.567414] rcu_pree-7 4d..2 1175575750us : sched_waking: comm=rcub/10 pid=45 prio=97 target_cpu=006
[ 1205.567414] rcu_pree-7 4d..2 1175578717us : sched_waking: comm=rcub/10 pid=45 prio=97 target_cpu=006
[ 1205.567414] rcu_pree-7 4d..2 1175581718us : sched_waking: comm=rcub/10 pid=45 prio=97 target_cpu=006
[ 1205.567414] rcu_pree-7 4d..2 1175584721us : sched_waking: comm=rcub/10 pid=45 prio=97 target_cpu=006
[ 1205.567414] rcu_pree-7 4d..2 1175587748us : sched_waking: comm=rcub/10 pid=45 prio=97 target_cpu=006
[ 1205.567414] rcu_pree-7 4d..2 1175590728us : sched_waking: comm=rcub/10 pid=45 prio=97 target_cpu=006
[ 1205.567414] rcu_pree-7 4d..2 1175593724us : sched_waking: comm=rcub/10 pid=45 prio=97 target_cpu=006
[ 1205.567414] rcu_pree-7 4d..2 1175596724us : sched_waking: comm=rcub/10 pid=45 prio=97 target_cpu=006
[ 1205.567414] rcu_pree-7 4d..2 1175599761us : sched_waking: comm=rcub/10 pid=45 prio=97 target_cpu=006
[ 1205.567414] rcu_pree-7 4d..2 1175602726us : sched_waking: comm=rcub/10 pid=45 prio=97 target_cpu=006
[ 1205.567414] rcu_pree-7 4d..2 1175605728us : sched_waking: comm=rcub/10 pid=45 prio=97 target_cpu=006
[ 1205.567414] rcu_pree-7 4d..2 1175612737us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175615753us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175618737us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175621736us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175624738us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175627757us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175630741us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175633741us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175636745us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175639765us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175642744us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175645745us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175648750us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175651771us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175654751us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175657750us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175660752us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175663779us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175666752us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175669753us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175672757us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175675782us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175678756us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175681761us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175684761us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175687778us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175690762us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175693763us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
[ 1205.567414] rcu_pree-7 4d..2 1175696766us : sched_waking: comm=rcub/12 pid=67 prio=97 target_cpu=010
We might have lost some events, but losing that many in that pattern
seems unlikely.
OK, so what wakeup path omits the sched_wakeup event?
The sched_waking event looks to occur once in try_to_wake_up() and
once in try_to_wake_up_local(). Starting with try_to_wake_up():
o If the task is ->on_rq, ttwu_remote() is invoked:
o This acquires the runqueue lock, then if
task_on_rq_queued() invokes ttwu_do_wakeup(). This
unconditionally does sched_wakeup, so we didn't go that
way. (And this path skips the bulk of try_to_wake_up()
on return.)
o Otherwise, we release the runqueu lock and returns zero.
o There is some ordering checking, runqueue selection, and then
p->state is set to TASK_WAKING. And we apparently are not getting
here, either. But I don't see any other way out.
Ignoring this for the moment...
We eventually reach to the call to ttwu_queue().
o Here the TTWU_QUEUE path seems to avoid doing a
sched_wakeup event -- and since we are trying to wake
CPU 0 from CPU 4, so they don't share cache (x86).
o This invokes ttwu_queue_remote(), which sends an IPI
unless polling is in effect. I would need to enable
trace_sched_wake_idle_without_ipi() to see whether or
not the IPI was actually sent.
If the target CPU was offline, we should have seen the
cpu_is_offline() WARN_ON(). I suppose that the CPU might
go offline between the check and the ->send_IPI_mask(),
but only once. And we are trying to wakeup on CPU 0
quite a few times.
Any thoughts on what to look for?
Next, try_to_wake_up_local():
o After doing several checks, it does the sched_waking event.
o If the task is already queued, it calls ttwu_activate().
o It then invokes ttwu_do_wakeup(), which unconditionally
does the sched_wakeup() event.
So this path looks unlikely, even ignoring the fact that
the waking CPU in the traces above is always different than
the CPU to be awakened on.
Any thoughts?
Thanx, Paul
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web