Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]


Groups > linux.kernel > #1251688 > unrolled thread

Re: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'

Started by"Wangnan (F)" <wangnan0@huawei.com>
First post2015-10-20 15:30 +0200
Last post2015-10-22 14:40 +0200
Articles 8 — 4 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.


Contents

  Re: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller' "Wangnan (F)" <wangnan0@huawei.com> - 2015-10-20 15:30 +0200
    Re: [PATCH 13/16] perf callchain: Switch default to  'graph,0.5,caller' Arnaldo Carvalho de Melo <acme@redhat.com> - 2015-10-20 15:40 +0200
      Re: [PATCH 13/16] perf callchain: Switch default to  'graph,0.5,caller' Namhyung Kim <namhyung@kernel.org> - 2015-10-21 03:50 +0200
      Re: [PATCH 13/16] perf callchain: Switch default to  'graph,0.5,caller' Ingo Molnar <mingo@kernel.org> - 2015-10-21 10:50 +0200
        Re: [PATCH 13/16] perf callchain: Switch default to  'graph,0.5,caller' Arnaldo Carvalho de Melo <acme@redhat.com> - 2015-10-21 15:50 +0200
          Re: [PATCH 13/16] perf callchain: Switch default to  'graph,0.5,caller' Arnaldo Carvalho de Melo <acme@redhat.com> - 2015-10-21 15:50 +0200
          Re: [PATCH 13/16] perf callchain: Switch default to  'graph,0.5,caller' Ingo Molnar <mingo@kernel.org> - 2015-10-22 10:50 +0200
            Re: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller' Namhyung Kim <namhyung@kernel.org> - 2015-10-22 14:40 +0200

#1251688 — Re: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'

From"Wangnan (F)" <wangnan0@huawei.com>
Date2015-10-20 15:30 +0200
SubjectRe: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'
Message-ID<qlF9h-4YG-39@gated-at.bofh.it>
Hi Arnaldo,

On 2015/10/6 5:03, Arnaldo Carvalho de Melo wrote:
> From: Arnaldo Carvalho de Melo <acme@redhat.com>
>
> Which is the most common default found in other similar tools.

Could you please show me some example about "other similar tools"?
For me, in most of the case I prefer callee order because most of my
task is to explain the reason why some code get executed too much times
than expected.

Also, I think changing default settings should be careful.

This is my story: after switching to new version of perf, in a period of
time there are plenty of perf users in my company be confused by the
first column of 'perf report' because the sum of the percentage listed
there is much higher than 100%. They find me because they think this is
a bug in perf which breaks their routinely profiling work.  The
"problem" is caused by the adding of "--children". New perf makes
'--children' as the default behavior at the first time it support that
option, but the old perf shows things similar to '--no-children'.
However, it is hard to explain the principle of call stack accumulation
and why we need '--children' to those perf users (they learned perf's
command line from others, and don't have enought to read perf
documentations or even help output. Althought the title of the first
column is changed to 'Children', I don't think they can understand the
meaning of it. I think some of them didn't even notice there's an
addition column in their output. They just confused and angry). Also,
and as you can expect, this change breaks some scripts. In those days I
have to make our IM tool response the information of "--no-children"
automatically.

This patch changes the default output again. Similar thing will happen
another time. I think this time I can make some preparation, for example,
prepare new script to restore old behavior?

Thank you.

