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 19:55:55 +0200
User-agent: KMail/4.13.1 (Linux/3.14.4-1-ARCH; KDE/4.13.1; x86_64; ; )

On Monday 02 June 2014 12:23:02 Milian Wolff wrote:
> 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?

I investigated the above a bit more, esp. the "unusual frame" which was the 
one pointing to __libc_start_main. Turns out that the conditional before

 /* Save information for a standard frame. */

in Gstash_frame.c fails because DWARF_GET_LOC(d->loc[d->ret_addr_column]) is 
null, d->cfa is 0x7fff0b3740b8 or similar. All other checks are true. If I 
also check for a null ret_addr_column loc, unw_backtrace becomes very fast. 
Does this help, or is a null loc there also something that might happen 
elsewhere and the check I added bogus?

My backtraces obtained that way still contain frames above __libc_start_main 
though... Which, if I understood you correctly, should not happen. See my 
other mail also. If you have any idea whats going on here any help would be 
highly appreciated!
-- 
Milian Wolff
address@hidden
http://milianw.de



reply via email to

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