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

Simon Marchi via Gdb-patches
2020-12-22T21:35:38Z

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