> Requested-by: Ingo Molnar <mingo@kernel.org>
> Cc: Adrian Hunter <adrian.hunter@intel.com>
> Cc: Borislav Petkov <bp@suse.de>
> Cc: Chandler Carruth <chandlerc@gmail.com>
> Cc: David Ahern <dsahern@gmail.com>
> Cc: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: Jiri Olsa <jolsa@redhat.com>
> Cc: Namhyung Kim <namhyung@kernel.org>
> Cc: Stephane Eranian <eranian@google.com>
> Cc: Wang Nan <wangnan0@huawei.com>
> Link: https://www.youtube.com/watch?v=nXaxk27zwlk
> Link: http://lkml.kernel.org/n/tip-v8lq36aispvdwgxdmt9p9jd9@git.kernel.org
> Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> ---
>   tools/perf/Documentation/perf-report.txt | 2 +-
>   tools/perf/builtin-report.c              | 4 ++--
>   tools/perf/util/util.c                   | 4 ++--
>   3 files changed, 5 insertions(+), 5 deletions(-)
>
> diff --git a/tools/perf/Documentation/perf-report.txt b/tools/perf/Documentation/perf-report.txt
> index ce499035e6d8..e4fdeeb51123 100644
> --- a/tools/perf/Documentation/perf-report.txt
> +++ b/tools/perf/Documentation/perf-report.txt
> @@ -192,7 +192,7 @@ OPTIONS
>   	when available. Usually more convenient to use --branch-history
>   	for this.
>   
> -	Default: fractal,0.5,callee,function.
> +	Default: graph,0.5,caller
>   
>   --children::
>   	Accumulate callchain of children to parent entry so that then can
> diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
> index b5623639f67d..3b23b25d1589 100644
> --- a/tools/perf/builtin-report.c
> +++ b/tools/perf/builtin-report.c
> @@ -633,7 +633,7 @@ int cmd_report(int argc, const char **argv, const char *prefix __maybe_unused)
>   	bool has_br_stack = false;
>   	int branch_mode = -1;
>   	bool branch_call_mode = false;
> -	char callchain_default_opt[] = "fractal,0.5,callee";
> +	char callchain_default_opt[] = "graph,0.5,caller";
>   	const char * const report_usage[] = {
>   		"perf report [<options>]",
>   		NULL
> @@ -701,7 +701,7 @@ int cmd_report(int argc, const char **argv, const char *prefix __maybe_unused)
>   		    "Only display entries with parent-match"),
>   	OPT_CALLBACK_DEFAULT('g', "call-graph", &report, "output_type,min_percent[,print_limit],call_order[,branch]",
>   		     "Display callchains using output_type (graph, flat, fractal, or none) , min percent threshold, optional print limit, callchain order, key (function or address), add branches. "
> -		     "Default: fractal,0.5,callee,function", &report_parse_callchain_opt, callchain_default_opt),
> +		     "Default: graph,0.5,caller", &report_parse_callchain_opt, callchain_default_opt),
>   	OPT_BOOLEAN(0, "children", &symbol_conf.cumulate_callchain,
>   		    "Accumulate callchains of children and show total overhead as well"),
>   	OPT_INTEGER(0, "max-stack", &report.max_stack,
> diff --git a/tools/perf/util/util.c b/tools/perf/util/util.c
> index ce465b259e52..c1bf9ff210b0 100644
> --- a/tools/perf/util/util.c
> +++ b/tools/perf/util/util.c
> @@ -17,9 +17,9 @@
>   #include "callchain.h"
>   
>   struct callchain_param	callchain_param = {
> -	.mode	= CHAIN_GRAPH_REL,
> +	.mode	= CHAIN_GRAPH_ABS,
>   	.min_percent = 0.5,
> -	.order  = ORDER_CALLEE,
> +	.order  = ORDER_CALLER,
>   	.key	= CCKEY_FUNCTION
>   };
>   


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [next] | [standalone]


#1251697 — Re: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'

FromArnaldo Carvalho de Melo <acme@redhat.com>
Date2015-10-20 15:40 +0200
SubjectRe: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'
Message-ID<qlFiW-59E-15@gated-at.bofh.it>
In reply to#1251688
Em Tue, Oct 20, 2015 at 09:23:12PM +0800, Wangnan (F) escreveu:
> On 2015/10/6 5:03, Arnaldo Carvalho de Melo wrote:
> >From: Arnaldo Carvalho de Melo <acme@redhat.com>
> >Which is the most common default found in other similar tools.
 
> Could you please show me some example about "other similar tools"?
> For me, in most of the case I prefer callee order because most of my
> task is to explain the reason why some code get executed too much times
> than expected.
 
> Also, I think changing default settings should be careful.
 
> This is my story: after switching to new version of perf, in a period of
> time there are plenty of perf users in my company be confused by the
> first column of 'perf report' because the sum of the percentage listed
> there is much higher than 100%. They find me because they think this is
> a bug in perf which breaks their routinely profiling work.  The
> "problem" is caused by the adding of "--children". New perf makes
> '--children' as the default behavior at the first time it support that
> option, but the old perf shows things similar to '--no-children'.
> However, it is hard to explain the principle of call stack accumulation
> and why we need '--children' to those perf users (they learned perf's
> command line from others, and don't have enought to read perf
> documentations or even help output. Althought the title of the first
> column is changed to 'Children', I don't think they can understand the
> meaning of it. I think some of them didn't even notice there's an
> addition column in their output. They just confused and angry). Also,
> and as you can expect, this change breaks some scripts. In those days I
> have to make our IM tool response the information of "--no-children"
> automatically.
> 
> This patch changes the default output again. Similar thing will happen
> another time. I think this time I can make some preparation, for example,
> prepare new script to restore old behavior?

I was bitten by the --children thing and took some time to get used to
it, so I can relate to that...

I think we should revert this change in callchain default, enough
complaints...  Ingo, since you suggested that change, what are your
thoughts?

Changing defaults is hard, there is also the horizontal scrolling that
made we repurpose the right and left arrows, sigh, that one will cause
some confusion as well...

It seems we'll need way more preparation for such changes, more
infrastructure to ease the transition, questioning if the user wants
that, etc, growing pains :-\

- Arnaldo
 
> Thank you.
> 
> >Requested-by: Ingo Molnar <mingo@kernel.org>
> >Cc: Adrian Hunter <adrian.hunter@intel.com>
> >Cc: Borislav Petkov <bp@suse.de>
> >Cc: Chandler Carruth <chandlerc@gmail.com>
> >Cc: David Ahern <dsahern@gmail.com>
> >Cc: Frederic Weisbecker <fweisbec@gmail.com>
> >Cc: Jiri Olsa <jolsa@redhat.com>
> >Cc: Namhyung Kim <namhyung@kernel.org>
> >Cc: Stephane Eranian <eranian@google.com>
> >Cc: Wang Nan <wangnan0@huawei.com>
> >Link: https://www.youtube.com/watch?v=nXaxk27zwlk
> >Link: http://lkml.kernel.org/n/tip-v8lq36aispvdwgxdmt9p9jd9@git.kernel.org
> >Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> >---
> >  tools/perf/Documentation/perf-report.txt | 2 +-
> >  tools/perf/builtin-report.c              | 4 ++--
> >  tools/perf/util/util.c                   | 4 ++--
> >  3 files changed, 5 insertions(+), 5 deletions(-)
> >
> >diff --git a/tools/perf/Documentation/perf-report.txt b/tools/perf/Documentation/perf-report.txt
> >index ce499035e6d8..e4fdeeb51123 100644
> >--- a/tools/perf/Documentation/perf-report.txt
> >+++ b/tools/perf/Documentation/perf-report.txt
> >@@ -192,7 +192,7 @@ OPTIONS
> >  	when available. Usually more convenient to use --branch-history
> >  	for this.
> >-	Default: fractal,0.5,callee,function.
> >+	Default: graph,0.5,caller
> >  --children::
> >  	Accumulate callchain of children to parent entry so that then can
> >diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
> >index b5623639f67d..3b23b25d1589 100644
> >--- a/tools/perf/builtin-report.c
> >+++ b/tools/perf/builtin-report.c
> >@@ -633,7 +633,7 @@ int cmd_report(int argc, const char **argv, const char *prefix __maybe_unused)
> >  	bool has_br_stack = false;
> >  	int branch_mode = -1;
> >  	bool branch_call_mode = false;
> >-	char callchain_default_opt[] = "fractal,0.5,callee";
> >+	char callchain_default_opt[] = "graph,0.5,caller";
> >  	const char * const report_usage[] = {
> >  		"perf report [<options>]",
> >  		NULL
> >@@ -701,7 +701,7 @@ int cmd_report(int argc, const char **argv, const char *prefix __maybe_unused)
> >  		    "Only display entries with parent-match"),
> >  	OPT_CALLBACK_DEFAULT('g', "call-graph", &report, "output_type,min_percent[,print_limit],call_order[,branch]",
> >  		     "Display callchains using output_type (graph, flat, fractal, or none) , min percent threshold, optional print limit, callchain order, key (function or address), add branches. "
> >-		     "Default: fractal,0.5,callee,function", &report_parse_callchain_opt, callchain_default_opt),
> >+		     "Default: graph,0.5,caller", &report_parse_callchain_opt, callchain_default_opt),
> >  	OPT_BOOLEAN(0, "children", &symbol_conf.cumulate_callchain,
> >  		    "Accumulate callchains of children and show total overhead as well"),
> >  	OPT_INTEGER(0, "max-stack", &report.max_stack,
> >diff --git a/tools/perf/util/util.c b/tools/perf/util/util.c
> >index ce465b259e52..c1bf9ff210b0 100644
> >--- a/tools/perf/util/util.c
> >+++ b/tools/perf/util/util.c
> >@@ -17,9 +17,9 @@
> >  #include "callchain.h"
> >  struct callchain_param	callchain_param = {
> >-	.mode	= CHAIN_GRAPH_REL,
> >+	.mode	= CHAIN_GRAPH_ABS,
> >  	.min_percent = 0.5,
> >-	.order  = ORDER_CALLEE,
> >+	.order  = ORDER_CALLER,
> >  	.key	= CCKEY_FUNCTION
> >  };
> 
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]


