kernel/sched/core.c | 1 + 1 file changed, 1 insertion(+)
Zimuzo reported seeing occasional cases in perfetto traces where
tasks went from sleeping directly to trace_sched_wakeup()
without always seeing a trace_sched_waking().
Looking at the code, trace_sched_wakeup() is only called in
ttwu_do_wakeup()
The call paths that get you to ttwu_do_wakeup() are:
try_to_wake_up() -> ttwu_do_wakeup()
try_to_wake_up() -> ttwu_runnable() -> ttwu_do_wakeup()
try_to_wake_up() -> ttwu_queue() -> ttwu_do_activate() -> ttwu_do_wakeup()
sched_ttwu_pending() -> ttwu_do_activate() -> ttwu_do_wakeup()
where trace_sched_waking() is currently called only in
try_to_wake_up().
So this patch adds a trace_sched_waking() call to
sched_ttwu_pending(), so we see the same state machine
transitions.
With this change, the number of unexpected state transitions
in perfetto was greatly reduced.
This has been in my drafts for awhile, so I wanted to send
this out for thoughts/feedback.
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Juri Lelli <juri.lelli@redhat.com>
Cc: Vincent Guittot <vincent.guittot@linaro.org>
Cc: Dietmar Eggemann <dietmar.eggemann@arm.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Ben Segall <bsegall@google.com>
Cc: Mel Gorman <mgorman@suse.de>
Cc: Daniel Bristot de Oliveira <bristot@redhat.com>
Cc: Valentin Schneider <vschneid@redhat.com>
Cc: kernel-team@android.com
Reported-by: Zimuzo Ezeozue <zezeozue@google.com>
Signed-off-by: John Stultz <jstultz@google.com>
---
kernel/sched/core.c | 1 +
1 file changed, 1 insertion(+)
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 9116bcc90346..233f06360d6a 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -3894,6 +3894,7 @@ void sched_ttwu_pending(void *arg)
if (WARN_ON_ONCE(task_cpu(p) != cpu_of(rq)))
set_task_cpu(p, cpu_of(rq));
+ trace_sched_waking(p);
ttwu_do_activate(rq, p, p->sched_remote_wakeup ? WF_MIGRATED : 0, &rf);
}
--
2.44.0.rc0.258.g7320e95886-googOn Thu, 22 Feb 2024 12:49:03 -0800
John Stultz <jstultz@google.com> wrote:
> Zimuzo reported seeing occasional cases in perfetto traces where
> tasks went from sleeping directly to trace_sched_wakeup()
> without always seeing a trace_sched_waking().
>
> Looking at the code, trace_sched_wakeup() is only called in
> ttwu_do_wakeup()
>
> The call paths that get you to ttwu_do_wakeup() are:
> try_to_wake_up() -> ttwu_do_wakeup()
> try_to_wake_up() -> ttwu_runnable() -> ttwu_do_wakeup()
> try_to_wake_up() -> ttwu_queue() -> ttwu_do_activate() -> ttwu_do_wakeup()
> sched_ttwu_pending() -> ttwu_do_activate() -> ttwu_do_wakeup()
>
> where trace_sched_waking() is currently called only in
> try_to_wake_up().
>
> So this patch adds a trace_sched_waking() call to
> sched_ttwu_pending(), so we see the same state machine
> transitions.
>
> With this change, the number of unexpected state transitions
> in perfetto was greatly reduced.
>
> This has been in my drafts for awhile, so I wanted to send
> this out for thoughts/feedback.
I just added at the same location as your trace event:
trace_printk("SCHED_WAKING %s:%d\n", p->comm, p->pid);
And then ran: trace-cmd record -e 'sched_wak*'
Where trace-cmd report gives:
kworker/0:1-10 [000] d..3. 190.212851: sched_waking: comm=kworker/7:3 pid=114 prio=120 target_cpu=007
<idle>-0 [002] d.h2. 190.212856: bprint: sched_ttwu_pending: SCHED_WAKING kworker/2:1:110
<idle>-0 [002] dNh2. 190.212861: sched_wakeup: kworker/2:1:110 [120] CPU:002
<idle>-0 [001] d.h2. 190.212911: bprint: sched_ttwu_pending: SCHED_WAKING kworker/1:1:85
<idle>-0 [003] d.h2. 190.212918: bprint: sched_ttwu_pending: SCHED_WAKING kworker/3:1:77
<idle>-0 [001] dNh2. 190.212919: sched_wakeup: kworker/1:1:85 [120] CPU:001
<idle>-0 [003] dNh2. 190.212927: sched_wakeup: kworker/3:1:77 [120] CPU:003
<idle>-0 [004] d.h2. 190.212930: bprint: sched_ttwu_pending: SCHED_WAKING kworker/4:1:115
<idle>-0 [004] dNh2. 190.212939: sched_wakeup: kworker/4:1:115 [120] CPU:004
<idle>-0 [007] d.h2. 190.212943: bprint: sched_ttwu_pending: SCHED_WAKING kworker/7:3:114
<idle>-0 [007] dNh2. 190.212952: sched_wakeup: kworker/7:3:114 [120] CPU:007
<idle>-0 [001] d.h3. 190.511970: sched_waking: comm=gmain pid=474 prio=120 target_cpu=001
<idle>-0 [001] dNh4. 190.511989: sched_wakeup: gmain:474 [120] CPU:001
<idle>-0 [006] d.s3. 190.708715: sched_waking: comm=kcompactd0 pid=70 prio=120 target_cpu=006
<idle>-0 [006] dNs4. 190.708726: sched_wakeup: kcompactd0:70 [120] CPU:006
<idle>-0 [002] d.s4. 190.916737: sched_waking: comm=kworker/2:1 pid=110 prio=120 target_cpu=002
<idle>-0 [002] dNs5. 190.916747: sched_wakeup: kworker/2:1:110 [120] CPU:002
<idle>-0 [005] d.s4. 191.044665: sched_waking: comm=kworker/5:0H pid=44 prio=100 target_cpu=005
<idle>-0 [005] dNs5. 191.044675: sched_wakeup: kworker/5:0H:44 [100] CPU:005
<idle>-0 [006] d.s3. 191.212680: sched_waking: comm=kcompactd0 pid=70 prio=120 target_cpu=006
<idle>-0 [006] dNs4. 191.212691: sched_wakeup: kcompactd0:70 [120] CPU:006
<idle>-0 [001] d.s3. 191.556713: sched_waking: comm=khugepaged pid=73 prio=139 target_cpu=001
<idle>-0 [001] dNs4. 191.556723: sched_wakeup: khugepaged:73 [139] CPU:001
<idle>-0 [001] dNs4. 191.556728: sched_waking: comm=kworker/1:1 pid=85 prio=120 target_cpu=001
Where only sched_wakeup shows the trace_printk() output but other
sched_waking events have a matching sched_wakeup event. I would say this is
a bug.
This will also cause some of my tooling to be incorrect too, as I normally
just use "sched_waking" to find wake ups :-/
-- Steve
On Thu, Feb 22, 2024 at 12:49:03PM -0800 John Stultz wrote: > Zimuzo reported seeing occasional cases in perfetto traces where > tasks went from sleeping directly to trace_sched_wakeup() > without always seeing a trace_sched_waking(). > > Looking at the code, trace_sched_wakeup() is only called in > ttwu_do_wakeup() > > The call paths that get you to ttwu_do_wakeup() are: > try_to_wake_up() -> ttwu_do_wakeup() > try_to_wake_up() -> ttwu_runnable() -> ttwu_do_wakeup() > try_to_wake_up() -> ttwu_queue() -> ttwu_do_activate() -> ttwu_do_wakeup() > sched_ttwu_pending() -> ttwu_do_activate() -> ttwu_do_wakeup() > > where trace_sched_waking() is currently called only in > try_to_wake_up(). > > So this patch adds a trace_sched_waking() call to > sched_ttwu_pending(), so we see the same state machine > transitions. > > With this change, the number of unexpected state transitions > in perfetto was greatly reduced. > > This has been in my drafts for awhile, so I wanted to send > this out for thoughts/feedback. > > Cc: Ingo Molnar <mingo@redhat.com> > Cc: Peter Zijlstra <peterz@infradead.org> > Cc: Juri Lelli <juri.lelli@redhat.com> > Cc: Vincent Guittot <vincent.guittot@linaro.org> > Cc: Dietmar Eggemann <dietmar.eggemann@arm.com> > Cc: Steven Rostedt <rostedt@goodmis.org> > Cc: Ben Segall <bsegall@google.com> > Cc: Mel Gorman <mgorman@suse.de> > Cc: Daniel Bristot de Oliveira <bristot@redhat.com> > Cc: Valentin Schneider <vschneid@redhat.com> > Cc: kernel-team@android.com > Reported-by: Zimuzo Ezeozue <zezeozue@google.com> > Signed-off-by: John Stultz <jstultz@google.com> > --- > kernel/sched/core.c | 1 + > 1 file changed, 1 insertion(+) > > diff --git a/kernel/sched/core.c b/kernel/sched/core.c > index 9116bcc90346..233f06360d6a 100644 > --- a/kernel/sched/core.c > +++ b/kernel/sched/core.c > @@ -3894,6 +3894,7 @@ void sched_ttwu_pending(void *arg) > if (WARN_ON_ONCE(task_cpu(p) != cpu_of(rq))) > set_task_cpu(p, cpu_of(rq)); > > + trace_sched_waking(p); > ttwu_do_activate(rq, p, p->sched_remote_wakeup ? WF_MIGRATED : 0, &rf); > } > > -- > 2.44.0.rc0.258.g7320e95886-goog > > This looks okay to me. Maybe s/this patch adds/add/. Otherwise the changelog is nice and complete. Reviewed-by: Phil Auld <pauld@redhat.com> Cheers, Phil --
On Thu, Feb 22, 2024 at 1:24 PM Phil Auld <pauld@redhat.com> wrote: > Maybe s/this patch adds/add/. Otherwise the changelog is nice and > complete. Ah, yes, I'm still terrible about using the imperative mood! Will fix for v2. Thanks for taking the time to look this over and to share your reviewed-by tag! -john
© 2016 - 2026 Red Hat, Inc.