Hi Frederic,
On 01/07/2013 06:08 PM, Frederic Weisbecker wrote:
> The runqueue clock is supposed to be periodically updated by the
> tick. On full dynticks CPU we call update_nohz_rq_clock() before
> reading it. Now the scheduler code is complicated enough that we
> may miss some update_nohz_rq_clock() calls before reading the
> runqueue clock.
>
> This therefore introduce a new debugging feature that detects
> when the rq clock is stale due to missing updates on full
> dynticks CPUs.
>
> This can be later expanded to debug stale clocks on dynticks-idle
> CPUs.
[...]
> diff --git a/kernel/sched/sched.h b/kernel/sched/sched.h
> index e1bac76..0fef0b3 100644
> --- a/kernel/sched/sched.h
> +++ b/kernel/sched/sched.h
> @@ -502,16 +502,39 @@ DECLARE_PER_CPU(struct rq, runqueues);
> #define cpu_curr(cpu) (cpu_rq(cpu)->curr)
> #define raw_rq() (&__raw_get_cpu_var(runqueues))
>
> +static inline void rq_clock_check(struct rq *rq)
> +{
> +#if defined(CONFIG_SCHED_DEBUG) && defined(CONFIG_NO_HZ_FULL)
> + unsigned long long clock;
> + unsigned long flags;
> + int cpu;
> +
> + cpu = cpu_of(rq);
> + if (!tick_nohz_full_cpu(cpu) || rq->curr == rq->idle)
> + return;
> +
> + local_irq_save(flags);
> + clock = sched_clock_cpu(cpu_of(rq));
> + local_irq_restore(flags);
> +
> + if (abs(clock - rq->clock) > (TICK_NSEC * 3))
> + WARN_ON_ONCE(1);
> +#endif
> +}
In working on the ARM port for full nohz, I'm hitting this
warning early in the kernel boot, well before userspace starts
(dump below[2].)
I've seen a few different variations of this, but the common
thing for all of them is the use of wait_for_completion().
During boot, only swapper is running so it seems
any waiting of sufficient length during boot will always trigger
this warning. The hack below[1] avoids checking for the init task,
but I'm not sure if it's the right fix.
Kevin
[1]
diff --git a/kernel/sched/sched.h b/kernel/sched/sched.h
index f96329b..56e74df 100644
--- a/kernel/sched/sched.h
+++ b/kernel/sched/sched.h
@@ -512,7 +512,8 @@ static inline void rq_clock_check(struct rq *rq)
int cpu;
cpu = cpu_of(rq);
- if (!tick_nohz_full_cpu(cpu) || rq->curr == rq->idle)
+ if (!tick_nohz_full_cpu(cpu) || rq->curr == rq->idle ||
+ is_global_init(current))
return;
[2] Example warning dump
[ 1.101013] ------------[ cut here ]------------
[ 1.105865] WARNING: at
/work/kernel/linaro/dev/kernel/sched/sched.h:534 __schedule+0x510/0x790()
[ 1.115051] Modules linked in:
[ 1.118316] [<c00159d0>] (unwind_backtrace+0x0/0x104) from
[<c054dc98>] (dump_stack+0x20/0x24)
[ 1.127227] [<c054dc98>] (dump_stack+0x20/0x24) from [<c0037f58>]
(warn_slowpath_common+0x5c/0x78)
[ 1.136535] [<c0037f58>] (warn_slowpath_common+0x5c/0x78) from
[<c0037fa0>] (warn_slowpath_null+0x2c/0x34)
[ 1.146545] [<c0037fa0>] (warn_slowpath_null+0x2c/0x34) from
[<c0560834>] (__schedule+0x510/0x790)
[ 1.155822] [<c0560834>] (__schedule+0x510/0x790) from [<c0560ba8>]
(schedule+0x40/0x80)
[ 1.164215] [<c0560ba8>] (schedule+0x40/0x80) from [<c055e288>]
(schedule_timeout+0x180/0x250)
[ 1.173156] [<c055e288>] (schedule_timeout+0x180/0x250) from
[<c05601a4>] (wait_for_common+0xb8/0x15c)
[ 1.182800] [<c05601a4>] (wait_for_common+0xb8/0x15c) from
[<c0560268>] (wait_for_completion+0x20/0x24)
[ 1.192535] [<c0560268>] (wait_for_completion+0x20/0x24) from
[<c005ce4c>] (kthread_create_on_node+0x84/0xe8)
[ 1.202819] [<c005ce4c>] (kthread_create_on_node+0x84/0xe8) from
[<c005732c>] (__alloc_workqueue_key+0x36c/0x440)
[ 1.213470] [<c005732c>] (__alloc_workqueue_key+0x36c/0x440) from
[<c052d380>] (rpc_init_mempool+0x44/0x118)
[ 1.223663] [<c052d380>] (rpc_init_mempool+0x44/0x118) from
[<c07f1714>] (init_sunrpc+0x10/0x6c)
[ 1.232757] [<c07f1714>] (init_sunrpc+0x10/0x6c) from [<c00087f0>]
(do_one_initcall+0x48/0x190)
[ 1.241790] [<c00087f0>] (do_one_initcall+0x48/0x190) from
[<c07c3988>] (do_basic_setup+0x9c/0xd0)
[ 1.251068] [<c07c3988>] (do_basic_setup+0x9c/0xd0) from [<c07c3a88>]
(kernel_init_freeable+0xcc/0x16c)
[ 1.260833] [<c07c3a88>] (kernel_init_freeable+0xcc/0x16c) from
[<c0548840>] (kernel_init+0x1c/0xf4)
[ 1.270294] [<c0548840>] (kernel_init+0x1c/0xf4) from [<c000e390>]
(ret_from_fork+0x14/0x20)
[
> +
> static inline u64 rq_clock(struct rq *rq)
> {
> + rq_clock_check(rq);
> return rq->clock;
> }
>
> static inline u64 rq_clock_task(struct rq *rq)
> {
> + rq_clock_check(rq);
> return rq->clock_task;
> }
>
> +
> #ifdef CONFIG_SMP
>
> #define rcu_dereference_check_sched_domain(p) \
>
On Wed, Mar 20, 2013 at 04:23:34PM -0700, Kevin Hilman wrote:
> Hi Frederic,
>
> On 01/07/2013 06:08 PM, Frederic Weisbecker wrote:
> > The runqueue clock is supposed to be periodically updated by the
> > tick. On full dynticks CPU we call update_nohz_rq_clock() before
> > reading it. Now the scheduler code is complicated enough that we
> > may miss some update_nohz_rq_clock() calls before reading the
> > runqueue clock.
> >
> > This therefore introduce a new debugging feature that detects
> > when the rq clock is stale due to missing updates on full
> > dynticks CPUs.
> >
> > This can be later expanded to debug stale clocks on dynticks-idle
> > CPUs.
>
> [...]
>
> > diff --git a/kernel/sched/sched.h b/kernel/sched/sched.h
> > index e1bac76..0fef0b3 100644
> > --- a/kernel/sched/sched.h
> > +++ b/kernel/sched/sched.h
> > @@ -502,16 +502,39 @@ DECLARE_PER_CPU(struct rq, runqueues);
> > #define cpu_curr(cpu) (cpu_rq(cpu)->curr)
> > #define raw_rq() (&__raw_get_cpu_var(runqueues))
> >
> > +static inline void rq_clock_check(struct rq *rq)
> > +{
> > +#if defined(CONFIG_SCHED_DEBUG) && defined(CONFIG_NO_HZ_FULL)
> > + unsigned long long clock;
> > + unsigned long flags;
> > + int cpu;
> > +
> > + cpu = cpu_of(rq);
> > + if (!tick_nohz_full_cpu(cpu) || rq->curr == rq->idle)
> > + return;
> > +
> > + local_irq_save(flags);
> > + clock = sched_clock_cpu(cpu_of(rq));
> > + local_irq_restore(flags);
> > +
> > + if (abs(clock - rq->clock) > (TICK_NSEC * 3))
> > + WARN_ON_ONCE(1);
> > +#endif
> > +}
>
> In working on the ARM port for full nohz, I'm hitting this
> warning early in the kernel boot, well before userspace starts
> (dump below[2].)
>
> I've seen a few different variations of this, but the common
> thing for all of them is the use of wait_for_completion().
>
> During boot, only swapper is running so it seems
> any waiting of sufficient length during boot will always trigger
> this warning. The hack below[1] avoids checking for the init task,
> but I'm not sure if it's the right fix.
>
> Kevin
>
> [1]
> diff --git a/kernel/sched/sched.h b/kernel/sched/sched.h
> index f96329b..56e74df 100644
> --- a/kernel/sched/sched.h
> +++ b/kernel/sched/sched.h
> @@ -512,7 +512,8 @@ static inline void rq_clock_check(struct rq *rq)
> int cpu;
>
> cpu = cpu_of(rq);
> - if (!tick_nohz_full_cpu(cpu) || rq->curr == rq->idle)
> + if (!tick_nohz_full_cpu(cpu) || rq->curr == rq->idle ||
> + is_global_init(current))
Makes sense. But we seem to be taking a new direction there after feedback from Ingo
and Peterz: tag scheduler entry and exit points and invalidate on top of missing rq clock
updates since the last scheduler entry point.
thanks.