#1252413 — Re: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'

FromNamhyung Kim <namhyung@kernel.org>
Date2015-10-21 03:50 +0200
SubjectRe: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'
Message-ID<qlQHp-4T6-19@gated-at.bofh.it>
In reply to#1251697
On Tue, Oct 20, 2015 at 11:38:16AM -0200, Arnaldo Carvalho de Melo wrote:
> Em Tue, Oct 20, 2015 at 09:23:12PM +0800, Wangnan (F) escreveu:
> > On 2015/10/6 5:03, Arnaldo Carvalho de Melo wrote:
> > >From: Arnaldo Carvalho de Melo <acme@redhat.com>
> > >Which is the most common default found in other similar tools.
>  
> > Could you please show me some example about "other similar tools"?
> > For me, in most of the case I prefer callee order because most of my
> > task is to explain the reason why some code get executed too much times
> > than expected.
>  
> > Also, I think changing default settings should be careful.
>  
> > This is my story: after switching to new version of perf, in a period of
> > time there are plenty of perf users in my company be confused by the
> > first column of 'perf report' because the sum of the percentage listed
> > there is much higher than 100%. They find me because they think this is
> > a bug in perf which breaks their routinely profiling work.  The
> > "problem" is caused by the adding of "--children". New perf makes
> > '--children' as the default behavior at the first time it support that
> > option, but the old perf shows things similar to '--no-children'.
> > However, it is hard to explain the principle of call stack accumulation
> > and why we need '--children' to those perf users (they learned perf's
> > command line from others, and don't have enought to read perf
> > documentations or even help output. Althought the title of the first
> > column is changed to 'Children', I don't think they can understand the
> > meaning of it. I think some of them didn't even notice there's an
> > addition column in their output. They just confused and angry). Also,
> > and as you can expect, this change breaks some scripts. In those days I
> > have to make our IM tool response the information of "--no-children"
> > automatically.
> > 
> > This patch changes the default output again. Similar thing will happen
> > another time. I think this time I can make some preparation, for example,
> > prepare new script to restore old behavior?
> 
> I was bitten by the --children thing and took some time to get used to
> it, so I can relate to that...

