Re: [PATCH] perf: sched: Show start of latency as well

[Namhyung Kim <namhyung@kernel.org>]

Hi Joel,

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.

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).  Then the remaining concern is the screen
width (of 114 or 115?) but I think it should be fine for most of us.

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

Thanks
Namhyung

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