Re: GDB Frame Unwinding for Pure Assembly Code

[Andrew Burgess <andrew.burgess@embecosm.com>]

* 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
> > > >
> > > >
> >