I feel sorry about that.  I did worry about the existing users when
making the --children default and actually I didn't agree with making
it default at first. :-(


> 
> I think we should revert this change in callchain default, enough
> complaints...  Ingo, since you suggested that change, what are your
> thoughts?
> 
> Changing defaults is hard, there is also the horizontal scrolling that
> made we repurpose the right and left arrows, sigh, that one will cause
> some confusion as well...

Yeah, it worries me too.  That's why I used '<' and '>' key for
scrolling in my patch.  Maybe it's worth adding those keys again,
reverting arrows key actions, and show some message that it'll be
changed later?


> 
> It seems we'll need way more preparation for such changes, more
> infrastructure to ease the transition, questioning if the user wants
> that, etc, growing pains :-\

Yes, it reminds me of changing default push behavior in git 2.0.  We
need to provide info and wait for enough time before changing some
behavior IMHO.

Thanks,
Namhyung
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]


#1252568 — Re: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'

FromIngo Molnar <mingo@kernel.org>
Date2015-10-21 10:50 +0200
SubjectRe: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'
Message-ID<qlXfQ-6bq-9@gated-at.bofh.it>
In reply to#1251697
* Arnaldo Carvalho de Melo <acme@redhat.com> wrote:

> I was bitten by the --children thing and took some time to get used to it, so I 
> can relate to that...
> 
> I think we should revert this change in callchain default, enough complaints...  
> Ingo, since you suggested that change, what are your thoughts?

Btw., one side note, I noticed that the call-graph options to 'perf top' do not 
match that of perf report. I tried for a couple of minutes to figure out why this 
doesn't work:

  perf top -g graph,0.5,caller

... only to notice that it's perf report options.

A couple of thoughts about defaults:

1)

I think 'perf top' and 'perf report' should provide the very same output by 
default. The two tools are unified, and we should think of 'perf top' more of a 
rolling, continuously updated perf report, with some dynamic runtime features that 
go beyond a simple perf report. Making them diverge only creates confusion.

2) min-percentage

I suspect the '0.5%' part of the default is not contested by anyone?

3) 'graph' vs. 'fractal'

The 'graph' part of the default: I think 'graph' (absolute percentages) is more 
intuitive in general than 'fractal' (relative percentages), especially when 
drilling down deep into more complex call graphs.

For example, if you look at this output:

                    |          |          |          |--41.61%-- local_apic_timer_interrupt
                    |          |          |          |          |          
                    |          |          |          |           --100.00%-- hrtimer_interrupt
                    |          |          |          |                     __run_hrtimer
                    |          |          |          |                     |          
                    |          |          |          |                     |--72.98%-- hrtimer_wakeup
                    |          |          |          |                     |          wake_up_process
                    |          |          |          |                     |          |          
                    |          |          |          |                     |           --100.00%-- try_to_wake_up
                    |          |          |          |                     |                     ttwu_do_activate.constprop.93
                    |          |          |          |                     |                     activate_task
                    |          |          |          |                     |                     enqueue_task
                    |          |          |          |                     |                     enqueue_task_fair
                    |          |          |          |                     |                     enqueue_entity
                    |          |          |          |                     |          
                    |          |          |          |                      --27.02%-- ehci_hrtimer_func

Would you have guessed that its relevance in reality is:

                    |          |          |          |          
                    |          |          |          |--0.11%-- local_apic_timer_interrupt
                    |          |          |          |          |          
                    |          |          |          |           --0.10%-- hrtimer_interrupt
                    |          |          |          |                     __run_hrtimer
                    |          |          |          |                     |          
                    |          |          |          |                     |--0.07%-- hrtimer_wakeup
                    |          |          |          |                     |          wake_up_process
                    |          |          |          |                     |          |          
                    |          |          |          |                     |           --0.01%-- try_to_wake_up
                    |          |          |          |                     |                     ttwu_do_activate.constprop.93
                    |          |          |          |                     |                     activate_task
                    |          |          |          |                     |                     enqueue_task
                    |          |          |          |                     |                     enqueue_task_fair
                    |          |          |          |                     |                     enqueue_entity
                    |          |          |          |                     |          
                    |          |          |          |                      --0.03%-- ehci_hrtimer_func
                    |          |          |          |          

?

I think the 'big picture' should always be apparent, even when looking at a small 
detail. Also, it's not _that_ hard to see the relative weight of each entry even 
if they are small numbers.

Fractal output can be useful if you are trying to drill down really, really deep 
and only concentrate on that aspect - but that kind of workflow is probably best 
served via a search option in any case:

  perf report --call-graph fractal,0.5,caller --stdio --symbol-filter local_apic_timer_interrupt

