Re: [PATCH 13/16] perf callchain: Switch default to 'graph,0.5,caller'
From: Ingo Molnar
Date: Wed Oct 21 2015 - 04:48:31 EST
* Arnaldo Carvalho de Melo <acme@xxxxxxxxxx> 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@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/