Re: [PATCH] perf top: Make -g refer to callchains

From: Ingo Molnar
Date: Mon Nov 18 2013 - 14:18:21 EST

Next message: Jiang, Dave: "Re: [v3][PATCH 0/2] v3: fix hugetlb vs. anon-thp copy page"
Previous message: Bjorn Helgaas: "[PATCH 2/2] PCI: Support PCIe Capability Slot registers only forports with slots"
In reply to: Jiri Olsa: "Re: [PATCH] perf top: Make -g refer to callchains"
Next in thread: Jan Kratochvil: "Re: [PATCH] perf top: Make -g refer to callchains"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

* Jiri Olsa <jolsa@xxxxxxxxxx> wrote:

> On Mon, Nov 18, 2013 at 03:26:53PM +0100, Ingo Molnar wrote:
> >
> > * Jiri Olsa <jolsa@xxxxxxxxxx> wrote:
> >
> > > On Mon, Nov 18, 2013 at 09:59:45AM -0300, Arnaldo Carvalho de Melo wrote:
> > > > Em Fri, Nov 15, 2013 at 06:46:09AM +0100, Ingo Molnar escreveu:
> > > > > btw., here's some 'perf top' call graph performance and profiling
> > > > > quality feedback, with the latest perf code:
> > > > >
> > > > > 'perf top --call-graph fp' now works very well, using just 0.2%
> > > > > of CPU time on a fast system:
> > > > >
> > > > > 4676 mingo 20 0 612m 56m 9948 S 1 0.2 0:00.68 perf
> > > > >
> > > > > 'perf top --call-graph dwarf' on the other hand is horrendously
> > > > > slow, using 20% of CPU time on a 4 GHz CPU:
> > > > >
> > > > > PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
> > > > > 4646 mingo 20 0 658m 81m 12m R 19 0.3 0:18.17 perf
> > > > >
> > > > > On another system with a 2.4GHz CPU it's taking up 100% of CPU
> > > > > time (!):
> > > > >
> > > > > PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
> > > > > 8018 mingo 20 0 290320 45220 8520 R 99.5 0.3 0:58.81 perf
> > > > >
> > > > > Profiling 'perf top' shows all sorts of very high dwarf
> > > > > processing overhead:
> > > >
> > > > Yeah, top dwarf callchain has been so far a proof of concept, it
> > > > exacerbates problems that can be seen on 'report', but since its
> > > > live, we can see it more clearly.
> > > >
> > > > The work on improving callchain processing, (rb_tree'ing, new comm
> > > > infrastructure) alleviated the problem a bit.
> > > >
> > > > Tuning the stack size requested from the kernel and using
> > > > --max-stack can help when it is really needed, but yes, work on it
> > > > is *badly* needed.
> > >
> > > agreed ;-)
> > >
> > > also there's new remote unwind interface recently added into libdw,
> > > which seems to be faster than libunwind.
> > >
> > > I plan on adding this soon.
> >
> > If the main source of overhead is libunwind (which needs
> > independent confirmation) then would it make sense to implement
> > dwarf stack unwind support ourselves?
> >
> > I think SysProf does that and it appears to be faster - its
> > unwind.c is only 400 lines long as it only implements the small
> > subset needed to walk the stack - AFAICS.
>
> I think it's an option.. but it'll simpler to try the libdw
> interface first and see if it's good/fast enough..
>
> also I recall discussing the speed with libdw developer Jan
> Kratochvil (CC-ed) and AFAICS they're open for
> suggestions/optimizations

So it's terribly difficult to measure the performance problems, do
something like this on an idle system:

$ perf top --call-graph dwarf

and unless you have a very, very fast CPU this is going to use up 100%
of CPU time. 20% on a very fast system. Both are anomalous and show
this kind of dwarf processing overhead:

#
# Overhead Command Shared Object Symbol
# ........ ....... ......................... .................................................
#
7.08% perf perf [.] access_mem
7.03% perf perf [.] dso__data_read_offset
5.83% perf perf [.] maps__find
5.64% perf libunwind-x86_64.so.8.0.1 [.] 0x000000000000ba25
4.75% perf perf [.] thread__find_addr_map
3.81% perf [kernel.kallsyms] [k] unmap_single_vma
2.57% perf perf [.] map__map_ip
2.48% perf libelf-0.156.so [.] 0x0000000000003a84
2.12% perf [kernel.kallsyms] [k] memset
2.12% perf perf [.] dso__data_read_addr
2.10% perf libc-2.17.so [.] __memcpy_sse2
1.72% perf libc-2.17.so [.] __memset_sse2
1.58% perf [kernel.kallsyms] [k] page_fault
1.56% perf libc-2.17.so [.] __memset_x86_64
1.44% perf perf [.] find_proc_info
1.25% perf libelf-0.156.so [.] elf_end
1.19% perf [kernel.kallsyms] [k] flush_tlb_mm_range
1.06% perf libc-2.17.so [.] vfprintf
1.04% perf libunwind-x86_64.so.8.0.1 [.] _Ux86_64_dwarf_search_unwind_table
1.00% perf [kernel.kallsyms] [k] __audit_syscall_exit
0.94% perf libc-2.17.so [.] _int_free
0.92% perf libc-2.17.so [.] _int_malloc
0.84% perf libc-2.17.so [.] __memcmp_sse2
0.81% perf [kernel.kallsyms] [k] unmapped_area_topdown
0.71% perf [kernel.kallsyms] [k] system_call
0.71% perf [kernel.kallsyms] [k] system_call_after_swapgs
0.65% perf [kernel.kallsyms] [k] sysret_check
0.63% perf perf [.] dso__find_symbol
0.58% perf [kernel.kallsyms] [k] clear_page_c
0.58% perf [kernel.kallsyms] [k] handle_mm_fault
0.56% perf libc-2.17.so [.] __sigprocmask

the libunwind and libelf entries didn't get resolved because I didn't
have a debug version of the libraries installed:

5.64% perf libunwind-x86_64.so.8.0.1 [.] 0x000000000000ba25
2.48% perf libelf-0.156.so [.] 0x0000000000003a84

Btw., tools like GDB are able to resolve symbols in such cases even
without debug packages installed:

(gdb) bt
#0 0x0000003e5908edf9 in __memcpy_sse2 () from /lib64/libc.so.6
#1 0x000000000046b61c in memcpy (__len=8, __src=<optimized out>, __dest=0x7fffc80b09b8) at /usr/include/bits/string3.h:51
#2 dso_cache__memcpy (size=8, data=0x7fffc80b09b8 "@\325\357\377\344\001", offset=1840096, cache=<optimized out>) at util/dso.c:259
#3 dso_cache_read (size=8, data=0x7fffc80b09b8 "@\325\357\377\344\001", offset=1840096, machine=0x9a2a48, dso=0x9b21a0) at util/dso.c:316
#4 dso__data_read_offset (dso=0x9b21a0, machine=0x9a2a48, offset=1840096, data=data@entry=0x7fffc80b09b8 "@\325\357\377\344\001", size=size@entry=8) at util/dso.c:330
#5 0x000000000046b7a5 in dso__data_read_addr (dso=<optimized out>, map=<optimized out>, machine=<optimized out>, addr=addr@entry=6034400,
data=data@entry=0x7fffc80b09b8 "@\325\357\377\344\001", size=size@entry=8) at util/dso.c:355
#6 0x00000000004bea3c in access_dso_mem (ui=0x7fffc80b18b0, ui=0x7fffc80b18b0, data=0x7fffc80b09b8, addr=6034400) at util/unwind.c:404
#7 access_mem (as=<optimized out>, addr=6034400, valp=0x7fffc80b09b8, __write=<optimized out>, arg=0x7fffc80b18b0) at util/unwind.c:455
#8 0x00007f885af02f2d in _Ux86_64_dwarf_read_encoded_pointer () from /lib64/libunwind-x86_64.so.8
#9 0x00007f885aeff992 in _Ux86_64_dwarf_extract_proc_info_from_fde () from /lib64/libunwind-x86_64.so.8
#10 0x00007f885af03e75 in _Ux86_64_dwarf_search_unwind_table () from /lib64/libunwind-x86_64.so.8
#11 0x00000000004bedbc in find_proc_info (as=0x1445560, ip=4975163, pi=0x7fffc80b15b0, need_unwind_info=1, arg=0x7fffc80b18b0) at util/unwind.c:335
#12 0x00007f885af00205 in fetch_proc_info () from /lib64/libunwind-x86_64.so.8
#13 0x00007f885af0246b in _Ux86_64_dwarf_find_save_locs () from /lib64/libunwind-x86_64.so.8
#14 0x00007f885af03769 in _Ux86_64_dwarf_step () from /lib64/libunwind-x86_64.so.8
#15 0x00007f885aefb3f1 in _Ux86_64_step () from /lib64/libunwind-x86_64.so.8

All those entries are within libunwind - and GDB was able to resolve
them.

How do they do it and shouldn't perf be able to do such magick?

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/

Next message: Jiang, Dave: "Re: [v3][PATCH 0/2] v3: fix hugetlb vs. anon-thp copy page"
Previous message: Bjorn Helgaas: "[PATCH 2/2] PCI: Support PCIe Capability Slot registers only forports with slots"
In reply to: Jiri Olsa: "Re: [PATCH] perf top: Make -g refer to callchains"
Next in thread: Jan Kratochvil: "Re: [PATCH] perf top: Make -g refer to callchains"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]