In which case fractal output is the more intuitive one I suspect:

  # To display the perf.data header info, please use --header/--header-only options.
  #
  #
  # Total Lost Samples: 0
  #
  # Samples: 1K of event 'cycles:pp'
  # Event count (approx.): 1155803425
  #
  # Children      Self  Command  Shared Object      Symbol                        
  # ........  ........  .......  .................  ..............................
  #
     0.11%     0.01%  swapper  [kernel.kallsyms]  [k] local_apic_timer_interrupt
            |          
            |--89.19%-- local_apic_timer_interrupt
            |          hrtimer_interrupt
            |          __run_hrtimer
            |          |          
            |          |--72.98%-- hrtimer_wakeup
            |          |          wake_up_process
            |          |          |          
            |          |           --100.00%-- try_to_wake_up
            |          |                     ttwu_do_activate.constprop.93
            |          |                     activate_task
            |          |                     enqueue_task
            |          |                     enqueue_task_fair
            |          |                     enqueue_entity
            |          |          
            |           --27.02%-- ehci_hrtimer_func
            |          
             --10.81%-- start_secondary
                       cpu_startup_entry
                       cpuidle_enter
                       apic_timer_interrupt
                       smp_apic_timer_interrupt
                       local_apic_timer_interrupt



  #
  # (For a higher level overview, try: perf report --sort comm,dso)
  #

Btw., I noticed an oddity, why doesn't "-S local_apic_timer_interrupt" produce any 
output? It was the first option I tried, and it only gave me:

  triton:~/tip> perf report --call-graph fractal,0.5,caller --stdio -S local_apic_timer_interrupt
  [nv] with build id 744b5b4279152a54e61208989daf5d3d6b375aa3 not found, continuing without symbols
  Failed to open /tmp/perf-6650.map, continuing without symbols
  # To display the perf.data header info, please use --header/--header-only options.
  #
  # symbol: local_apic_timer_interrupt
  #
  # Total Lost Samples: 0
  #
  # Samples: 1K of event 'cycles:pp'
  # Event count (approx.): 1155803425
  #
  # Children      Self  Command  Shared Object
  # ........  ........  .......  .............
  #


  #
  # (For a higher level overview, try: perf report --sort comm,dso)
  #

some symbols could not be found - but the output is pretty confusing and 
misleading in outputing just empty headers, plus it doesn't explain why it does 
so.

4) 'caller' vs. 'callee'.

If I change 'caller' to 'callee' in the above example, I get this output:

  triton:~/tip> perf report --call-graph fractal,0.5,callee --stdio --symbol-filter local_apic_timer_interrupt
  [nv] with build id 744b5b4279152a54e61208989daf5d3d6b375aa3 not found, continuing without symbols
  Failed to open /tmp/perf-6650.map, continuing without symbols
  # To display the perf.data header info, please use --header/--header-only options.
  #
  #
  # Total Lost Samples: 0
  #
  # Samples: 1K of event 'cycles:pp'
  # Event count (approx.): 1155803425
  #
  # Children      Self  Command  Shared Object      Symbol                        
  # ........  ........  .......  .................  ..............................
  #
       0.11%     0.01%  swapper  [kernel.kallsyms]  [k] local_apic_timer_interrupt
              |
              ---local_apic_timer_interrupt
                 smp_apic_timer_interrupt
                 apic_timer_interrupt
                 cpuidle_enter
                 cpu_startup_entry
                 start_secondary



  #
  # (For a higher level overview, try: perf report --sort comm,dso)
  #

That does not look very helpful, does it?

Now I tried to test caller vs. callee in perf top - but couldn't find a command 
line option to do it - is there any?

5) --no-children

I agree that 'perf top -g --no-children' looks more intuitive than 'perf top -g'.

Thanks,

	Ingo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]


#1252836 — Re: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'

FromArnaldo Carvalho de Melo <acme@redhat.com>
Date2015-10-21 15:50 +0200
SubjectRe: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'
Message-ID<qm1Wa-4CG-19@gated-at.bofh.it>
In reply to#1252568
Em Wed, Oct 21, 2015 at 10:48:16AM +0200, Ingo Molnar escreveu:
> 
> * Arnaldo Carvalho de Melo <acme@redhat.com> wrote:
> 
> > I was bitten by the --children thing and took some time to get used to it, so I 
> > can relate to that...
> > 
> > I think we should revert this change in callchain default, enough complaints...  
> > Ingo, since you suggested that change, what are your thoughts?
> 
> Btw., one side note, I noticed that the call-graph options to 'perf top' do not 
> match that of perf report. I tried for a couple of minutes to figure out why this 
> doesn't work:
> 
>   perf top -g graph,0.5,caller
> 
> ... only to notice that it's perf report options.

Right, 'perf top' needs 'record' and 'report' knobs, so, for -g, it uses
the 'record' semantics where its parameters specify how to _collect_ the
callchains, not how to _present_ them, i.e.:

