| 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
| ||
|
Message-ID: <20201013123308.GB1063281@kernel.org>
Date: Tue, 13 Oct 2020 09:33:08 -0300
From: Arnaldo Carvalho de Melo <acme@...nel.org>
To: Namhyung Kim <namhyung@...nel.org>
Cc: "Joel Fernandes (Google)" <joel@...lfernandes.org>,
linux-kernel <linux-kernel@...r.kernel.org>,
Alexander Shishkin <alexander.shishkin@...ux.intel.com>,
Ingo Molnar <mingo@...hat.com>, Jiri Olsa <jolsa@...hat.com>,
Mark Rutland <mark.rutland@....com>,
Peter Zijlstra <peterz@...radead.org>
Subject: Re: [PATCH] perf: sched: Show start of latency as well
Em Sat, Sep 26, 2020 at 11:10:46PM +0900, Namhyung Kim escreveu:
> Hi Joel,
>
> On Sat, Sep 26, 2020 at 8:56 AM Joel Fernandes (Google)
> <joel@...lfernandes.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@...nel.org>
Thanks, applied.
- Arnaldo
>
> Thanks
> Namhyung
>
> >
> > Signed-off-by: Joel Fernandes (Google) <joel@...lfernandes.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
--
- Arnaldo
Powered by blists - more mailing lists