perf hists browser: Print overhead percent value for first-level callchain

Currently perf report on TUI doesn't print percent for first-level callchain entry. I guess it (wrongly) assumes that there's only a single callchain in the first level. This patch fixes it by handling the first level callchains same as others - if it's not 100% it should print the percent value. Also it'll affect other callchains in the other way around - if it's 100% (single callchain) it should not print the percentage.

Before:
- 30.95% 6.84% abc2 abc2 [.] a
- a
- 70.00% c
- 100.00% apic_timer_interrupt
smp_apic_timer_interrupt
local_apic_timer_interrupt
hrtimer_interrupt
...
+ 30.00% b
+ __libc_start_main

After:
- 30.95% 6.84% abc2 abc2 [.] a
- 77.90% a
- 70.00% c
- apic_timer_interrupt
smp_apic_timer_interrupt
local_apic_timer_interrupt
hrtimer_interrupt
...
+ 30.00% b
+ 22.10% __libc_start_main

---
 tools/perf/ui/browsers/hists.c | 14 ++++++++++++--
 1 file changed, 12 insertions(+), 2 deletions(-)

index 12c17c5a3d68..8d22905a4687 100644
@@ -542,8 +542,11 @@ static int hist_browser__show_callchain(struct hist_browser *browser,
 	struct rb_node *node;
 	int first_row = row, offset = level * LEVEL_OFFSET_STEP;
 	u64 new_total;
+	bool need_percent;
 
 	node = rb_first(root);
+	need_percent = !!rb_next(node);
+
 	while (node) {
 		struct callchain_node *child = rb_entry(node, struct callchain_node, rb_node);
 		struct rb_node *next = rb_next(node);

@@ -560,7 +563,7 @@ static int hist_browser__show_callchain(struct hist_browser *browser,
 
 			if (first)
 				first = false;
-			else if (level > 1)
+			else if (need_percent)
 				extra_offset = LEVEL_OFFSET_STEP;
 
 			folded_sign = callchain_list__folded(chain);

@@ -573,7 +576,7 @@ static int hist_browser__show_callchain(struct hist_browser *browser,
 			str = callchain_list__sym_name(chain, bf, sizeof(bf),
 						       browser->show_dso);
 
-			if (was_first && level > 1) {
+			if (was_first && need_percent) {
 				double percent = cumul * 100.0 / total;
 
 				if (asprintf(&alloc_str, "%2.2f%% %s", percent, str) < 0)

@@ -790,6 +793,13 @@ static int hist_browser__show_entry(struct hist_browser *browser,
 			.is_current_entry = current_entry,
 		};
 
+		if (callchain_param.mode == CHAIN_GRAPH_REL) {
+			if (symbol_conf.cumulate_callchain)
+				total = entry->stat_acc->period;
+			else
+				total = entry->stat.period;
+		}
+
 		printed += hist_browser__show_callchain(browser,
 					&entry->sorted_chain, 1, row, total,
 					hist_browser__show_callchain_entry, &arg,

2.1.2

If first level callchain has more than single path like when -g caller option is given, it should show only first one in the path and hide others. But it didn't do it properly nad just hindered the output.

Before:
- 80.33% 11.11% abc2 abc2 [.] main
+ 86.18% main
13.82% __libc_start_main
main

After:
- 80.33% 11.11% abc2 abc2 [.] main
+ 86.18% main
+ 13.82% __libc_start_main

---
 tools/perf/ui/browsers/hists.c | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

index 8d22905a4687..502daff76ceb 100644
@@ -227,10 +227,14 @@ static void callchain_node__init_have_children_rb_tree(struct callchain_node *no
 	}
 }
 
-static void callchain_node__init_have_children(struct callchain_node *node)
+static void callchain_node__init_have_children(struct callchain_node *node,
+					       bool has_sibling)
 {
 	struct callchain_list *chain;
 
+	chain = list_entry(node->val.next, struct callchain_list, list);
+	chain->ms.has_children = has_sibling;
+
 	if (!list_empty(&node->val)) {
 		chain = list_entry(node->val.prev, struct callchain_list, list);
 		chain->ms.has_children = !RB_EMPTY_ROOT(&node->rb_root);

@@ -241,11 +245,12 @@ static void callchain_node__init_have_children(struct callchain_node *node)
 
 static void callchain__init_have_children(struct rb_root *root)
 {
-	struct rb_node *nd;
+	struct rb_node *nd = rb_first(root);
+	bool has_sibling = nd && rb_next(nd);
 
 	for (nd = rb_first(root); nd; nd = rb_next(nd)) {
 		struct callchain_node *node = rb_entry(nd, struct callchain_node, rb_node);
-		callchain_node__init_have_children(node);
+		callchain_node__init_have_children(node, has_sibling);
 	}
 }
 

2.1.2

Em Mon, Nov 24, 2014 at 05:13:26PM +0900, Namhyung Kim escreveu:

Thanks, with this the --stdio output matches --tui when --branch-history is used in 'report', will push soon.

One thing I think would be great would be to make it possible to use:

  [root@zoo acme]# perf probe -L get_vma_policy
  <get_vma_policy@/usr/src/debug/kernel-3.17.fc20/linux-3.17.2-200.fc20.x86_64/mm/mempolicy.c:0>
        0  struct mempolicy *get_vma_policy(struct task_struct *task,
                          struct vm_area_struct *vma, unsigned long addr)
        2  {
        3         struct mempolicy *pol = get_task_policy(task);

        5         if (vma) {
        6                 if (vma->vm_ops && vma->vm_ops->get_policy) {
        7                         struct mempolicy *vpol = vma->vm_ops->get_policy(vma,
                                                                                  addr);
        9                         if (vpol)
                                          pol = vpol;
       11                 } else if (vma->vm_policy) {
                                  pol = vma->vm_policy;
         
                                  /*
                                   * shmem_alloc_page() passes
                                   * MPOL_F_SHARED policy with
                                   * a pseudo vma whose vma->vm_ops=NULL.
                                   * Take a reference
                                   * count on these policies which will be
                                   * dropped by
                                   * mpol_cond_put() later
                                   */
       20                         if (mpol_needs_cond_ref(pol))
       21                                 mpol_get(pol);
                          }
                  }
                  if (!pol)
                          pol = &default_policy;
                  return pol;
       27  }

[root@zoo acme]#

Together with the srcline code, i.e. to allow matching the above with the output from 'perf report', like here:

     2.40%  mmzone.c:69  [k] next_zones_zonelist            [kernel.vmlinux]
            |
            ---next_zones_zonelist mmzone.c:59
               __alloc_pages_nodemask mmzone.h:1039
               __alloc_pages_nodemask page_alloc.c:2775
               __alloc_pages_nodemask page_alloc.c:2765
               __alloc_pages_nodemask page_alloc.c:2765
               _cond_resched core.c:4180
               _cond_resched core.c:4175
               __alloc_pages_nodemask page_alloc.c:2765
               __alloc_pages_nodemask page_alloc.c:2765
               __alloc_pages_nodemask page_alloc.c:2765
               __alloc_pages_nodemask page_alloc.c:2751
               alloc_pages_vma mempolicy.c:2046
               alloc_pages_vma mempolicy.c:2046
               policy_zonelist mempolicy.c:1735
               policy_zonelist gfp.h:274
               policy_zonelist mempolicy.c:1717
               policy_zonelist mempolicy.c:1717
               policy_zonelist mempolicy.c:1715
               policy_zonelist mempolicy.c:1714
               alloc_pages_vma mempolicy.c:2046
               alloc_pages_vma mempolicy.c:2046
               policy_nodemask mempolicy.c:1709
               policy_nodemask mempolicy.c:1701
               alloc_pages_vma mempolicy.c:2046
               alloc_pages_vma seqlock.h:111
               get_vma_policy mempolicy.c:1650
               get_vma_policy mempolicy.c:1650
               get_vma_policy mempolicy.c:1634
               get_vma_policy mempolicy.c:1634
               get_vma_policy mempolicy.c:1629
               get_vma_policy mempolicy.c:1628
               get_vma_policy mempolicy.c:134

See the get_vma_policy lines? We need a way to ask both for 'perf probe -L' to show absolute line numbers and also for the report code to show line numbers as offsets from function start.

At some point being able to, as IIRC Andi suggested, to show the callchains via the annotate widget would be fantastic as well, i.e. showing the callchain in a window and in another window to show it as arrows in the source code, that would move from function to function as we navigate on the callchain, as we do already with jumps, calls, rets.

But the absolute line numbers on 'perf probe -L' and the offsets from function start in 'report' look like low hanging fruits and a way to integrate further 'perf probe' with 'perf report', because both will look at the right file, keyed by the build-id, etc.

- Arnaldo

Em Mon, Nov 24, 2014 at 11:52:27AM -0300, Arnaldo Carvalho de Melo escreveu:

[acme@zoo linux]$ time make -C tools/perf build-test
make: Entering directory `/home/git/linux/tools/perf'
- make_pure: cd . && make -f Makefile DESTDIR=/tmp/tmp.z11aKMiurz
- make_clean_all: cd . && make -f Makefile DESTDIR=/tmp/tmp.aylbvfzj5m clean all
- make_python_perf_so: cd . && make -f Makefile DESTDIR=/tmp/tmp.t896NZcPrJ python/perf.so
- make_debug: cd . && make -f Makefile DESTDIR=/tmp/tmp.ARnUdN0Ox5 DEBUG=1
- make_no_libperl: cd . && make -f Makefile DESTDIR=/tmp/tmp.xG1XJ2Pjq7 NO_LIBPERL=1
- make_no_libpython: cd . && make -f Makefile DESTDIR=/tmp/tmp.2k8q3ouduH NO_LIBPYTHON=1
- make_no_scripts: cd . && make -f Makefile DESTDIR=/tmp/tmp.kwu6TUzMaZ NO_LIBPYTHON=1 NO_LIBPERL=1
- make_no_newt: cd . && make -f Makefile DESTDIR=/tmp/tmp.Ra0cHpOVXI NO_NEWT=1
- make_no_slang: cd . && make -f Makefile DESTDIR=/tmp/tmp.dI5pMO80Gw NO_SLANG=1
- make_no_gtk2: cd . && make -f Makefile DESTDIR=/tmp/tmp.r4R7rILIq4 NO_GTK2=1
- make_no_ui: cd . && make -f Makefile DESTDIR=/tmp/tmp.36qCtqcT3J NO_NEWT=1 NO_SLANG=1 NO_GTK2=1
- make_no_demangle: cd . && make -f Makefile DESTDIR=/tmp/tmp.5PpSkaVWUl NO_DEMANGLE=1
cd . && make -f Makefile DESTDIR=/tmp/tmp.5PpSkaVWUl NO_DEMANGLE=1
BUILD: Doing 'make -j4' parallel build

Auto-detecting system features:

...                         dwarf: [ on  ]
...                         glibc: [ on  ]
...                          gtk2: [ on  ]
...                      libaudit: [ on  ]
...                        libbfd: [ on  ]
...                        libelf: [ on  ]
...                       libnuma: [ on  ]
...                       libperl: [ on  ]
...                     libpython: [ on  ]
...                      libslang: [ on  ]
...                     libunwind: [ on  ]
...            libdw-dwarf-unwind: [ on  ]
...                          zlib: [ on  ]

... DWARF post unwind library: libunwind

  GEN      common-cmds.h
  FLAGS:   * new build flags or prefix
  BISON    util/pmu-bison.c
  CC       util/environment.o
  CC       util/event.o
  CC       util/evlist.o
  CC       util/evsel.o
  PERF_VERSION = 3.18.rc3.gf07177
  CC       util/exec_cmd.o
  CC       util/help.o
  CC       util/kallsyms.o
  CC       util/levenshtein.o
  CC       util/parse-options.o
  BISON    util/parse-events-bison.c
  CC       util/path.o
  CC       util/rbtree.o
  CC       util/bitmap.o
  CC       util/hweight.o
  CC       util/run-command.o
  CC       util/quote.o
  CC       util/strbuf.o
  CC       util/string.o
  CC       util/strlist.o
  CC       util/strfilter.o
  CC       util/top.o
  CC       util/usage.o
  CC       util/wrapper.o
  CC       util/sigchain.o
  CC       util/dso.o
  CC       util/symbol.o
  CC       util/symbol-elf.o
  CC       util/color.o
  CC       util/pager.o
  CC       util/header.o
  CC       util/callchain.o
  CC       util/values.o
  CC       util/debug.o
  CC       util/machine.o
  CC       util/map.o
  CC       util/pstack.o
  CC       util/session.o
  CC       util/ordered-events.o
  CC       util/comm.o
  CC       util/thread.o
  CC       util/thread_map.o
  CC       util/trace-event-parse.o
  CC       util/parse-events-bison.o
  CC       util/pmu-bison.o
  CC       util/trace-event-read.o
  CC       util/trace-event-info.o
  CC       util/trace-event-scripting.o
  CC       util/trace-event.o
  CC       util/svghelper.o
  CC       util/sort.o
  CC       util/hist.o
  CC       util/probe-event.o
  CC       util/util.o
  CC       util/xyarray.o
  CC       util/cpumap.o
  CC       util/cgroup.o
  CC       util/target.o
  CC       util/rblist.o
  CC       util/intlist.o
  CC       util/vdso.o
  CC       util/stat.o
  CC       util/record.o
  CC       util/srcline.o
  CC       util/data.o
  CC       util/tsc.o
  CC       util/cloexec.o
In file included from util/srcline.c:18:0:
/usr/include/bfd.h:6197:7: error: conflicting types for ‘bfd_demangle’
 char *bfd_demangle (bfd *, const char *, int);
       ^

In file included from util/srcline.c:11:0:
util/symbol.h:35:21: note: previous definition of ‘bfd_demangle’ was here
static inline char *bfd_demangle(void __maybe_unused *v,

                     ^

make[3]: *** [util/srcline.o] Error 1 make[3]: *** Waiting for unfinished jobs.... make[2]: *** [all] Error 2
test: test -x ./perf
make[1]: *** [make_no_demangle] Error 1
make: *** [build-test] Error 2
make: Leaving directory `/home/git/linux/tools/perf'

real 4m21.797s
user 10m54.214s
sys 1m26.056s
[acme@zoo linux]$

Em Mon, Nov 24, 2014 at 12:23:12PM -0300, Arnaldo Carvalho de Melo escreveu:

Right to the point:

[acme@zoo linux]$ make -C tools/perf NO_DEMANGLE=1 util/srcline.o
make: Entering directory `/home/git/linux/tools/perf'
BUILD: Doing 'make -j4' parallel build
CC util/srcline.o
In file included from util/srcline.c:18:0:
/usr/include/bfd.h:6197:7: error: conflicting types for ‘bfd_demangle’
char *bfd_demangle (bfd *, const char *, int);

       ^

In file included from util/srcline.c:11:0:
util/symbol.h:35:21: note: previous definition of ‘bfd_demangle’ was here
static inline char *bfd_demangle(void __maybe_unused *v,

                     ^

make[1]: *** [util/srcline.o] Error 1
make: *** [util/srcline.o] Error 2
make: Leaving directory `/home/git/linux/tools/perf' [acme@zoo linux]$

Em Mon, Nov 24, 2014 at 12:25:41PM -0300, Arnaldo Carvalho de Melo escreveu:

bisected it down to:

43e3229ef07a2dda81bda86a5b81ef8c2890ab63 is the first bad commit commit 43e3229ef07a2dda81bda86a5b81ef8c2890ab63

Author: Andi Kleen <[email protected]>
Date:   Wed Nov 12 18:05:27 2014 -0800

perf callchain: Make get_srcline fall back to sym+offset

When the source line is not found fall back to sym + offset. This is generally much more useful than a raw address.

For this we need to pass in the symbol from the caller.

For some callers it's awkward to compute, so we stay at the old behaviour.

:040000 040000 ae5e95c8dbfd9ab8e836707fcb2904e263f872c6
5979ba316f1d317c59866b0c3bf92c39fbdcde6b M tools
[acme@zoo linux]$

Em Mon, Nov 24, 2014 at 12:32:04PM -0300, Arnaldo Carvalho de Melo escreveu:

What I have is on the perf/branch-history branch, we can't both include bfd.h and symbol.h when NO_DEMANGLE=1, probably we should just move the stub inline to symbol-elf.c, its only user, but I have to check further, lunch time tho.

- Arnaldo

Em Mon, Nov 24, 2014 at 12:48:41PM -0300, Arnaldo Carvalho de Melo escreveu:

Fixed, pushed it out on my perf/core and perf/branch-history branches.

--branch-history stuff still on a separate branch because it explodes:

[root@zoo acme]# perf record -a -g -b sleep 2s
[ perf record: Woken up 7 times to write data ]
[ perf record: Captured and wrote 3.033 MB perf.data (~132504 samples) ] [root@zoo acme]# perf report --stdio --branch-history
# To display the perf.data header info, please use --header/--header-only options. #
BFD: Dwarf Error: Offset (2585882475) greater than or equal to .debug_str size (44321517).
BFD: Dwarf Error: Could not find abbrev number 11800.
<BIG SNIP>
BFD: Dwarf Error: Offset (83496016) greater than or equal to .debug_str size (44321517).
BFD: Dwarf Error: Offset (48628447) greater than or equal to .debug_str size (44321517). (END)Segmentation fault (core dumped)
[root@zoo acme]#

Will investigate this later today/tomorrow, if nobody finds a fix in the meantime.

- Arnaldo

I cannot reproduce this.

For me it looks like you have some binary or debuginfo that your libbfd doesn't like. --branch-history resolves all addresses as srcline, so it will actually walk all the line numbers.

Can you please find out which one it is? Probably can be seen by just going up a few levels in gdb and dumping the event.

If you can find the address that explodes you can also try it directly with addr2line. If that works it's some problem in the perf implementation.

It is likely that it would need to be fixed in libbfd.

To work around it we could turn off force resolving the srcline, but that would make the output much less useful too unfortuantely...

-Andi

[email protected] -- Speaking for myself only.

Em Mon, Nov 24, 2014 at 11:52:44PM +0100, Andi Kleen escreveu:

Right, I'll try and figure this out, since you didn't manage to easily reproduce this.

I'll try to find out if there is something that can flag a file as "unsafe" to feed libbfd with, so that we can have a workaround for known buggy libbfds, if that ends up being really the case.

- Arnaldo

Em Mon, Nov 24, 2014 at 11:52:44PM +0100, Andi Kleen escreveu:

Yeah, you are right:

[acme@zoo linux]$ addr2line -e /usr/lib/debug/usr/lib64/firefox/libxul.so.debug 22fefe8
BFD: Dwarf Error: Offset (2585882475) greater than or equal to
.debug_str size (44321517).
BFD: Dwarf Error: Could not find abbrev number 11800.
BFD: Dwarf Error: Offset (493511937) greater than or equal to .debug_str size (44321517).

[acme@zoo linux]$ file /usr/lib/debug/usr/lib64/firefox/libxul.so.debug /usr/lib/debug/usr/lib64/firefox/libxul.so.debug: ELF 64-bit LSB shared object, x86-64, version 1 (GNU/Linux), dynamically linked, BuildID[sha1]=ab6f19f13352ca2fbf218d1ff9200ef8e29764b8, not stripped [acme@zoo linux]$

[acme@zoo linux]$ rpm -qf /usr/lib/debug/usr/lib64/firefox/libxul.so.debug firefox-debuginfo-33.1-2.fc20.x86_64

If I ignore just this one file, all works, I'll process your patch while leaving a note in the changelog that this may trigger binutils bugs, and will check if a later version of binutils has the same problem, etc.

- Arnaldo

Thanks for testing.

But addr2line didn't crash? What happens when you run it under valgrind?

If yes, I can check what it does differently than get_srcline() to make it recover better.

-Andi

Hi Arnaldo,

Okay, will do later :)

Thanks,
Namhyung