linux-kernel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
From: Joel Fernandes <joel@joelfernandes.org>
To: Namhyung Kim <namhyung@kernel.org>
Cc: linux-kernel <linux-kernel@vger.kernel.org>,
	Alexander Shishkin <alexander.shishkin@linux.intel.com>,
	Arnaldo Carvalho de Melo <acme@kernel.org>,
	Ingo Molnar <mingo@redhat.com>, Jiri Olsa <jolsa@redhat.com>,
	Mark Rutland <mark.rutland@arm.com>,
	Peter Zijlstra <peterz@infradead.org>
Subject: Re: [PATCH] perf: sched: Show start of latency as well
Date: Sat, 26 Sep 2020 11:45:39 -0400	[thread overview]
Message-ID: <CAEXW_YQEozS_O6VQcBRzFS_t9sihV12HLZ6q=v+YFjJi8+Yprg@mail.gmail.com> (raw)
In-Reply-To: <CAM9d7ciK4w-BYLPLK7ADpB5dz83YV5Un4zG66PxPzBS=QzS9mA@mail.gmail.com>

On Sat, Sep 26, 2020 at 10:10 AM Namhyung Kim <namhyung@kernel.org> wrote:
[...]
> On Sat, Sep 26, 2020 at 8:56 AM Joel Fernandes (Google)
> <joel@joelfernandes.org> wrote:
> >
> > perf sched latency is really useful at showing worst-case latencies that task
> > encountered since wakeup. However it shows only the end of the latency. Often
> > times the start of a latency is interesting as it can show what else was going
> > on at the time to cause the latency. I certainly myself spending a lot of time
> > backtracking to the start of the latency in "perf sched script" which wastes a
> > lot of time.
> >
> > This patch therefore adds a new column "Max delay start". Considering this,
> > also rename "Maximum delay at" to "Max delay end" as its easier to understand.
>
> Oh, I thought we print start time not the end time.  I think it's better
> to print start time but others may think differently.

Right, glad you think so too.

> Actually we can calculate the start time from the end time and the
> latency but it'd be convenient if the tool does that for us (as they are
> printed in different units).

Correct, but as you mention it is more burdensome to calculate each time.

> Then the remaining concern is the screen
> width (of 114 or 115?) but I think it should be fine for most of us.

It is 114 without the patch and 140 with it. I tried my best to trim
it a little. It fits fine on my screen with the patch. So I think we
should be good!

> Acked-by: Namhyung Kim <namhyung@kernel.org>

Thanks, Namyhung!

 - Joel

