linux-kernel - Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1)

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: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <20161115064214.GB27089@gmail.com>
Date:   Tue, 15 Nov 2016 07:42:14 +0100
From:   Ingo Molnar <mingo@...nel.org>
To:     Namhyung Kim <namhyung@...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)


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


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

Thanks,

	Ingo