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

[Ingo Molnar <mingo@kernel.org>]

* 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