> > Signed-off-by: Joel Fernandes (Google) <joel@joelfernandes.org>
> >
> >
> > ---
> > A sample output can be seen after applying patch:
> > https://hastebin.com/raw/ivinimaler
> >
> >  tools/perf/builtin-sched.c | 24 ++++++++++++++----------
> >  1 file changed, 14 insertions(+), 10 deletions(-)
> >
> > diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> > index 459e4229945e..2791da1fe5f7 100644
> > --- a/tools/perf/builtin-sched.c
> > +++ b/tools/perf/builtin-sched.c
> > @@ -130,7 +130,8 @@ struct work_atoms {
> >         struct thread           *thread;
> >         struct rb_node          node;
> >         u64                     max_lat;
> > -       u64                     max_lat_at;
> > +       u64                     max_lat_start;
> > +       u64                     max_lat_end;
> >         u64                     total_lat;
> >         u64                     nb_atoms;
> >         u64                     total_runtime;
> > @@ -1096,7 +1097,8 @@ add_sched_in_event(struct work_atoms *atoms, u64 timestamp)
> >         atoms->total_lat += delta;
> >         if (delta > atoms->max_lat) {
> >                 atoms->max_lat = delta;
> > -               atoms->max_lat_at = timestamp;
> > +               atoms->max_lat_start = atom->wake_up_time;
> > +               atoms->max_lat_end = timestamp;
> >         }
> >         atoms->nb_atoms++;
> >  }
> > @@ -1322,7 +1324,7 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
> >         int i;
> >         int ret;
> >         u64 avg;
> > -       char max_lat_at[32];
> > +       char max_lat_start[32], max_lat_end[32];
> >
> >         if (!work_list->nb_atoms)
> >                 return;
> > @@ -1344,13 +1346,14 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
> >                 printf(" ");
> >
> >         avg = work_list->total_lat / work_list->nb_atoms;
> > -       timestamp__scnprintf_usec(work_list->max_lat_at, max_lat_at, sizeof(max_lat_at));
> > +       timestamp__scnprintf_usec(work_list->max_lat_start, max_lat_start, sizeof(max_lat_start));
> > +       timestamp__scnprintf_usec(work_list->max_lat_end, max_lat_end, sizeof(max_lat_end));
> >
> > -       printf("|%11.3f ms |%9" PRIu64 " | avg:%9.3f ms | max:%9.3f ms | max at: %13s s\n",
> > +       printf("|%11.3f ms |%9" PRIu64 " | avg:%8.3f ms | max:%8.3f ms | max start: %12s s | max end: %12s s\n",
> >               (double)work_list->total_runtime / NSEC_PER_MSEC,
> >                  work_list->nb_atoms, (double)avg / NSEC_PER_MSEC,
> >                  (double)work_list->max_lat / NSEC_PER_MSEC,
> > -                max_lat_at);
> > +                max_lat_start, max_lat_end);
> >  }
> >
> >  static int pid_cmp(struct work_atoms *l, struct work_atoms *r)
> > @@ -3118,7 +3121,8 @@ static void __merge_work_atoms(struct rb_root_cached *root, struct work_atoms *d
> >                         list_splice(&data->work_list, &this->work_list);
> >                         if (this->max_lat < data->max_lat) {
> >                                 this->max_lat = data->max_lat;
> > -                               this->max_lat_at = data->max_lat_at;
> > +                               this->max_lat_start = data->max_lat_start;
> > +                               this->max_lat_end = data->max_lat_end;
> >                         }
> >                         zfree(&data);
> >                         return;
> > @@ -3157,9 +3161,9 @@ static int perf_sched__lat(struct perf_sched *sched)
> >         perf_sched__merge_lat(sched);
> >         perf_sched__sort_lat(sched);
> >
> > -       printf("\n -----------------------------------------------------------------------------------------------------------------\n");
> > -       printf("  Task                  |   Runtime ms  | Switches | Average delay ms | Maximum delay ms | Maximum delay at       |\n");
> > -       printf(" -----------------------------------------------------------------------------------------------------------------\n");
> > +       printf("\n -------------------------------------------------------------------------------------------------------------------------------------------\n");
> > +       printf("  Task                  |   Runtime ms  | Switches | Avg delay ms    | Max delay ms    | Max delay start           | Max delay end          |\n");
> > +       printf(" -------------------------------------------------------------------------------------------------------------------------------------------\n");
> >
> >         next = rb_first_cached(&sched->sorted_atom_root);
> >
> > --
> > 2.28.0.709.gb0816b6eb0-goog

  reply	other threads:[~2020-09-26 15:45 UTC|newest]

Thread overview: 7+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2020-09-25 23:56 [PATCH] perf: sched: Show start of latency as well Joel Fernandes (Google)
2020-09-26 14:10 ` Namhyung Kim
2020-09-26 15:45   ` Joel Fernandes [this message]
2020-10-13 12:37     ` Arnaldo Carvalho de Melo
2020-10-14 15:05       ` joel
2020-10-14 15:17         ` Arnaldo Carvalho de Melo
2020-10-13 12:33   ` Arnaldo Carvalho de Melo

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to='CAEXW_YQEozS_O6VQcBRzFS_t9sihV12HLZ6q=v+YFjJi8+Yprg@mail.gmail.com' \
    --to=joel@joelfernandes.org \
    --cc=acme@kernel.org \
    --cc=alexander.shishkin@linux.intel.com \
    --cc=jolsa@redhat.com \
    --cc=linux-kernel@vger.kernel.org \
    --cc=mark.rutland@arm.com \
    --cc=mingo@redhat.com \
    --cc=namhyung@kernel.org \
    --cc=peterz@infradead.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
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).