[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
- Re: [Libunwind-devel] Backtrace performance on x86-64 based on Dwarf info, (continued)
- Re: [Libunwind-devel] Backtrace performance on x86-64 based on Dwarf info, Milian Wolff, 2014/06/02
- Re: [Libunwind-devel] Backtrace performance on x86-64 based on Dwarf info, Arun Sharma, 2014/06/02
- Re: [Libunwind-devel] Backtrace performance on x86-64 based on Dwarf info, Milian Wolff, 2014/06/03
- Re: [Libunwind-devel] Backtrace performance on x86-64 based on Dwarf info, Arun Sharma, 2014/06/03
- Re: [Libunwind-devel] Backtrace performance on x86-64 based on Dwarf info, Milian Wolff, 2014/06/04
- Re: [Libunwind-devel] Backtrace performance on x86-64 based on Dwarf info, Milian Wolff, 2014/06/04
- Re: [Libunwind-devel] Backtrace performance on x86-64 based on Dwarf info, Milian Wolff, 2014/06/04
- Re: [Libunwind-devel] Backtrace performance on x86-64 based on Dwarf info, Lassi Tuura, 2014/06/13
- Re: [Libunwind-devel] Backtrace performance on x86-64 based on Dwarf info, Milian Wolff, 2014/06/14
- Re: [Libunwind-devel] Backtrace performance on x86-64 based on Dwarf info, Lassi Tuura, 2014/06/19
Re: [Libunwind-devel] Backtrace performance on x86-64 based on Dwarf info,
Milian Wolff <=