Re: [PATCH v2 3/3] gdb: introduce scoped debug prints

[Simon Marchi via Gdb-patches <gdb-patches@sourceware.org>]

On 2020-12-16 3:47 p.m., Simon Marchi via Gdb-patches wrote:
> New in v2:
> 
> - Print indentation using %*s format specifier.
> - Add missing space
> - Use DISABLE_COPY_AND_ASSIGN
> 
> I spent a lot of time reading infrun debug logs recently, and I think
> they could be made much more readable by being indented, to clearly see
> what operation is done as part of what other operation.  In the current
> format, there are no visual cues to tell where things start and end,
> it's just a big flat list.  It's also difficult to understand what
> caused a given operation (e.g. a call to resume_1) to be done.
> 
> To help with this, I propose to add the new scoped_debug_start_end
> structure, along with a bunch of macros to make it convenient to use.
> 
> The idea of scoped_debug_start_end is simply to print a start and end
> message at construction and destruction.  It also increments/decrements
> a depth counter in order to make debug statements printed during this
> range use some indentation.  Some care is taken to handle the fact that
> debug can be turned on or off in the middle of such a range.  For
> example, a "set debug foo 1" command in a breakpoint command, or a
> superior GDB manually changing the debug_foo variable.
> 
> Two macros are added in gdbsupport/common-debug.h, which are helpers to
> define module-specific macros:
> 
>   - scoped_debug_start_end: takes a message that is printed both at
>     construction / destruction, with "start: " and "end: " prefixes.
>   - scoped_debug_enter_exit: prints hard-coded "enter" and "exit"
>     messages, to denote the entry and exit of a function.
> 
> I added some examples in the infrun module to give an idea of how it can
> be used and what the result looks like.  The macros are in capital
> letters (INFRUN_SCOPED_DEBUG_START_END and
> INFRUN_SCOPED_DEBUG_ENTER_EXIT) to mimic the existing SCOPE_EXIT, but
> that can be changed if you prefer something else.
> 
> Here's an excerpt of the debug
> statements printed when doing "continue", where a displaced step is
> started:
> 
>     [infrun] proceed: enter
>       [infrun] proceed: addr=0xffffffffffffffff, signal=GDB_SIGNAL_DEFAULT
>       [infrun] global_thread_step_over_chain_enqueue: enqueueing thread Thread 0x7ffff75a5640 (LWP 2289301) in global step over chain
>       [infrun] start_step_over: enter
>         [infrun] start_step_over: stealing global queue of threads to step, length = 1
>         [infrun] start_step_over: resuming [Thread 0x7ffff75a5640 (LWP 2289301)] for step-over
>         [infrun] resume_1: step=1, signal=GDB_SIGNAL_0, trap_expected=1, current thread [Thread 0x7ffff75a5640 (LWP 2289301)] at 0x5555555551bd
>         [displaced] displaced_step_prepare_throw: displaced-stepping Thread 0x7ffff75a5640 (LWP 2289301) now
>         [displaced] prepare: selected buffer at 0x5555555550c2
>         [displaced] prepare: saved 0x5555555550c2: 1e fa 31 ed 49 89 d1 5e 48 89 e2 48 83 e4 f0 50
>         [displaced] amd64_displaced_step_copy_insn: copy 0x5555555551bd->0x5555555550c2: c7 45 fc 00 00 00 00 eb 13 8b 05 d4 2e 00 00 83
>         [displaced] displaced_step_prepare_throw: prepared successfully thread=Thread 0x7ffff75a5640 (LWP 2289301), original_pc=0x5555555551bd, displaced_pc=0x5555555550c2
>         [displaced] resume_1: run 0x5555555550c2: c7 45 fc 00
>         [infrun] infrun_async: enable=1
>         [infrun] prepare_to_wait: prepare_to_wait
>         [infrun] start_step_over: [Thread 0x7ffff75a5640 (LWP 2289301)] was resumed.
>         [infrun] operator(): step-over queue now empty
>       [infrun] start_step_over: exit
>       [infrun] proceed: start: resuming threads, all-stop-on-top-of-non-stop
>         [infrun] proceed: resuming Thread 0x7ffff7da7740 (LWP 2289296)
>         [infrun] resume_1: step=0, signal=GDB_SIGNAL_0, trap_expected=0, current thread [Thread 0x7ffff7da7740 (LWP 2289296)] at 0x7ffff7f7d9b7
>         [infrun] prepare_to_wait: prepare_to_wait
>         [infrun] proceed: resuming Thread 0x7ffff7da6640 (LWP 2289300)
>         [infrun] resume_1: thread Thread 0x7ffff7da6640 (LWP 2289300) has pending wait status status->kind = stopped, signal = GDB_SIGNAL_TRAP (currently_stepping=0).
>         [infrun] prepare_to_wait: prepare_to_wait
>         [infrun] proceed: [Thread 0x7ffff75a5640 (LWP 2289301)] resumed
>         [infrun] proceed: resuming Thread 0x7ffff6da4640 (LWP 2289302)
>         [infrun] resume_1: thread Thread 0x7ffff6da4640 (LWP 2289302) has pending wait status status->kind = stopped, signal = GDB_SIGNAL_TRAP (currently_stepping=0).
>         [infrun] prepare_to_wait: prepare_to_wait
>       [infrun] proceed: end: resuming threads, all-stop-on-top-of-non-stop
>     [infrun] proceed: exit
> 
> We can easily see where the call to `proceed` starts and end.  We can
> also see why there are a bunch of resume_1 calls, it's because we are
> resuming threads, emulating all-stop on top of a non-stop target.
> 
> We also see that debug statements nest well with other modules that have
> been migrated to use the "new" debug statement helpers (because they all
> use debug_prefixed_vprintf in the end.  I think this is desirable, for
> example we could see the debug statements about reading the DWARF info
> of a library nested under the debug statements about loading that
> library.
> 
> Of course, modules that haven't been migrated to use the "new" helpers
> will still print without indentations.  This will be one good reason to
> migrate them.
> 
> I think the runtime cost (when debug statements are disabled) of this is
> reasonable, given the improvement in readability.  There is the cost of
> the conditionals (like standard debug statements), one more condition
> (if (m_must_decrement_print_depth)) and the cost of constructing a stack
> object, which means copying a fews pointers.
> 
> Adding the print in fetch_inferior_event breaks some tests that use "set
> debug infrun", because it prints a debug statement after the prompt.  I
> adapted these tests to cope with it, by using the "-prompt" switch of
> gdb_test_multiple to as if this debug statement is part of the expected
> prompt.  It's unfortunate that we have to do this, but I think the debug
> print is useful, and I don't want a few tests to get in the way of
> adding good debug output.

With this patch, gdb.threads/stepi-random-signal.exp becomes flaky.  I folded
this little fixup in the patch:

commit 49c94827cbbe802726f177bc61c6c9d830907ffa
Author: Simon Marchi <simon.marchi@polymtl.ca>
Date:   Tue Dec 22 16:33:40 2020 -0500

    fixup
    
    Change-Id: Ibd2f622df3e76c873fcf82bca7c4c7900654647e

diff --git a/gdb/testsuite/gdb.threads/stepi-random-signal.exp b/gdb/testsuite/gdb.threads/stepi-random-signal.exp
index 9a8b38c2acf5..689de8fdc632 100644
--- a/gdb/testsuite/gdb.threads/stepi-random-signal.exp
+++ b/gdb/testsuite/gdb.threads/stepi-random-signal.exp
@@ -86,12 +86,13 @@ if {$prev_addr == ""} {
 set seen 0
 
 set test "stepi"
-if {[gdb_test_multiple "stepi" "$test" {
+set prompt "$gdb_prompt \\\[infrun\\\] fetch_inferior_event: exit\r\n$"
+if {[gdb_test_multiple "stepi" "$test" -prompt $prompt {
     -re {\[infrun\] handle_signal_stop: random signal} {
 	set seen 1
 	exp_continue
     }
-    -re "$gdb_prompt $" {
+    -re "$prompt$" {
     }
 }] != 0} {
     return


Simon