From mboxrd@z Thu Jan  1 00:00:00 1970
Return-Path: <linux-kernel-owner@vger.kernel.org>
Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand
        id S1755421AbcKOG4K (ORCPT <rfc822;w@1wt.eu>);
        Tue, 15 Nov 2016 01:56:10 -0500
Received: from mail-pg0-f65.google.com ([74.125.83.65]:33362 "EHLO
        mail-pg0-f65.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org
        with ESMTP id S1750766AbcKOG4I (ORCPT
        <rfc822;linux-kernel@vger.kernel.org>);
        Tue, 15 Nov 2016 01:56:08 -0500
Date: Tue, 15 Nov 2016 15:55:09 +0900
From: Namhyung Kim <namhyung@kernel.org>
To: Ingo Molnar <mingo@kernel.org>
Cc: Arnaldo Carvalho de Melo <acme@kernel.org>,
        David Ahern <dsahern@gmail.com>, Peter Zijlstra <peterz@infradead.org>,
        Jiri Olsa <jolsa@kernel.org>, LKML <linux-kernel@vger.kernel.org>,
        Stephane Eranian <eranian@google.com>,
        Andi Kleen <andi@firstfloor.org>
Subject: Re: [PATCHSET 0/7] perf sched: Introduce timehist command, again (v1)
Message-ID: <20161115065509.GB16821@danjae.aot.lge.com>
References: <20161114161243.15403-1-namhyung@kernel.org>
 <20161115064214.GB27089@gmail.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
In-Reply-To: <20161115064214.GB27089@gmail.com>
User-Agent: Mutt/1.7.1 (2016-10-04)
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

Hi Ingo,

On Tue, Nov 15, 2016 at 07:42:14AM +0100, Ingo Molnar wrote:
> 
> * Namhyung Kim <namhyung@kernel.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