gdb: introduce scoped debug prints

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.

gdbsupport/ChangeLog:

	* common-debug.h (debug_print_depth): New.
	(struct scoped_debug_start_end): New.
	(scoped_debug_start_end): New.
	(scoped_debug_enter_exit): New.
	* common-debug.cc (debug_prefixed_vprintf): Print indentation.

gdb/ChangeLog:

	* debug.c (debug_print_depth): New.
	* infrun.h (INFRUN_SCOPED_DEBUG_START_END): New.
	(INFRUN_SCOPED_DEBUG_ENTER_EXIT): New.
	* infrun.c (start_step_over): Use
	INFRUN_SCOPED_DEBUG_ENTER_EXIT.
	(proceed): Use INFRUN_SCOPED_DEBUG_ENTER_EXIT and
	INFRUN_SCOPED_DEBUG_START_END.
	(fetch_inferior_event): Use INFRUN_SCOPED_DEBUG_ENTER_EXIT.

gdbserver/ChangeLog:

	* debug.cc (debug_print_depth): New.

gdb/testsuite/ChangeLog:

        * gdb.base/ui-redirect.exp: Expect infrun debug print after
	prompt.
        * gdb.threads/ia64-sigill.exp: Likewise.
        * gdb.threads/watchthreads-reorder.exp: Likewise.

Change-Id: I7c3805e6487807aa63a1bae318876a0c69dce949

14 files changed, 162 insertions, 12 deletions

diff --git a/gdb/ChangeLog b/gdb/ChangeLog
index 674c3964e9e..0d1c5a864c7 100644
--- a/gdb/ChangeLog
+++ b/gdb/ChangeLog
@@ -1,5 +1,16 @@
 2021-01-04  Simon Marchi  <simon.marchi@efficios.com>
 
+	* debug.c (debug_print_depth): New.
+	* infrun.h (INFRUN_SCOPED_DEBUG_START_END): New.
+	(INFRUN_SCOPED_DEBUG_ENTER_EXIT): New.
+	* infrun.c (start_step_over): Use
+	INFRUN_SCOPED_DEBUG_ENTER_EXIT.
+	(proceed): Use INFRUN_SCOPED_DEBUG_ENTER_EXIT and
+	INFRUN_SCOPED_DEBUG_START_END.
+	(fetch_inferior_event): Use INFRUN_SCOPED_DEBUG_ENTER_EXIT.
+
+2021-01-04  Simon Marchi  <simon.marchi@efficios.com>
+
 	* infrun.c (print_target_wait_results): Use infrun_debug_printf.
 
 2021-01-04  Simon Marchi  <simon.marchi@efficios.com>
diff --git a/gdb/debug.c b/gdb/debug.c
index 94eb39b6d97..f7dfee1cfeb 100644
--- a/gdb/debug.c
+++ b/gdb/debug.c
@@ -23,6 +23,10 @@
 
 /* See gdbsupport/common-debug.h.  */
 
