linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* [PATCH] [RFC] sched: Add trace_sched_waking() tracepoint to sched_ttwu_pending()
@ 2024-02-22 20:49 John Stultz
  2024-02-22 21:24 ` Phil Auld
  2024-02-22 22:57 ` Steven Rostedt
  0 siblings, 2 replies; 4+ messages in thread
From: John Stultz @ 2024-02-22 20:49 UTC (permalink / raw)
  To: LKML
  Cc: John Stultz, Ingo Molnar, Peter Zijlstra, Juri Lelli,
	Vincent Guittot, Dietmar Eggemann, Steven Rostedt, Ben Segall,
	Mel Gorman, Daniel Bristot de Oliveira, Valentin Schneider,
	kernel-team, Zimuzo Ezeozue

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


^ permalink raw reply related	[flat|nested] 4+ messages in thread

* Re: [PATCH] [RFC] sched: Add trace_sched_waking() tracepoint to sched_ttwu_pending()
  2024-02-22 20:49 [PATCH] [RFC] sched: Add trace_sched_waking() tracepoint to sched_ttwu_pending() John Stultz
@ 2024-02-22 21:24 ` Phil Auld
  2024-02-22 22:27   ` John Stultz
  2024-02-22 22:57 ` Steven Rostedt
  1 sibling, 1 reply; 4+ messages in thread
From: Phil Auld @ 2024-02-22 21:24 UTC (permalink / raw)
  To: John Stultz
  Cc: LKML, Ingo Molnar, Peter Zijlstra, Juri Lelli, Vincent Guittot,
	Dietmar Eggemann, Steven Rostedt, Ben Segall, Mel Gorman,
	Daniel Bristot de Oliveira, Valentin Schneider, kernel-team,
	Zimuzo Ezeozue

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
-- 


^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: [PATCH] [RFC] sched: Add trace_sched_waking() tracepoint to sched_ttwu_pending()
  2024-02-22 21:24 ` Phil Auld
@ 2024-02-22 22:27   ` John Stultz
  0 siblings, 0 replies; 4+ messages in thread
From: John Stultz @ 2024-02-22 22:27 UTC (permalink / raw)
  To: Phil Auld
  Cc: LKML, Ingo Molnar, Peter Zijlstra, Juri Lelli, Vincent Guittot,
	Dietmar Eggemann, Steven Rostedt, Ben Segall, Mel Gorman,
	Daniel Bristot de Oliveira, Valentin Schneider, kernel-team,
	Zimuzo Ezeozue

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

^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: [PATCH] [RFC] sched: Add trace_sched_waking() tracepoint to sched_ttwu_pending()
  2024-02-22 20:49 [PATCH] [RFC] sched: Add trace_sched_waking() tracepoint to sched_ttwu_pending() John Stultz
  2024-02-22 21:24 ` Phil Auld
@ 2024-02-22 22:57 ` Steven Rostedt
  1 sibling, 0 replies; 4+ messages in thread
From: Steven Rostedt @ 2024-02-22 22:57 UTC (permalink / raw)
  To: John Stultz
  Cc: LKML, Ingo Molnar, Peter Zijlstra, Juri Lelli, Vincent Guittot,
	Dietmar Eggemann, Ben Segall, Mel Gorman,
	Daniel Bristot de Oliveira, Valentin Schneider, kernel-team,
	Zimuzo Ezeozue

On 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

^ permalink raw reply	[flat|nested] 4+ messages in thread

end of thread, other threads:[~2024-02-22 22:55 UTC | newest]

Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2024-02-22 20:49 [PATCH] [RFC] sched: Add trace_sched_waking() tracepoint to sched_ttwu_pending() John Stultz
2024-02-22 21:24 ` Phil Auld
2024-02-22 22:27   ` John Stultz
2024-02-22 22:57 ` Steven Rostedt

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).