perf report:
    -g, --call-graph <output_type,min_percent[,print_limit],call_order[,branch]>
                  Display callchains using output_type (graph, flat, fractal or
                  none) , min percent threshold, optional print limit, callchain
                  order, key (function or address), add branches.
		  Default: graph,0.5,caller

perf record:

    -g            enables call-graph recording
        --call-graph <mode[,dump_size]>
                  setup and enables call-graph (stack chain/backtrace)
                  recording: fp dwarf lbr

perf top:
    -g            enables call-graph recording
        --call-graph <mode[,dump_size]>
                  setup and enables call-graph (stack chain/backtrace)
                  recording: fp dwarf lbr

Possibly we could make it smart and accept both cases, interpreting
'report' like parameters if starting with one of (graph, flat, fractal
or none) having as a separator one of (fp, dwarf or lbr).

This way one could specify both how to collect and how to present
callchains in one --call-graph call.
 
> A couple of thoughts about defaults:
> 
> 1)
> 
> I think 'perf top' and 'perf report' should provide the very same output by 
> default. The two tools are unified, and we should think of 'perf top' more of a 
> rolling, continuously updated perf report, with some dynamic runtime features that 
> go beyond a simple perf report. Making them diverge only creates confusion.

That is the idea, now with 'f' (Enable/Disable events) in the TUI it is
one step closer to that, i.e. it moves to/from top/dynamic to/from
report/static,we need more code to ask it to start collecting into a
perf.data so that it gets 'record', but the general idea is to have it
all integrated.

> 2) min-percentage
> 
> I suspect the '0.5%' part of the default is not contested by anyone?
> 
> 3) 'graph' vs. 'fractal'
> 
> The 'graph' part of the default: I think 'graph' (absolute percentages) is more 
> intuitive in general than 'fractal' (relative percentages), especially when 
> drilling down deep into more complex call graphs.

Here I'm more worried about polishing the invalid entries in callchains
so that we can have sane caller based output.

With some work we could go to/from caller/callee without a huge impact,
i.e. without the need to reprocess everything.
 
> For example, if you look at this output:
> 
>                     |          |          |          |--41.61%-- local_apic_timer_interrupt
>                     |          |          |          |          |          
>                     |          |          |          |           --100.00%-- hrtimer_interrupt
>                     |          |          |          |                     __run_hrtimer
>                     |          |          |          |                     |          
>                     |          |          |          |                     |--72.98%-- hrtimer_wakeup
>                     |          |          |          |                     |          wake_up_process
>                     |          |          |          |                     |          |          
>                     |          |          |          |                     |           --100.00%-- try_to_wake_up
>                     |          |          |          |                     |                     ttwu_do_activate.constprop.93
>                     |          |          |          |                     |                     activate_task
>                     |          |          |          |                     |                     enqueue_task
>                     |          |          |          |                     |                     enqueue_task_fair
>                     |          |          |          |                     |                     enqueue_entity
>                     |          |          |          |                     |          
>                     |          |          |          |                      --27.02%-- ehci_hrtimer_func
> 
> Would you have guessed that its relevance in reality is:
> 
>                     |          |          |          |          
>                     |          |          |          |--0.11%-- local_apic_timer_interrupt
>                     |          |          |          |          |          
>                     |          |          |          |           --0.10%-- hrtimer_interrupt
>                     |          |          |          |                     __run_hrtimer
>                     |          |          |          |                     |          
>                     |          |          |          |                     |--0.07%-- hrtimer_wakeup
>                     |          |          |          |                     |          wake_up_process
>                     |          |          |          |                     |          |          
>                     |          |          |          |                     |           --0.01%-- try_to_wake_up
>                     |          |          |          |                     |                     ttwu_do_activate.constprop.93
>                     |          |          |          |                     |                     activate_task
>                     |          |          |          |                     |                     enqueue_task
>                     |          |          |          |                     |                     enqueue_task_fair
>                     |          |          |          |                     |                     enqueue_entity
>                     |          |          |          |                     |          
>                     |          |          |          |                      --0.03%-- ehci_hrtimer_func
>                     |          |          |          |          
> 
> ?
> 
> I think the 'big picture' should always be apparent, even when looking at a small 
> detail. Also, it's not _that_ hard to see the relative weight of each entry even 
> if they are small numbers.
> 
> Fractal output can be useful if you are trying to drill down really, really deep 
> and only concentrate on that aspect - but that kind of workflow is probably best 
> served via a search option in any case:
> 
>   perf report --call-graph fractal,0.5,caller --stdio --symbol-filter local_apic_timer_interrupt
> 
> In which case fractal output is the more intuitive one I suspect:
> 
>   # To display the perf.data header info, please use --header/--header-only options.
>   #
>   #
>   # Total Lost Samples: 0
>   #
>   # Samples: 1K of event 'cycles:pp'
>   # Event count (approx.): 1155803425
>   #
>   # Children      Self  Command  Shared Object      Symbol                        
>   # ........  ........  .......  .................  ..............................
>   #
>      0.11%     0.01%  swapper  [kernel.kallsyms]  [k] local_apic_timer_interrupt
>             |          
>             |--89.19%-- local_apic_timer_interrupt
>             |          hrtimer_interrupt
>             |          __run_hrtimer
>             |          |          
>             |          |--72.98%-- hrtimer_wakeup
>             |          |          wake_up_process
>             |          |          |          
>             |          |           --100.00%-- try_to_wake_up
>             |          |                     ttwu_do_activate.constprop.93
>             |          |                     activate_task
>             |          |                     enqueue_task
>             |          |                     enqueue_task_fair
>             |          |                     enqueue_entity
>             |          |          
>             |           --27.02%-- ehci_hrtimer_func
>             |          
>              --10.81%-- start_secondary
>                        cpu_startup_entry
>                        cpuidle_enter
>                        apic_timer_interrupt
>                        smp_apic_timer_interrupt
>                        local_apic_timer_interrupt
> 
> 
> 
>   #
>   # (For a higher level overview, try: perf report --sort comm,dso)
>   #
> 
> Btw., I noticed an oddity, why doesn't "-S local_apic_timer_interrupt" produce any 
> output? It was the first option I tried, and it only gave me:

I'll check that
 
>   triton:~/tip> perf report --call-graph fractal,0.5,caller --stdio -S local_apic_timer_interrupt
>   [nv] with build id 744b5b4279152a54e61208989daf5d3d6b375aa3 not found, continuing without symbols
>   Failed to open /tmp/perf-6650.map, continuing without symbols
>   # To display the perf.data header info, please use --header/--header-only options.
>   #
>   # symbol: local_apic_timer_interrupt
>   #
>   # Total Lost Samples: 0
>   #
>   # Samples: 1K of event 'cycles:pp'
>   # Event count (approx.): 1155803425
>   #
>   # Children      Self  Command  Shared Object
>   # ........  ........  .......  .............
>   #
> 
> 
>   #
>   # (For a higher level overview, try: perf report --sort comm,dso)
>   #
> 
> some symbols could not be found - but the output is pretty confusing and 
> misleading in outputing just empty headers, plus it doesn't explain why it does 
> so.

Needs fixing, will check
 
> 4) 'caller' vs. 'callee'.
> 
> If I change 'caller' to 'callee' in the above example, I get this output:
> 
>   triton:~/tip> perf report --call-graph fractal,0.5,callee --stdio --symbol-filter local_apic_timer_interrupt
>   [nv] with build id 744b5b4279152a54e61208989daf5d3d6b375aa3 not found, continuing without symbols
>   Failed to open /tmp/perf-6650.map, continuing without symbols
>   # To display the perf.data header info, please use --header/--header-only options.
>   #
>   #
>   # Total Lost Samples: 0
>   #
>   # Samples: 1K of event 'cycles:pp'
>   # Event count (approx.): 1155803425
>   #
>   # Children      Self  Command  Shared Object      Symbol                        
>   # ........  ........  .......  .................  ..............................
>   #
>        0.11%     0.01%  swapper  [kernel.kallsyms]  [k] local_apic_timer_interrupt
>               |
>               ---local_apic_timer_interrupt
>                  smp_apic_timer_interrupt
>                  apic_timer_interrupt
>                  cpuidle_enter
>                  cpu_startup_entry
>                  start_secondary
> 
> 
> 
>   #
>   # (For a higher level overview, try: perf report --sort comm,dso)
>   #
> 
> That does not look very helpful, does it?
> 
> Now I tried to test caller vs. callee in perf top - but couldn't find a command 
> line option to do it - is there any?
> 
> 5) --no-children
> 
> I agree that 'perf top -g --no-children' looks more intuitive than 'perf top -g'.

So, what do you propose, to switch back the default to --no-children,
for both tools, top and report? Now that I am getting used to it... ;-)

- Arnaldo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]


#1252838 — Re: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'

FromArnaldo Carvalho de Melo <acme@redhat.com>
Date2015-10-21 15:50 +0200
SubjectRe: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'
Message-ID<qm1Wb-4CG-33@gated-at.bofh.it>
In reply to#1252836
Em Wed, Oct 21, 2015 at 10:43:48AM -0300, Arnaldo Carvalho de Melo escreveu:
> Em Wed, Oct 21, 2015 at 10:48:16AM +0200, Ingo Molnar escreveu:
> > 5) --no-children
> > 
> > I agree that 'perf top -g --no-children' looks more intuitive than 'perf top -g'.
> 
> So, what do you propose, to switch back the default to --no-children,
> for both tools, top and report? Now that I am getting used to it... ;-)

And for this one, having a hotkey to toggle children/no-children, in
'top', using a big hammer (perhaps the only one possible since we have
no perf.data file?) we could just trow away the existing hist_entries,
and flip the relevant flag, the new samples would then use the new mode,
etc.

For 'report' it would involve, at first sight, reprocessing everything,
possibly saving some work because we already did symbol resolution, etc,
i.e. the struct machine with its threads, etc will be all there.

- Arnaldo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]


#1253590 — Re: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'

FromIngo Molnar <mingo@kernel.org>
Date2015-10-22 10:50 +0200
SubjectRe: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'
Message-ID<qmjJn-5wE-3@gated-at.bofh.it>
In reply to#1252836
* Arnaldo Carvalho de Melo <acme@redhat.com> wrote:

> > 5) --no-children
> > 
> > I agree that 'perf top -g --no-children' looks more intuitive than 'perf top -g'.
> 
> So, what do you propose, to switch back the default to --no-children, for both 
> tools, top and report? Now that I am getting used to it... ;-)

Heh ;-) So I'm only thinking out loud, trying to find the most intuitive initial 
screen to display. Expert users can configure their output any which way they want 
it to be, I'm not worried about them.

It's casual and in particular first-time users we should be worried about most - 
if they try the '-g' option in record, what will they first see in 'perf report' 
output?

I think the best output method would be to include only the 'highest level' parent 
symbols, with all children summed up under the parent's entry. Isn't the new 
'graph,0.5,caller' default very close to that?

But what confuses me about the output is the same that confused Wangnan's users:

  "This is my story: after switching to new version of perf, in a period of time 
   there are plenty of perf users in my company be confused by the first column of 
   'perf report' because the sum of the percentage listed there is much higher than 
   100%. They find me because they think this is a bug in perf which breaks their 
   routinely profiling work."

So this is suboptimal.

The first column is 'Children', which should show the sum of all child overhead - 
but if a child overhead was already included under a parent, it should never show 
up under another parent's entry. I.e. the first column should only contain the 
highest level entries, no sub-entries.

But what we do currently is:

  Children      Self  Command        Shared Object       Symbol
-   70.41%     0.00%  cc1            cc1                 [.] toplev_main
   - toplev_main
      + __libc_start_main
-   70.38%     0.00%  cc1            libc-2.20.so        [.] __libc_start_main
   + __libc_start_main

i.e. even though '__libc_start_main' is a child of 'toplev_main', it's still 
included on the 'overview' page.

Is there an output method that can do what I suggest above?

( Having both 'children' and 'self' columns in itself is intuitive IMHO: it shows
  that an entry that is shown does not directly have overhead at that level, a
  child call of it has that overhead. )

Thanks,

	Ingo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [next] | [standalone]


#1253769

FromNamhyung Kim <namhyung@kernel.org>
Date2015-10-22 14:40 +0200
Message-ID<qmnjY-2vq-25@gated-at.bofh.it>
In reply to#1253590
On Thu, Oct 22, 2015 at 5:46 PM, Ingo Molnar <mingo@kernel.org> wrote:
>
> * Arnaldo Carvalho de Melo <acme@redhat.com> wrote:
>
>> > 5) --no-children
>> >
>> > I agree that 'perf top -g --no-children' looks more intuitive than 'perf top -g'.
>>
>> So, what do you propose, to switch back the default to --no-children, for both
>> tools, top and report? Now that I am getting used to it... ;-)
>
> Heh ;-) So I'm only thinking out loud, trying to find the most intuitive initial
> screen to display. Expert users can configure their output any which way they want
> it to be, I'm not worried about them.

:)

>
> It's casual and in particular first-time users we should be worried about most -
> if they try the '-g' option in record, what will they first see in 'perf report'
> output?
>
> I think the best output method would be to include only the 'highest level' parent
> symbols, with all children summed up under the parent's entry. Isn't the new
> 'graph,0.5,caller' default very close to that?

Hmm.. not sure I'm following well. what do you mean by 'highest level
parent'?  Do you want single depth callchains for each entry?

>
> But what confuses me about the output is the same that confused Wangnan's users:
>
>   "This is my story: after switching to new version of perf, in a period of time
>    there are plenty of perf users in my company be confused by the first column of
>    'perf report' because the sum of the percentage listed there is much higher than
>    100%. They find me because they think this is a bug in perf which breaks their
>    routinely profiling work."
>
> So this is suboptimal.
>
> The first column is 'Children', which should show the sum of all child overhead -
> but if a child overhead was already included under a parent, it should never show
> up under another parent's entry. I.e. the first column should only contain the
> highest level entries, no sub-entries.

Again, I don't understand.  Could you elaborate it more probably with
example below?

>
> But what we do currently is:
>
>   Children      Self  Command        Shared Object       Symbol
> -   70.41%     0.00%  cc1            cc1                 [.] toplev_main
>    - toplev_main
>       + __libc_start_main
> -   70.38%     0.00%  cc1            libc-2.20.so        [.] __libc_start_main
>    + __libc_start_main
>
> i.e. even though '__libc_start_main' is a child of 'toplev_main', it's still
> included on the 'overview' page.

Strange. AFAIK 'toplev_main' is a child of '__libc_start_main'.  Are
you using 'caller' ordering?

Also I think 'main' should be shown between 'toplev_main' and
'__libc_start_main' but maybe it's a different issue.

Thanks,
Namhyung


>
> Is there an output method that can do what I suggest above?
>
> ( Having both 'children' and 'self' columns in itself is intuitive IMHO: it shows
>   that an entry that is shown does not directly have overhead at that level, a
>   child call of it has that overhead. )
>
> Thanks,
>
>         Ingo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

[toc] | [prev] | [standalone]


Back to top | Article view | linux.kernel


csiph-web