libunwind-devel
[Top][All Lists]
Advanced

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: [Libunwind-devel] Backtrace performance on x86-64 based on Dwarf inf


From: Milian Wolff
Subject: Re: [Libunwind-devel] Backtrace performance on x86-64 based on Dwarf info
Date: Mon, 02 Jun 2014 12:23:02 +0200
User-agent: KMail/4.13.1 (Linux/3.14.4-1-ARCH; KDE/4.13.1; x86_64; ; )

On Sunday 01 June 2014 10:36:09 Arun Sharma wrote:

> On Fri, May 30, 2014 at 3:42 PM, Milian Wolff <address@hidden> wrote:

> > So... yes? But what does that have to do with the 0-IP I encounter at the

> > end of a backtrace?

>

> Only RBP=0 can indicate the end of call chain. We used to treat RIP=0

> as an indication to stop the unwinding, but it broke a bunch of legit

> use cases.

>

> d04dc94 dwarf: ip == 0 should't terminate unwind

>

> The problem here may be that various caches in the fast path (Gtrace.c

> and src/dwarf/Gparser.c:rs_new()) ignore the RIP==0 case. This is

> exacerbated by the calls to block signals.

>

> We do have a --enable_block_signals config option. More info about it here:

>

> 9aa0d6d Allow caller to block signals.

> 84d4150 Allow caller to block signals.

>

> If you can guarantee that signals are blocked on entry to libunwind,

> we can optimize away the sigprocmask calls.

>

> A longer term solution may be to teach the libunwind caches about

> negative caching in general or the RIP==0 case in particular.

 

Hello Arun,

 

thanks for the input. The negative caching sounds like a good idea to me. But somehow I think there is something else going on as well:

 

I tried out the supposedly fast unw_backtrace() and it seems to have the same issue. At the end of every backtrace it finds some garbage it is not expecting and then triggers a fallback to the slow-path based on unw_step. Debug output contains lines like this for every call to unw_backtrace:

 

...

>_ULx86_64_tdep_trace: depth 9 cfa 0x7fffb98a3820 rip 0x400d28 rsp 0x7fffb98a3820 rbp 0x0

>trace_lookup: updating slot 1832 after 0 steps, replacing 0x0

>_ULx86_64_step: (cursor=0x7fffb98a29f0, ip=0x0000000000400d29, cfa=0x00007fffb98a3820)

>_ULx86_64_dwarf_find_proc_info: looking for IP=0x400d28

>_ULx86_64_dwarf_search_unwind_table: e->fde_offset = ffffffffffffff9c, segbase = 4013fc, debug_frame_base = 0, fde_addr = 401398

>_ULx86_64_dwarf_extract_proc_info_from_fde: FDE @ 0x401398

>_ULx86_64_fetch_frame: fetch frame ip=0x400d29 cfa=0x7fffb98a3820 format=0

>_ULx86_64_cache_frame: cache frame ip=0x400d29 cfa=0x7fffb98a3820 format=0

>_ULx86_64_reuse_frame: reuse frame ip=0x400d29 cfa=0x7fffb98a3820 format=0 addr=0x0 offset=+0

>_ULx86_64_stash_frame: ip=0x0 cfa=0x7fffb98a3828 type 0 cfa [where=3 val=7] cfaoff=8 ra=0x0 rbp [where=1 val=0 @0x7fffb98a26b8] rsp [where=1 val=0 @0x7fffb98a26e0]

>_ULx86_64_stash_frame: unusual frame

>_ULx86_64_step: returning 1

>trace_init_addr: frame va 400d28 type 0 last 0 cfa rsp+0 rbp @ cfa-1 rsp @ cfa-1

>_ULx86_64_tdep_trace: frame va 400d28 type 0 last 0 cfa rsp+0 rbp @ cfa-1 rsp @ cfa-1

>_ULx86_64_tdep_trace: new cfa 0x7fffb98a3820 rip 0x400d28 rsp 0x7fffb98a3820 rbp 0x0

...

>trace_init_addr: frame va 400e59 type -2 last 0 cfa rbp+16 rbp @ cfa-16 rsp @ cfa-1

>_ULx86_64_tdep_trace: frame va 400e59 type -2 last 0 cfa rbp+16 rbp @ cfa-16 rsp @ cfa-1

>_ULx86_64_tdep_trace: new cfa 0x7fffb98a3760 rip 0x7f0b689a1000 rsp 0x7fffb98a3760 rbp 0x4010d0

>_ULx86_64_tdep_trace: depth 6 cfa 0x7fffb98a3760 rip 0x7f0b689a0fff rsp 0x7fffb98a3760 rbp 0x4010d0

>trace_lookup: found address after 0 steps

>_ULx86_64_tdep_trace: frame va 7f0b689a0fff type -2 last 0 cfa rsp+192 rbp @ cfa-40 rsp @ cfa-1

>_ULx86_64_tdep_trace: new cfa 0x7fffb98a3820 rip 0x400d29 rsp 0x7fffb98a3820 rbp 0x0

>_ULx86_64_tdep_trace: depth 7 cfa 0x7fffb98a3820 rip 0x400d28 rsp 0x7fffb98a3820 rbp 0x0

>trace_lookup: found address after 0 steps

>_ULx86_64_tdep_trace: frame va 400d28 type 0 last 0 cfa rsp+0 rbp @ cfa-1 rsp @ cfa-1

>_ULx86_64_tdep_trace: new cfa 0x7fffb98a3820 rip 0x400d28 rsp 0x7fffb98a3820 rbp 0x0

>_ULx86_64_tdep_trace: returning -5, depth 7

>_ULx86_64_init_local: (cursor=0x7fffb98a2e20)

>_ULx86_64_step: (cursor=0x7fffb98a2e20, ip=0x00007f0b6990dc68, cfa=0x00007fffb98a2660)

>_ULx86_64_reuse_frame: reuse frame ip=0x7f0b6990dc68 cfa=0x7fffb98a2660 format=0 addr=0x0 offset=+0

>_ULx86_64_step: returning 1

...

>_ULx86_64_step: (cursor=0x7fffb98a2e20, ip=0x0000000000400d29, cfa=0x00007fffb98a3820)

>_ULx86_64_reuse_frame: reuse frame ip=0x400d29 cfa=0x7fffb98a3820 format=0 addr=0x0 offset=+0

>_ULx86_64_step: returning 1

>_ULx86_64_step: (cursor=0x7fffb98a2e20, ip=0x0000000000000000, cfa=0x00007fffb98a3828)

>_ULx86_64_dwarf_find_proc_info: looking for IP=0xffffffffffffffff

>_ULx86_64_dwarf_find_proc_info: IP=0xffffffffffffffff not found

>_ULx86_64_step: dwarf_step() failed (ret=-10), trying frame-chain

>_ULx86_64_step: NULL %rbp loc, returning 0

 

Looking at the backtrace for the return values I go

 

...

0x400fff main in /home/milian/projects/kde4/mallocinfo/tests/test.cpp:66 /home/milian/projects/.build/kde4/mallocinfo/tests/test_cpp

0x7f0b689a1000 __libc_start_main /usr/lib/libc.so.6

0x400d29 ? /home/milian/projects/.build/kde4/mallocinfo/tests/test_cpp

0x0 <unknown module>

...

 

So I wonder what is going on here. Considering that the fast unw_backtrace always fails for me, is there maybe something going on on my machine / platform / setup which is currently not supported by libunwind? Is there a bug somewhere?

--

Milian Wolff

address@hidden

http://milianw.de


reply via email to

[Prev in Thread] Current Thread [Next in Thread]