Re: GDB Frame Unwinding for Pure Assembly Code

[Ahmad Nouralizadeh <ahmad.mlists@gmail.com>]

Thanks, Andrew,
I will try harder.
Regards.

On Thursday, 25 June 2020, Andrew Burgess <andrew.burgess@embecosm.com>
wrote:

> * Ahmad Nouralizadeh <ahmad.mlists@gmail.com> [2020-06-25 13:40:21 +0430]:
>
> > Hi Andrew,
> >
> > Thanks! This makes many things clear to me.
> >
> > I enabled frame debugging (by setting the global variable, "frame_debug",
> > to 1). The frame debugging information shows that, the frame that Perf
> > could not unwind (i.e., the next to the innermost frame of ffmpeg
> > benchmark), is extracted using the inline unwinder. It knows that
> > "0x7fffeaabdad9" is stored at $RSP. The value is accessed using the
> > following backtrace:
> > #0  _Z23frame_unwind_got_memoryP10frame_infoim (frame=0x555556314750,
> > regnum=16, addr=140737488309304) at frame-unwind.c:236
> > #1  0x000055555561dc64 in amd64_frame_prev_register
> > (this_frame=0x555556314750, this_cache=0x555556314768, regnum=16) at
> > amd64-tdep.c:2642
> > #2  0x00005555558b27d4 in _Z27frame_unwind_register_valueP10frame_infoi
> > (frame=0x555556314750, regnum=16) at frame.c:1194
> > #3  0x00005555558b231e in
> > _Z21frame_register_unwindP10frame_infoiPiS1_P9lval_typePmS1_Ph
> > (frame=0x555556314750, regnum=16, optimizedp=0x7fffffffd6e0,
> >     unavailablep=0x7fffffffd6e4, lvalp=0x7fffffffd6ec,
> > addrp=0x7fffffffd6f0, realnump=0x7fffffffd6e8, bufferp=0x7fffffffd720
> > "0\327\377\377\377\177") at frame.c:1096
> > #4  0x00005555558b2643 in _Z21frame_unwind_registerP10frame_infoiPh
> > (frame=0x555556314750, regnum=16, buf=0x7fffffffd720
> > "0\327\377\377\377\177") at frame.c:1153
> > #5  0x0000555555602706 in i386_unwind_pc (gdbarch=0x5555566924c0,
> > next_frame=0x555556314750) at i386-tdep.c:1965
> > #6  0x00005555558c6056 in _Z17gdbarch_unwind_pcP7gdbarchP10frame_info
> > (gdbarch=0x5555566924c0, next_frame=0x555556314750) at gdbarch.c:3075
> > #7  0x00005555558b1b0b in frame_unwind_pc (this_frame=0x555556314750) at
> > frame.c:885
> > #8  0x00005555558b4f72 in _Z12get_frame_pcP10frame_info
> > (frame=0x555556314900) at frame.c:2379
> > #9  0x00005555558b50ea in _Z26get_frame_address_in_blockP10frame_info
> > (this_frame=0x555556314900) at frame.c:2410
> > #10 0x0000555555905d53 in inline_frame_sniffer (self=0x555556193520
> > <inline_frame_unwind>, this_frame=0x555556314900,
> > this_cache=0x555556314918) at inline-frame.c:215
> > #11 0x00005555558b719a in frame_unwind_try_unwinder
> > (this_frame=0x555556314900, this_cache=0x555556314918,
> > unwinder=0x555556193520 <inline_frame_unwind>)
> >     at frame-unwind.c:106
> > #12 0x00005555558b737d in _Z26frame_unwind_find_by_frameP10frame_infoPPv
> > (this_frame=0x555556314900, this_cache=0x555556314918) at
> frame-unwind.c:164
> > #13 0x00005555558b0d8f in compute_frame_id (fi=0x555556314900) at
> > frame.c:501
> > #14 0x00005555558b407d in get_prev_frame_if_no_cycle
> > (this_frame=0x555556314750) at frame.c:1913
> > #15 0x00005555558b478e in get_prev_frame_always_1
> > (this_frame=0x555556314750) at frame.c:2087
> > #16 0x00005555558b47e6 in _Z21get_prev_frame_alwaysP10frame_info
> > (this_frame=0x555556314750) at frame.c:2103
> > #17 0x00005555558b4e39 in _Z14get_prev_frameP10frame_info
> > (this_frame=0x555556314750) at frame.c:2356
> > #18 0x00005555556b7fab in _Z26frame_info_to_frame_objectP10frame_info
> > (frame=0x555556314750) at python/py-frame.c:372
> > #19 0x00005555556bd003 in bootstrap_python_frame_filters
> > (frame=0x555556314750, frame_low=0, frame_high=-1) at
> > python/py-framefilter.c:1283
> > #20 0x00005555556bd3a2 in
> > _Z24gdbpy_apply_frame_filterPK23extension_language_
> defnP10frame_infoi19ext_lang_frame_argsP6ui_outii
> > (
> >     extlang=0x5555560c3c40 <extension_language_python>,
> > frame=0x555556314750, flags=7, args_type=CLI_SCALAR_VALUES,
> > out=0x55555636bed0, frame_low=0, frame_high=-1)
> >     at python/py-framefilter.c:1359
> > #21 0x00005555558a8664 in
> > _Z27apply_ext_lang_frame_filterP10frame_infoi19ext_
> lang_frame_argsP6ui_outii
> > (frame=0x555556314750, flags=7, args_type=CLI_SCALAR_VALUES,
> >     out=0x55555636bed0, frame_low=0, frame_high=-1) at extension.c:570
> > #22 0x00005555559e33b4 in backtrace_command_1 (count_exp=0x0,
> > show_locals=0, no_filters=0, from_tty=1) at stack.c:1789
> > #23 0x00005555559e3816 in backtrace_command (arg=0x0, from_tty=1) at
> > stack.c:1902
> > #24 0x000055555566c8a4 in do_const_cfunc (c=0x555556344a60, args=0x0,
> > from_tty=1) at cli/cli-decode.c:106
> > #25 0x000055555566fba8 in _Z8cmd_funcP16cmd_list_elementPKci
> > (cmd=0x555556344a60, args=0x0, from_tty=1) at cli/cli-decode.c:1886
> > #26 0x0000555555a4066e in _Z15execute_commandPKci (p=0x555556609e52 "",
> > from_tty=1) at top.c:630
> > #27 0x00005555558a1b58 in _Z15command_handlerPKc (command=0x555556609e50
> > "bt") at event-top.c:583
> > #28 0x00005555558a1f6c in _Z20command_line_handlerPc (rl=0x55555ab70790
> "")
> > at event-top.c:774
> > #29 0x00005555558a12c6 in gdb_rl_callback_handler (rl=0x55555ab70790 "")
> at
> > event-top.c:213
> > #30 0x0000555555aca378 in rl_callback_read_char () at callback.c:220
> > #31 0x00005555558a11b2 in gdb_rl_callback_read_char_wrapper_noexcept ()
> at
> > event-top.c:175
> > #32 0x00005555558a1231 in gdb_rl_callback_read_char_wrapper
> > (client_data=0x5555561f9030) at event-top.c:192
> > #33 0x00005555558a19ea in _Z19stdin_event_handleriPv (error=0,
> > client_data=0x5555561f9030) at event-top.c:511
> > #34 0x000055555589f930 in handle_file_event (file_ptr=0x55555af2fd60,
> > ready_mask=1) at event-loop.c:733
> > #35 0x000055555589fef9 in gdb_wait_for_event (block=1) at
> event-loop.c:859
> > #36 0x000055555589ec76 in _Z16gdb_do_one_eventv () at event-loop.c:347
> > #37 0x000055555589ecbd in _Z16start_event_loopv () at event-loop.c:371
> > #38 0x000055555592869b in captured_command_loop () at main.c:330
> > #39 0x0000555555929c7c in captured_main (data=0x7fffffffe400) at
> main.c:1157
> > #40 0x0000555555929d51 in _Z8gdb_mainP18captured_main_args
> > (args=0x7fffffffe400) at main.c:1173
> > #41 0x00005555555ff4a3 in main (argc=2, argv=0x7fffffffe508) at gdb.c:32
> >
> > "#1  0x000055555561dc64 in amd64_frame_prev_register
> > (this_frame=0x555556314750, this_cache=0x555556314768, regnum=16) at
> > amd64-tdep.c:2642", is this code snippet:
> > return frame_unwind_got_memory (this_frame, regnum,
> >    cache->saved_regs[regnum]);
> >
> > There seems to be a cache of registers.
> > The last parameter of "#0  _Z23frame_unwind_got_memoryP10frame_infoim
> > (frame=0x555556314750, regnum=16, addr=140737488309304) at
> > frame-unwind.c:236" shows that addr is 140737488309304 which is
> > "0x7fffffff4c38" in hex (RSP for the innermost ffmpeg backtrace function
> > (frame -1) that I mentioned in the first thread, is in fact equal
> > to "0x7fffffff4c38"). GDB, somehow, knows that the $RIP value for frame 0
> > (i.e. "#1  0x00007fffeaabdad9 in x264_mb_mc_01xywh (h=0x5555561dea00,
> x=0,
> > y=0, width=4, height=<optimized out>) at common/macroblock.c:128") is
> > stored at "0x7fffffff4c38" (i.e., the RSP value for frame -1). But I do
> not
> > know how! Perhaps, luckily, because there is no push/pop in the innermost
> > function of the ffmpeg workload?!
>
> If you're on x86-64 then the place to start in answering this question
> would be amd64-tdep.c:amd64_analyze_prologue.  I'm no expert on this
> code, but the basic idea is we actually inspect the instructions, and
> so long as the prologue of the function follows some basic conventions
> then we can figure out the size of the stack frame, and where the
> important bits of state have been written too.
>
> Obviously it is trivially easy to write a prologue that _can't_ be
> scanned, as Jan said earlier in the thread, the prologue scanner is a
> last ditched fall back for when no other scanner wants to claim the
> frame.
>
> I think the most common usage for the prologue scanning unwinder is to
> unwind compiler generated code when the debug info has been stripped.
> As such the "conventions" that I mention are actually just "what does
> the compiler spit out", and from time to time the prologue scanner
> will get an update as GCC/LLVM starts spitting out some new
> instruction into the prologue.
>
> Hope that helps a little.
>
> Thanks,
> Andrew
>
>
>
>
>
> >
> > Here is the initial portion of the GDB output, when frame_debug is
> enabled:
> > Thread 1 "ffmpeg" hit Breakpoint 1, 0x00007fffeab68840 in
> > x264_pixel_avg_w16_avx2 () from /usr/lib/x86_64-linux-gnu/libx264.so.152
> > (gdb) bt
> > { get_prev_frame_always (this_frame=-1) ->
> > {level=0,type=NORMAL_FRAME,unwind=0x555556191780,pc=
> 0x7fffeab68840,id=<unknown>,func=<unknown>}
> > // cached
> > { get_prev_frame_always (this_frame=-1) ->
> > {level=0,type=NORMAL_FRAME,unwind=0x555556191780,pc=
> 0x7fffeab68840,id=<unknown>,func=<unknown>}
> > // cached
> > { compute_frame_id (fi=0) { get_frame_func (this_frame=0) ->
> 0x7fffeab68840
> > }
> > { frame_unwind_register_value (frame=-1,regnum=7(rsp),...) -> register=7
> > bytes=[f845ffffff7f0000] }
> > { frame_id_p (l={stack=0x7fffffff4600,code=0x7fffeab68840,!special}) ->
> 1 }
> > -> {stack=0x7fffffff4600,code=0x7fffeab68840,!special} }
> > { get_prev_frame_always (this_frame=0) ->
> > {level=1,type=<unknown>,unwind=<unknown>,pc=<unknown>,
> id=<unknown>,func=<unknown>}
> > }
> > { compute_frame_id (fi=1) { frame_unwind_arch (next_frame=0) ->
> i386:x86-64
> > }
> > { frame_unwind_register_value (frame=0,regnum=16(rip),...) ->
> > address=0x7fffffff45f8 bytes=[d9daabeaff7f0000] }
> > { frame_unwind_pc (this_frame=0) -> 0x7fffeaabdad9 }
> > { get_frame_func (this_frame=1) -> 0x7fffeaabd860 }
> > { frame_id_p (l={!stack,!code,!special}) -> 0 }
> > { frame_unwind_register_value (frame=0,regnum=7(rsp),...) -> computed
> > bytes=[0046ffffff7f0000] }
> > { frame_id_p (l={stack=0x7fffffff4940,code=0x7fffeaabd860,!special}) ->
> 1 }
> > -> {stack=0x7fffffff4940,code=0x7fffeaabd860,!special} }
> > #0  0x00007fffeab68840 in x264_pixel_avg_w16_avx2 () from
> > /usr/lib/x86_64-linux-gnu/libx264.so.152
> > { get_prev_frame_always (this_frame=0) ->
> > {level=1,type=NORMAL_FRAME,unwind=0x5555560c8820,pc=
> 0x7fffeaabdad9,id={stack=0x7fffffff4940,code=
> 0x7fffeaabd860,!special},func=0x7fffeaabd860}
> > // cached
> > #1  0x00007fffeaabdad9 in x264_mb_mc_01xywh ({ frame_id_p
> > (l={stack=0x7fffffff4940,code=0x7fffeaabd860,!special}) -> 1 }
> > { frame_id_eq
> > (l={stack=0x7fffffff4940,code=0x7fffeaabd860,!special},r={
> stack=<sentinel>,!code,special=0x0})
> > -> 0 }
> >
> > The $RIP value for frame 0 is reported as "{ frame_unwind_register_value
> > (frame=0,regnum=16(rip),...) -> address=0x7fffffff45f8
> > bytes=[d9daabeaff7f0000] }".
> >
> > Regards.
> >
> > On Wednesday, 24 June 2020, Andrew Burgess <andrew.burgess@embecosm.com>
> > wrote:
> >
> > > * Ahmad Nouralizadeh via Gdb <gdb@sourceware.org> [2020-06-23 16:18:42
> > > +0430]:
> > >
> > > > Thanks for the answer! Could you tell me why is an inline unwinder
> used?
> > >
> > > What you saw in your GDB backtrace was this:
> > >
> > >   #5  0x00005555558b1b0b in frame_unwind_pc
> (this_frame=0x55555673c2e0) at
> > > frame.c:885
> > >   #6  0x00005555558b4f72 in _Z12get_frame_pcP10frame_info
> > > (frame=0x55555673c490) at frame.c:2379
> > >   #7  0x00005555558b50ea in _Z26get_frame_address_in_
> blockP10frame_info
> > > (this_frame=0x55555673c490) at frame.c:2410
> > >   #8  0x0000555555905d53 in inline_frame_sniffer (self=0x555556193520
> > > <inline_frame_unwind>, this_frame=0x55555673c490,
> > > this_cache=0x55555673c4a8) at inline-frame.c:215
> > >   #9  0x00005555558b719a in frame_unwind_try_unwinder
> > > (this_frame=0x55555673c490, this_cache=0x55555673c4a8,
> > > unwinder=0x555556193520 <inline_frame_unwind>) at frame-unwind.c:106
> > >
> > > So GDB hasn't decided for sure that a frame is an inline frame,
> > > instead it is running the inline_frame_sniffer to see if a particular
> > > frame is an inline frame or not.
> > >
> > > In order to figure this out GDB needs to know the value of $pc in the
> > > frame that is being sniffed.  To get the $pc value GDB asks the next
> > > frame (that would be a frame with a lower frame number in GDB terms)
> > > to unwind the $pc register.  You can see this happening between frames
> > > #8 and #6 in the above, before finally in #5 we ask the next frame to
> > > unwind the $pc.
> > >
> > > Almost every frame will have had the inline frame unwinder run on it
> > > in order to figure out if it was an inline frame, that doesn't mean
> > > the inline frame unwinder will claim the frame.
> > >
> > > Hope that helps,
> > > Thanks,
> > > Andrew
> > >
> > >
> > >
> > >
> > >
> > > >
> > > > On Tuesday, 23 June 2020, Jan Kratochvil <jan.kratochvil@redhat.com>
> > > wrote:
> > > >
> > > > > On Mon, 22 Jun 2020 23:55:30 +0200, Ahmad Nouralizadeh via Gdb
> wrote:
> > > > > > But knowing the GDB mechanism to get over the problem will be
> > > helpful.
> > > > >
> > > > > GDB disassembles the code and tries to guess how to unwind it.
> > > > > amd64-tdep.c amd64_analyze_prologue(), amd64_frame_cache_1() etc.
> > > > >
> > > > > That is just a last resort way of unwinding (=a bug in the
> debuggee),
> > > there
> > > > > should always be .eh_frame in the debuggee, also for throwing
> > > exceptions
> > > > > across such .eh_frame-less functions if there is any callback
> there.
> > > > >
> > > > >
> > > > > Jan
> > > > >
> > > > >
> > >
>