linux-kernel - Re: RE???[PATCH] sched: Add trace for task wake up latency and leave running time

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 for Android: free password hash cracker in your pocket

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

Message-ID: <20200915184118.211214b6@gandalf.local.home>
Date:   Tue, 15 Sep 2020 18:41:18 -0400
From:   Steven Rostedt <rostedt@...dmis.org>
To:     Mel Gorman <mgorman@...e.de>
Cc:     peterz@...radead.org, gengdongjiu <gengdongjiu@...wei.com>,
        "mingo@...hat.com" <mingo@...hat.com>,
        "juri.lelli@...hat.com" <juri.lelli@...hat.com>,
        "vincent.guittot@...aro.org" <vincent.guittot@...aro.org>,
        "dietmar.eggemann@....com" <dietmar.eggemann@....com>,
        "bsegall@...gle.com" <bsegall@...gle.com>,
        "thara.gopinath@...aro.org" <thara.gopinath@...aro.org>,
        "pauld@...hat.com" <pauld@...hat.com>,
        "vincent.donnefort@....com" <vincent.donnefort@....com>,
        "rdunlap@...radead.org" <rdunlap@...radead.org>,
        "linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>
Subject: Re: RE???[PATCH] sched: Add trace for task wake up latency and
 leave running time

On Thu, 3 Sep 2020 09:49:25 +0100
Mel Gorman <mgorman@...e.de> wrote:

> If state is to be accumulated between multiple tracepoints then the
> primary options are BPF, systemtap, trace-cmd for offline analysis or

Note, ftrace now has histograms which use the "synthetic events" that Peter
mentioned, which can give you state between two different trace points. For
example:

  # cd /sys/kernel/tracing
  # echo latency u64 lat pid_t pid int prio > synthetic_events
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
  # echo 'hist:keys=next_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).trace(latency,$lat,next_pid,next_prio) if next_prio < 100' > events/sched/sched_switch/trigger

Which will trigger the synthetic event "latency" when the sched_switch
"next_pid" matches the sched_waking "pid" only if "next_prio" is less than
100 (note lower inside the kernel means higher priority, so these are only
real time tasks).

  # echo 1 > events/synthetic/latency/enable

  # cat trace
            sshd-1049  [000] d...411  3739.316424: latency: lat=3 pid=277 prio=49
          <idle>-0     [001] d...4..  3739.316466: latency: lat=30 pid=275 prio=49
            grep-9054  [000] d...4..  3739.316564: latency: lat=3 pid=277 prio=49
            grep-9054  [000] d...411  3739.316671: latency: lat=3 pid=277 prio=49
          <idle>-0     [001] d...4..  3739.316709: latency: lat=31 pid=275 prio=49
            grep-9054  [000] d...4..  3739.316759: latency: lat=3 pid=277 prio=49
            sshd-1049  [000] d...411  3739.316835: latency: lat=4 pid=277 prio=49
          <idle>-0     [001] d...4..  3739.316893: latency: lat=50 pid=275 prio=49
            sshd-1049  [000] d...4..  3739.316968: latency: lat=4 pid=277 prio=49
            sshd-1049  [000] d...4..  3739.317082: latency: lat=6 pid=277 prio=49
          <idle>-0     [001] d...4..  3739.317115: latency: lat=29 pid=275 prio=49
            sshd-1049  [000] d...411  3739.317194: latency: lat=4 pid=277 prio=49

  # echo 'hist:keys=prio,lat:sort=lat' > events/synthetic/latency/trigger
  # cat events/synthetic/latency/hist

# event histogram
#
# trigger info: hist:keys=prio,lat:vals=hitcount:sort=lat:size=2048 [active]
#

{ prio:         98, lat:          2 } hitcount:          1
{ prio:         98, lat:          3 } hitcount:          1
{ prio:          0, lat:          3 } hitcount:          2
{ prio:         98, lat:          4 } hitcount:          1
{ prio:         98, lat:          5 } hitcount:          3
{ prio:         98, lat:          6 } hitcount:          1
{ prio:         49, lat:          8 } hitcount:          2
{ prio:         49, lat:          9 } hitcount:          1
{ prio:         49, lat:         10 } hitcount:          1
{ prio:         49, lat:         11 } hitcount:          1
{ prio:         98, lat:         22 } hitcount:          2
{ prio:         98, lat:         25 } hitcount:          1
{ prio:         49, lat:         25 } hitcount:          1
{ prio:         98, lat:         26 } hitcount:          1
{ prio:         98, lat:         28 } hitcount:          2
{ prio:         49, lat:         30 } hitcount:          2
{ prio:         49, lat:         31 } hitcount:          1
{ prio:         98, lat:         33 } hitcount:          1
{ prio:         49, lat:         34 } hitcount:          1
{ prio:         49, lat:         35 } hitcount:          1
{ prio:         49, lat:         41 } hitcount:          1
{ prio:         49, lat:         44 } hitcount:          2
{ prio:         49, lat:         54 } hitcount:          1
{ prio:          0, lat:        172 } hitcount:          1

Totals:
    Hits: 32
    Entries: 24
    Dropped: 0

Just FYI ;-)

-- Steve


> opening trace_pipe with a script, parsing the events and accumulate the
> state that way. This can lead to a concern that the script must be running
> from system start to track the data and yes, this is exactly what you
> have to do.  It's not that different to having to monitor /proc/vmstat
> over time to get some interesting vm stats as the accumulated state since
> the system started is often useless.