| 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: <20161115065509.GB16821@danjae.aot.lge.com>
Date: Tue, 15 Nov 2016 15:55:09 +0900
From: Namhyung Kim <namhyung@...nel.org>
To: Ingo Molnar <mingo@...nel.org>
Cc: Arnaldo Carvalho de Melo <acme@...nel.org>,
David Ahern <dsahern@...il.com>,
Peter Zijlstra <peterz@...radead.org>,
Jiri Olsa <jolsa@...nel.org>,
LKML <linux-kernel@...r.kernel.org>,
Stephane Eranian <eranian@...gle.com>,
Andi Kleen <andi@...stfloor.org>
Subject: Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1)
Hi Ingo,
On Tue, Nov 15, 2016 at 07:42:14AM +0100, Ingo Molnar wrote:
>
> * Namhyung Kim <namhyung@...nel.org> wrote:
>
> > Hello,
> >
> > This patchset is a rebased version of David's sched timehist work [1].
> > I plan to improve perf sched command more and think that having
> > timehist command before the work looks good. It seems David is busy
> > these days, so I'm retrying it by myself.
> >
> > This implements only basic feature and a few options. I just split
> > the patch to make it easier to review and did some cosmetic changes.
> > More patches will come later.
> >
> > The below is from the David's original description:
> >
> > ------------------------8<-------------------------
> > 'perf sched timehist' provides an analysis of scheduling events.
> >
> > Example usage:
> > perf sched record -- sleep 1
> > perf sched timehist
>
>
> Cool, very nice!
:)
>
> > By default it shows the individual schedule events, including the time between
> > sched-in events for the task, the task scheduling delay (time between wakeup
> > and actually running) and run time for the task:
> >
> > time cpu task name[tid/pid] b/n time sch delay run time
> > ------------- ---- -------------------- --------- --------- ---------
> > 79371.874569 [11] gcc[31949] 0.014 0.000 1.148
> > 79371.874591 [10] gcc[31951] 0.000 0.000 0.024
> > 79371.874603 [10] migration/10[59] 3.350 0.004 0.011
> > 79371.874604 [11] <idle> 1.148 0.000 0.035
> > 79371.874723 [05] <idle> 0.016 0.000 1.383
> > 79371.874746 [05] gcc[31949] 0.153 0.078 0.022
> > ...
>
> What does the 'b/n' abbreviation stand for? 'Between'? Could we call the column
> 'sch wait' instead, or so?
Looks better, or what about 'wait time'?
>
>
> > Times are in msec.usec.
> >
> > If callchains were recorded they are appended to the line with a default stack depth of 5:
> >
> > 79371.874569 [11] gcc[31949] 0.000014 0.000000 0.001148 wait_for_completion_killable do_fork sys_vfork stub_vfork __vfork
> > 79371.874591 [10] gcc[31951] 0.000000 0.000000 0.000024 __cond_resched _cond_resched wait_for_completion stop_one_cpu sched_exec
> > 79371.874603 [10] migration/10[59] 0.003350 0.000004 0.000011 smpboot_thread_fn kthread ret_from_fork
> > 79371.874604 [11] <idle> 0.001148 0.000000 0.000035 cpu_startup_entry start_secondary
> > 79371.874723 [05] <idle> 0.000016 0.000000 0.001383 cpu_startup_entry start_secondary
> > 79371.874746 [05] gcc[31949] 0.000153 0.000078 0.000022 do_wait sys_wait4 system_call_fastpath __GI___waitpid
>
> So when I first saw this it was hard for me to disambiguate individual function
> names. Wouldn't this be a bit more readable:
>
> > 79371.874569 [11] gcc[31949] 0.000014 0.000000 0.001148 wait_for_completion_killable() <- do_fork sys_vfork stub_vfork() <- __vfork()
> > 79371.874591 [10] gcc[31951] 0.000000 0.000000 0.000024 __cond_resched() <- _cond_resched() <- wait_for_completion() <- stop_one_cpu() <- sched_exec()
> > 79371.874603 [10] migration/10[59] 0.003350 0.000004 0.000011 smpboot_thread_fn() <- kthread() <- ret_from_fork()
> > 79371.874604 [11] <idle> 0.001148 0.000000 0.000035 cpu_startup_entry() <- start_secondary()
> > 79371.874723 [05] <idle> 0.000016 0.000000 0.001383 cpu_startup_entry() <- start_secondary()
> > 79371.874746 [05] gcc[31949] 0.000153 0.000078 0.000022 do_wait() <- sys_wait4() <- system_call_fastpath() <- __GI___waitpid()
>
> Or:
>
> > 79371.874569 [11] gcc[31949] 0.000014 0.000000 0.001148 wait_for_completion_killable() <- do_fork sys_vfork stub_vfork() <- __vfork()
> > 79371.874591 [10] gcc[31951] 0.000000 0.000000 0.000024 __cond_resched() <- _cond_resched() <- wait_for_completion() <- stop_one_cpu() <- sched_exec()
> > 79371.874603 [10] migration/10[59] 0.003350 0.000004 0.000011 smpboot_thread_fn() <- kthread() <- ret_from_fork()
> > 79371.874604 [11] <idle> 0.001148 0.000000 0.000035 cpu_startup_entry() <- start_secondary()
> > 79371.874723 [05] <idle> 0.000016 0.000000 0.001383 cpu_startup_entry() <- start_secondary()
> > 79371.874746 [05] gcc[31949] 0.000153 0.000078 0.000022 do_wait() <- sys_wait4() <- system_call_fastpath() <- __GI___waitpid()
>
> (i.e. visually separate the first entry - and list the rest.)
>
> Or maybe it could be ASCII color coded so that the different entries are easier to
> separate: for example the functions could be printed in alternating white/grey
> color?
I'd go with the first option - simply adding arrows. It's good enough
to identify each function IMHO.
Thanks,
Namhyung
Powered by blists - more mailing lists