linux-kernel - Re: [PATCH] [RFC] sched: Add trace_sched_waking() tracepoint to sched_ttwu

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [day] [month] [year] [list]

Message-ID: <20240222175715.0593cb09@gandalf.local.home>
Date: Thu, 22 Feb 2024 17:57:15 -0500
From: Steven Rostedt <rostedt@...dmis.org>
To: John Stultz <jstultz@...gle.com>
Cc: LKML <linux-kernel@...r.kernel.org>, Ingo Molnar <mingo@...hat.com>,
 Peter Zijlstra <peterz@...radead.org>, Juri Lelli <juri.lelli@...hat.com>,
 Vincent Guittot <vincent.guittot@...aro.org>, Dietmar Eggemann
 <dietmar.eggemann@....com>, Ben Segall <bsegall@...gle.com>, Mel Gorman
 <mgorman@...e.de>, Daniel Bristot de Oliveira <bristot@...hat.com>,
 Valentin Schneider <vschneid@...hat.com>, kernel-team@...roid.com, Zimuzo
 Ezeozue <zezeozue@...gle.com>
Subject: Re: [PATCH] [RFC] sched: Add trace_sched_waking() tracepoint to
 sched_ttwu_pending()

On Thu, 22 Feb 2024 12:49:03 -0800
John Stultz <jstultz@...gle.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