+int debug_print_depth = 0;
+
+/* See gdbsupport/common-debug.h.  */
+
 void
 debug_vprintf (const char *fmt, va_list ap)
 {
diff --git a/gdb/infrun.c b/gdb/infrun.c
index 01d7ead8a41..45bedf89641 100644
--- a/gdb/infrun.c
+++ b/gdb/infrun.c
@@ -1833,6 +1833,8 @@ static step_over_what thread_still_needs_step_over (struct thread_info *tp);
 static bool
 start_step_over (void)
 {
+  INFRUN_SCOPED_DEBUG_ENTER_EXIT;
+
   thread_info *next;
 
   /* Don't start a new step-over if we already have an in-line
@@ -2849,6 +2851,8 @@ check_multi_target_resumption (process_stratum_target *resume_target)
 void
 proceed (CORE_ADDR addr, enum gdb_signal siggnal)
 {
+  INFRUN_SCOPED_DEBUG_ENTER_EXIT;
+
   struct regcache *regcache;
   struct gdbarch *gdbarch;
   CORE_ADDR pc;
@@ -3018,6 +3022,9 @@ proceed (CORE_ADDR addr, enum gdb_signal siggnal)
       }
     else if (!non_stop && target_is_non_stop_p ())
       {
+	INFRUN_SCOPED_DEBUG_START_END
+	  ("resuming threads, all-stop-on-top-of-non-stop");
+
 	/* In all-stop, but the target is always in non-stop mode.
 	   Start all other threads that are implicitly resumed too.  */
 	for (thread_info *tp : all_non_exited_threads (resume_target,
@@ -3771,6 +3778,8 @@ all_uis_on_sync_execution_starting (void)
 void
 fetch_inferior_event ()
 {
+  INFRUN_SCOPED_DEBUG_ENTER_EXIT;
+
   struct execution_control_state ecss;
   struct execution_control_state *ecs = &ecss;
   int cmd_done = 0;
diff --git a/gdb/infrun.h b/gdb/infrun.h
index 6bac31be023..7160b60f136 100644
--- a/gdb/infrun.h
+++ b/gdb/infrun.h
@@ -36,6 +36,16 @@ extern bool debug_infrun;
 #define infrun_debug_printf(fmt, ...) \
   debug_prefixed_printf_cond (debug_infrun, "infrun",fmt, ##__VA_ARGS__)
 
+/* Print "infrun" start/end debug statements.  */
+
+#define INFRUN_SCOPED_DEBUG_START_END(msg) \
+  scoped_debug_start_end (debug_infrun, "infrun", msg)
+
+/* Print "infrun" enter/exit debug statements.  */
+
+#define INFRUN_SCOPED_DEBUG_ENTER_EXIT \
+  scoped_debug_enter_exit (debug_infrun, "infrun")
+
 /* Nonzero if we want to give control to the user when we're notified
    of shared library events by the dynamic linker.  */
 extern int stop_on_solib_events;
diff --git a/gdb/testsuite/ChangeLog b/gdb/testsuite/ChangeLog
index 44afe3629b5..92675799d12 100644
--- a/gdb/testsuite/ChangeLog
+++ b/gdb/testsuite/ChangeLog
@@ -1,5 +1,9 @@
 2021-01-04  Simon Marchi  <simon.marchi@efficios.com>
 
+
+
+2021-01-04  Simon Marchi  <simon.marchi@efficios.com>
+
 	* gdb.server/abspath.exp: Append "set sysroot" to GDBFLAGS.
 	* gdb.server/connect-without-multi-process.exp: Likewise.
 	* gdb.server/exit-multiple-threads.exp: Likewise.
diff --git a/gdb/testsuite/gdb.base/ui-redirect.exp b/gdb/testsuite/gdb.base/ui-redirect.exp
index 21fbb58aff7..af428000607 100644
--- a/gdb/testsuite/gdb.base/ui-redirect.exp
+++ b/gdb/testsuite/gdb.base/ui-redirect.exp
@@ -117,7 +117,14 @@ with_test_prefix "debugging" {
     gdb_test "set debug infrun 1"
     gdb_test "set logging on" \
     "Copying output to /dev/null.*Copying debug output to /dev/null\\."
-    gdb_test "continue" {Continuing.*\[infrun\] .*\[infrun\] .*Breakpoint [0-9]+, foo.*}
+
+    set prompt "$gdb_prompt \\\[infrun\\\] fetch_inferior_event: exit\r\n$"
+    gdb_test_multiple "continue" "continue" -prompt $prompt {
+	-re "Continuing.*\\\[infrun\\\] .*\\\[infrun\\\] .*Breakpoint \[0-9\]+, foo.*$prompt$" {
+	    pass $gdb_test_name
+	}
+    }
+
     gdb_test "set debug infrun 0"
     gdb_test "set logging off" "Done logging to /dev/null\\."
     gdb_test "help" "List of classes of commands:.*"
diff --git a/gdb/testsuite/gdb.threads/ia64-sigill.exp b/gdb/testsuite/gdb.threads/ia64-sigill.exp
index e4d3056d8e9..636b387d388 100644
--- a/gdb/testsuite/gdb.threads/ia64-sigill.exp
+++ b/gdb/testsuite/gdb.threads/ia64-sigill.exp
@@ -57,17 +57,21 @@ gdb_test_no_output "set debug infrun 1"
 
 # The ia64 SIGILL signal is visible only in the lin-lwp debug.
 
-gdb_test "continue" "Breakpoint \[0-9\]+,( .* in)? thread_func .*"
+set prompt "$gdb_prompt \\\[infrun\\\] fetch_inferior_event: exit\r\n$"
+gdb_test_multiple "continue" "continue" -prompt $prompt {
+    -re "Breakpoint \[0-9\]+,( .* in)? thread_func .*$prompt$" {
+	pass $gdb_test_name
+    }
+}
 
 gdb_test_no_output {delete $sigill_bpnum}
 
-set test "continue for the pending signal"
-gdb_test_multiple "continue" $test {
-    -re "Breakpoint \[0-9\]+, .*break-at-exit.*\r\n$gdb_prompt $" {
+gdb_test_multiple "continue" "continue for the pending signal" -prompt $prompt {
+    -re "Breakpoint \[0-9\]+, .*break-at-exit.*\r\n$prompt$" {
 	# Breakpoint has been skipped in the other thread.
-	pass $test
+	pass $gdb_test_name
     }
     -re " received signal .*\r\n$gdb_prompt $" {
-	fail $test
+	fail $gdb_test_name
     }
 }
diff --git a/gdb/testsuite/gdb.threads/stepi-random-signal.exp b/gdb/testsuite/gdb.threads/stepi-random-signal.exp
index d4e066ef07d..6a474e1e400 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
diff --git a/gdb/testsuite/gdb.threads/watchthreads-reorder.exp b/gdb/testsuite/gdb.threads/watchthreads-reorder.exp
index 7cdbba545df..98c6af75213 100644
--- a/gdb/testsuite/gdb.threads/watchthreads-reorder.exp
+++ b/gdb/testsuite/gdb.threads/watchthreads-reorder.exp
@@ -90,5 +90,10 @@ foreach reorder {0 1} { with_test_prefix "reorder$reorder" {
     # found in the DEBUG_INFRUN code path.
     gdb_test "set debug infrun 1"
 
-    gdb_continue_to_breakpoint "break-at-exit" ".*break-at-exit.*"
+    set prompt "$gdb_prompt \\\[infrun\\\] fetch_inferior_event: exit\r\n$"
+    gdb_test_multiple "continue" "continue to breakpoint: break-at-exit" -prompt $prompt {
+        -re ".*break-at-exit.*$prompt$" {
+	    pass $gdb_test_name
+	}
+    }
 }}
diff --git a/gdbserver/ChangeLog b/gdbserver/ChangeLog
index a30678df605..6c7738e8077 100644
--- a/gdbserver/ChangeLog
+++ b/gdbserver/ChangeLog
@@ -1,3 +1,7 @@
+2021-01-04  Simon Marchi  <simon.marchi@efficios.com>
+
+	* debug.cc (debug_print_depth): New.
+
 2021-01-01  Joel Brobecker  <brobecker@adacore.com>
 
 	* server.cc (gdbserver_version): Update copyright year.
diff --git a/gdbserver/debug.cc b/gdbserver/debug.cc
index c7a1e5f0191..b3a5fe1b15c 100644
--- a/gdbserver/debug.cc
+++ b/gdbserver/debug.cc
@@ -64,6 +64,10 @@ debug_set_output (const char *new_debug_file)
 
 #endif
 
+/* See gdbsupport/common-debug.h.  */
+
+int debug_print_depth = 0;
+
 /* Print a debugging message.
    If the text begins a new line it is preceded by a timestamp.
    We don't get fancy with newline checking, we just check whether the
diff --git a/gdbsupport/ChangeLog b/gdbsupport/ChangeLog
index cc21b0b50f0..2c69581fbce 100644
--- a/gdbsupport/ChangeLog
+++ b/gdbsupport/ChangeLog
@@ -1,3 +1,11 @@
+2021-01-04  Simon Marchi  <simon.marchi@efficios.com>
+
+	* common-debug.h (debug_print_depth): New.
+	(struct scoped_debug_start_end): New.
+	(scoped_debug_start_end): New.
+	(scoped_debug_enter_exit): New.
+	* common-debug.cc (debug_prefixed_vprintf): Print indentation.
+
 2020-12-11  Andrew Burgess  <andrew.burgess@embecosm.com>
 
 	* gdbsupport/common-utils.cc: Change 'ctype.h' include to
diff --git a/gdbsupport/common-debug.cc b/gdbsupport/common-debug.cc
index 1eb193cff81..0d3e9198921 100644
--- a/gdbsupport/common-debug.cc
+++ b/gdbsupport/common-debug.cc
@@ -55,7 +55,7 @@ void
 debug_prefixed_vprintf (const char *module, const char *func,
 			const char *format, va_list args)
 {
-  debug_printf ("[%s] %s: ", module, func);
+  debug_printf ("%*s[%s] %s: ", debug_print_depth * 2, "", module, func);
   debug_vprintf (format, args);
   debug_printf ("\n");
 }
diff --git a/gdbsupport/common-debug.h b/gdbsupport/common-debug.h
index e5de9808006..f3137870ffc 100644
--- a/gdbsupport/common-debug.h
+++ b/gdbsupport/common-debug.h
@@ -50,7 +50,6 @@ extern void ATTRIBUTE_PRINTF (3, 4) debug_prefixed_printf
 extern void ATTRIBUTE_PRINTF (3, 0) debug_prefixed_vprintf
   (const char *module, const char *func, const char *format, va_list args);
 
-
 /* Helper to define "_debug_print" macros.
 
    DEBUG_ENABLED_COND is an expression that evaluates to true if the debugging
@@ -67,4 +66,84 @@ extern void ATTRIBUTE_PRINTF (3, 0) debug_prefixed_vprintf
     } \
   while (0)
 
+/* Nesting depth of scoped_debug_start_end objects.  */
+
+extern int debug_print_depth;
+
+/* Print a message on construction and destruction, to denote the start and end
+   of an operation.  Increment DEBUG_PRINT_DEPTH on construction and decrement
+   it on destruction, such that nested debug statements will be printed with
+   an indent and appear "inside" this one.  */
+
+struct scoped_debug_start_end
+{
+  /* DEBUG_ENABLED is a reference to a variable that indicates whether debugging
+     is enabled, so if the debug statements should be printed.  Is is read
+     separately at construction and destruction, such that the start statement
+     could be printed but not the end statement, or vice-versa.
+
+     MODULE and FUNC are forwarded to debug_prefixed_printf.
+
+     START_MSG and END_MSG are the statements to print on construction and
+     destruction, respectively.  */
+
+  scoped_debug_start_end (bool &debug_enabled, const char *module,
+			  const char *func, const char *start_msg,
+			  const char *end_msg)
+    : m_debug_enabled (debug_enabled),
+      m_module (module),
+      m_func (func),
+      m_end_msg (end_msg)
+  {
+    if (m_debug_enabled)
+      {
+	debug_prefixed_printf (m_module, m_func, "%s", start_msg);
+	++debug_print_depth;
+	m_must_decrement_print_depth = true;
+      }
+  }
+
+  DISABLE_COPY_AND_ASSIGN (scoped_debug_start_end);
+
+  ~scoped_debug_start_end ()
+  {
+    if (m_must_decrement_print_depth)
+      {
+	gdb_assert (debug_print_depth > 0);
+	--debug_print_depth;
+      }
+
+    if (m_debug_enabled)
+      {
+	debug_prefixed_printf (m_module, m_func, "%s", m_end_msg);
+      }
+  }
+
+private:
+  bool &m_debug_enabled;
+  const char *m_module;
+  const char *m_func;
+  const char *m_end_msg;
+
+  /* This is used to handle the case where debugging is enabled during
+     construction but not during destruction, or vice-versa.  We want to make
+     sure there are as many increments are there are decrements.  */
+
+  bool m_must_decrement_print_depth = false;
+};
+
+/* Helper to define a module-specific start/end debug macro.  */
+
+#define scoped_debug_start_end(debug_enabled, module, msg) \
+  scoped_debug_start_end CONCAT(scoped_debug_start_end, __LINE__) \
+    (debug_enabled, module, __func__, "start: " msg, "end: " msg)
+
+/* Helper to define a module-specific enter/exit debug macro.  This is a special
+   case of `scoped_debug_start_end` where the start and end messages are "enter"
+   and "exit", to denote entry and exit of a function.  */
+
+#define scoped_debug_enter_exit(debug_enabled, module) \
+  scoped_debug_start_end CONCAT(scoped_debug_start_end, __LINE__) \
+    (debug_enabled, module, __func__, "enter", "exit")
+
 #endif /* COMMON_COMMON_DEBUG_H */