[PATCH v2 1/3] gdb: make "set debug timestamp" work nice with new debug printouts

[PATCH v2 1/3] gdb: make "set debug timestamp" work nice with new debug printouts

[Simon Marchi]

New in v2:

- implement by modifying vprintf_unfiltered rather than
  debug_prefixed_vprintf.

I tried enabling debug timestamps, and realized that it doesn't play
well with the revamp of the debug printouts I've been working on:

    $ ./gdb -q -nx --data-directory=data-directory -ex "set debug infrun" -ex "set debug timestamp" a.out
    Reading symbols from a.out...
    (gdb) start
    Temporary breakpoint 1 at 0x1131: file test.c, line 2.
    Starting program: /home/smarchi/build/binutils-gdb-all-targets/gdb/a.out
    939897.769338 [infrun] infrun_async:
    939897.769383 enable=1
    939897.769409
    939897.915218 [infrun] proceed:
    939897.915281 addr=0x7ffff7fd0100, signal=GDB_SIGNAL_0
    939897.915315
    939897.915417 [infrun] start_step_over:
    939897.915464 stealing global queue of threads to step, length = 0
    939897.915502
    939897.915567 [infrun] operator():
    939897.915601 step-over queue now empty
    939897.915633
    939897.915690 [infrun] proceed:
    939897.915729 resuming process 636244
    939897.915768
    939897.915892 [infrun] resume_1:
    939897.915954 step=0, signal=GDB_SIGNAL_0, trap_expected=0, current thread [process 636244] at 0x7ffff7fd0100
    939897.915991
    939897.916119 [infrun] prepare_to_wait:
    939897.916153 prepare_to_wait
    939897.916201
    939897.916661 [infrun] target_wait (-1.0.0, status) =
    [infrun]   636244.636244.0 [process 636244],
    [infrun]   status->kind = stopped, signal = GDB_SIGNAL_TRAP
    939897.916734 [infrun] handle_inferior_event:
    939897.916768 status->kind = stopped, signal = GDB_SIGNAL_TRAP
    939897.916799

This is due to debug_prefixed_vprintf being implemented as three
separate calls to debug_printf / debug_vprintf.  Each call gets its own
timestamp and newline, curtesy of vprintf_unfiltered.

My first idea was to add a "line_start" parameter to debug_vprintf,
allowing the caller to say whether the print is the start of the line.
A debug timestamp would only be printed if line_start was true.
However, that was much more invasive than the simple fix implemented in
this patch.

My second idea was to make debug_prefixed_vprintf use string_printf and
issue a single call to debug_printf.  That would however prevent future
use of styling in the debug messages.

What is implemented in this patch is the same as is implemented in
GDBserver: the timestamp-printing code in GDB tracks whether the last
debug output ended with a newline.  If so, it prints a timestamp on the
next debug output.

After the fix, it looks like this:

    $ ./gdb -q -nx --data-directory=data-directory -ex "set debug infrun" -ex "set debug timestamp" a.out
    Reading symbols from a.out...
    (gdb) start
    Temporary breakpoint 1 at 0x1131: file test.c, line 2.
    Starting program: /home/smarchi/build/binutils-gdb-all-targets/gdb/a.out
    941112.135662 [infrun] infrun_async: enable=1
    941112.279930 [infrun] proceed: addr=0x7ffff7fd0100, signal=GDB_SIGNAL_0
    941112.280064 [infrun] start_step_over: stealing global queue of threads to step, length = 0
    941112.280125 [infrun] operator(): step-over queue now empty
    941112.280194 [infrun] proceed: resuming process 646228
    941112.280332 [infrun] resume_1: step=0, signal=GDB_SIGNAL_0, trap_expected=0, current thread [process 646228] at 0x7ffff7fd0100
    941112.280480 [infrun] prepare_to_wait: prepare_to_wait
    941112.281004 [infrun] target_wait (-1.0.0, status) =
    [infrun]   646228.646228.0 [process 646228],
    [infrun]   status->kind = stopped, signal = GDB_SIGNAL_TRAP
    941112.281078 [infrun] handle_inferior_event: status->kind = stopped, signal = GDB_SIGNAL_TRAP

gdb/ChangeLog:

	* utils.c (vfprintf_unfiltered): Print timestamp only when
	previous debug output ended with a newline.

Change-Id: Idcfe3acc7e3d0f526a5f0a43a5e0884bf93c41ae
---
 gdb/utils.c | 34 +++++++++++++++++++---------------
 1 file changed, 19 insertions(+), 15 deletions(-)

diff --git a/gdb/utils.c b/gdb/utils.c
index abcf6e256b0..5d6fa61910c 100644
--- a/gdb/utils.c
+++ b/gdb/utils.c
@@ -2126,26 +2126,30 @@ vfprintf_unfiltered (struct ui_file *stream, const char *format, va_list args)
 {
   if (debug_timestamp && stream == gdb_stdlog)
     {
-      using namespace std::chrono;
-      int len, need_nl;
+      static bool needs_timestamp = true;
 
+      /* Print timestamp if previous print ended with a \n.  */
+      if (needs_timestamp)
+	{
+	  using namespace std::chrono;
+
+	  steady_clock::time_point now = steady_clock::now ();
+	  seconds s = duration_cast<seconds> (now.time_since_epoch ());
+	  microseconds us = duration_cast<microseconds> (now.time_since_epoch () - s);
+	  std::string timestamp = string_printf ("%ld.%06ld ",
+						 (long) s.count (),
+						 (long) us.count ());
+	  fputs_unfiltered (timestamp.c_str (), stream);
+	}
+
+      /* Print the message.  */
       string_file sfile;
       cli_ui_out (&sfile, 0).vmessage (ui_file_style (), format, args);
       std::string linebuffer = std::move (sfile.string ());
+      fputs_unfiltered (linebuffer.c_str (), stream);
 
-      steady_clock::time_point now = steady_clock::now ();
-      seconds s = duration_cast<seconds> (now.time_since_epoch ());
-      microseconds us = duration_cast<microseconds> (now.time_since_epoch () - s);
-
-      len = linebuffer.size ();
-      need_nl = (len > 0 && linebuffer[len - 1] != '\n');
-
-      std::string timestamp = string_printf ("%ld.%06ld %s%s",
-					     (long) s.count (),
-					     (long) us.count (),
-					     linebuffer.c_str (),
-					     need_nl ? "\n": "");
-      fputs_unfiltered (timestamp.c_str (), stream);
+      size_t len = linebuffer.length ();
+      needs_timestamp = (len > 0 && linebuffer[len - 1] == '\n');
     }
   else
     vfprintf_maybe_filtered (stream, format, args, false, true);
-- 
2.29.2

[PATCH v2 2/3] gdb: use infrun_debug_printf in print_target_wait_results

[Simon Marchi]

The code in print_target_wait_results uses a single call to debug_printf
in order to make sure a single timestamp is emitted, despite printing
multiple lines.  The result is:

    941502.043284 [infrun] target_wait (-1.0.0, status) =
    [infrun]   649832.649832.0 [process 649832],
    [infrun]   status->kind = stopped, signal = GDB_SIGNAL_TRAP

I find this decision a bit counter productive, because it messes up the
alignment of the three lines.  We don't care that three (slightly
different) timestamps are printed.

I suggest to change this function to use infrun_debug_printf, with this
result:

    941601.425771 [infrun] print_target_wait_results: target_wait (-1.0.0 [process -1], status) =
    941601.425824 [infrun] print_target_wait_results:   651481.651481.0 [process 651481],
    941601.425867 [infrun] print_target_wait_results:   status->kind = stopped, signal = GDB_SIGNAL_TRAP

Note that the current code only prints the waiton_ptid as a string
between square brackets if pid != -1.  I don't think this complexity is
needed in a debug print.  I made it so it's always printed, which I
think results in a much simpler function.

gdb/ChangeLog:

	* infrun.c (print_target_wait_results): Use infrun_debug_printf.

Change-Id: I817bd10286b8e641a6c751ac3a1bd1ddf9b18ce0
---
 gdb/infrun.c | 36 +++++++++++-------------------------
 1 file changed, 11 insertions(+), 25 deletions(-)

diff --git a/gdb/infrun.c b/gdb/infrun.c
index f509481e3d3..fe07be5e381 100644
--- a/gdb/infrun.c
+++ b/gdb/infrun.c
@@ -3275,31 +3275,17 @@ void
 print_target_wait_results (ptid_t waiton_ptid, ptid_t result_ptid,
 			   const struct target_waitstatus *ws)
 {
-  std::string status_string = target_waitstatus_to_string (ws);
-  string_file stb;
-
-  /* The text is split over several lines because it was getting too long.
-     Call fprintf_unfiltered (gdb_stdlog) once so that the text is still
-     output as a unit; we want only one timestamp printed if debug_timestamp
-     is set.  */
-
-  stb.printf ("[infrun] target_wait (%d.%ld.%ld",
-	      waiton_ptid.pid (),
-	      waiton_ptid.lwp (),
-	      waiton_ptid.tid ());
-  if (waiton_ptid.pid () != -1)
-    stb.printf (" [%s]", target_pid_to_str (waiton_ptid).c_str ());
-  stb.printf (", status) =\n");
-  stb.printf ("[infrun]   %d.%ld.%ld [%s],\n",
-	      result_ptid.pid (),
-	      result_ptid.lwp (),
-	      result_ptid.tid (),
-	      target_pid_to_str (result_ptid).c_str ());
-  stb.printf ("[infrun]   %s\n", status_string.c_str ());
-
-  /* This uses %s in part to handle %'s in the text, but also to avoid
-     a gcc error: the format attribute requires a string literal.  */
-  fprintf_unfiltered (gdb_stdlog, "%s", stb.c_str ());
+  infrun_debug_printf ("target_wait (%d.%ld.%ld [%s], status) =",
+		       waiton_ptid.pid (),
+		       waiton_ptid.lwp (),
+		       waiton_ptid.tid (),
+		       target_pid_to_str (waiton_ptid).c_str ());
+  infrun_debug_printf ("  %d.%ld.%ld [%s],",
+		       result_ptid.pid (),
+		       result_ptid.lwp (),
+		       result_ptid.tid (),
+		       target_pid_to_str (result_ptid).c_str ());
+  infrun_debug_printf ("  %s", target_waitstatus_to_string (ws).c_str ());
 }
 
 /* Select a thread at random, out of those which are resumed and have
-- 
2.29.2

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

[Simon Marchi]

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.

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
---
 gdb/debug.c                                   |  4 +
 gdb/infrun.c                                  |  9 +++
 gdb/infrun.h                                  | 10 +++
 gdb/testsuite/gdb.base/ui-redirect.exp        |  9 ++-
 gdb/testsuite/gdb.threads/ia64-sigill.exp     | 16 ++--
 .../gdb.threads/watchthreads-reorder.exp      |  7 +-
 gdbserver/debug.cc                            |  4 +
 gdbsupport/common-debug.cc                    |  2 +-
 gdbsupport/common-debug.h                     | 81 ++++++++++++++++++-
 9 files changed, 132 insertions(+), 10 deletions(-)

diff --git a/gdb/debug.c b/gdb/debug.c
index fe571aaae39..b1d56b489a9 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 fe07be5e381..2c0251014f2 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 3b5ab75175e..195349269cc 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/gdb.base/ui-redirect.exp b/gdb/testsuite/gdb.base/ui-redirect.exp
index 9e0a694c798..c1db696776f 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 84d50b0851f..b9cfd344476 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/watchthreads-reorder.exp b/gdb/testsuite/gdb.threads/watchthreads-reorder.exp
index 8c4aaff276b..8ab6caa59cf 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/debug.cc b/gdbserver/debug.cc
index 7bb2504570d..b91de4b4d85 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/common-debug.cc b/gdbsupport/common-debug.cc
index 38f6023f497..c88996b7bb3 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 7bc62185f7a..3aa7d93e940 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 */
-- 
2.29.2

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

[Simon Marchi]

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

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

[Simon Marchi]

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


I pushed this series, including this fix.

Simon

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

[Tom de Vries]

On 1/4/21 6:02 PM, Simon Marchi via Gdb-patches wrote:
> 
>> 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
>>
> 
> 
> I pushed this series, including this fix.

Hi Simon,

starting this commit, I run into:
...
51            callme ();^M
gdb_expect_list pattern: //
  [infrun] infrun_async: enable=0^M
(gdb) [infrun] fetch_inferior_event: exit^M
FAIL: gdb.threads/signal-while-stepping-over-bp-other-thread.exp: step
(pattern 6 + sentinel) (timeout)
...
which before the commit was:
...
51            callme ();^M
gdb_expect_list pattern: //
[infrun] infrun_async: enable=0^M
(gdb) PASS: gdb.threads/signal-while-stepping-over-bp-other-thread.exp: step
...

Using patch below, the test passes for me again.

[ I first tried to override $gdb_prompt for the duration of
gdb_test_sequence using save_vars, but there's the invariant that the
gdb_prompt variable has an implicit " " after it, which
gdb_test_sequence adds, so that didn't work. ]

Thanks,
- Tom

diff --git
a/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
b/gdb
/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
index fe842531977..2b3aec6562e 100644
---
a/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
+++
b/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
@@ -102,12 +102,15 @@ gdb_test "set scheduler-locking off"
 gdb_test "set debug infrun 1"

 set test "step"
-gdb_test_sequence $test $test {
+send_gdb "$test\n"
+set prompt "$gdb_prompt \\\[infrun\\\] fetch_inferior_event: exit\r\n$"
+gdb_expect_list $test $prompt {
     "need to step-over"
     "resume_1: step=1,"
     "signal arrived while stepping over breakpoint"
     "stepped to a different line"
     "callme"
+    ""
 }

 set cnt_after [get_value "args\[$my_number\]" "get count after step"]

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

[Tom de Vries]

[-- Attachment #1: Type: text/plain, Size: 428 bytes --]

On 1/5/21 10:01 AM, Tom de Vries wrote:
> [ I first tried to override $gdb_prompt for the duration of
> gdb_test_sequence using save_vars, but there's the invariant that the
> gdb_prompt variable has an implicit " " after it, which
> gdb_test_sequence adds, so that didn't work. ]

So, if we introduce a variable gdb_prompt_full which does contain the
space, and use it in gdb_test_sequence, we can override it.

Thanks,
- Tom


[-- Attachment #2: tmp.patch --]
[-- Type: text/x-patch, Size: 2105 bytes --]

diff --git a/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp b/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
index fe842531977..03f9c135361 100644
--- a/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
+++ b/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
@@ -102,12 +102,16 @@ gdb_test "set scheduler-locking off"
 gdb_test "set debug infrun 1"
 
 set test "step"
-gdb_test_sequence $test $test {
-    "need to step-over"
-    "resume_1: step=1,"
-    "signal arrived while stepping over breakpoint"
-    "stepped to a different line"
-    "callme"
+save_vars { gdb_prompt_full } {
+    set gdb_prompt_full \
+	"$gdb_prompt_full\\\[infrun\\\] fetch_inferior_event: exit\r\n"
+    gdb_test_sequence $test $test {
+	"need to step-over"
+	"resume_1: step=1,"
+	"signal arrived while stepping over breakpoint"
+	"stepped to a different line"
+	"callme"
+    }
 }
 
 set cnt_after [get_value "args\[$my_number\]" "get count after step"]
diff --git a/gdb/testsuite/lib/gdb.exp b/gdb/testsuite/lib/gdb.exp
index 3f61da8adf1..cf64bd21305 100644
--- a/gdb/testsuite/lib/gdb.exp
+++ b/gdb/testsuite/lib/gdb.exp
@@ -142,6 +142,9 @@ if ![info exists gdb_prompt] then {
     set gdb_prompt "\\(gdb\\)"
 }
 
+global gdb_prompt_full
+set gdb_prompt_full "$gdb_prompt "
+
 # A regexp that matches the pagination prompt.
 set pagination_prompt \
     "--Type <RET> for more, q to quit, c to continue without paging--"
@@ -1414,7 +1417,7 @@ proc gdb_test_no_output { args } {
 #   -1 if there was an internal error.
 
 proc gdb_test_sequence { command test_name expected_output_list } {
-    global gdb_prompt
+    global gdb_prompt_full
     if { $test_name == "" } {
 	set test_name $command
     }
@@ -1422,7 +1425,7 @@ proc gdb_test_sequence { command test_name expected_output_list } {
     if { $command != "" } {
 	send_gdb "$command\n"
     }
-    return [gdb_expect_list $test_name "$gdb_prompt $" $expected_output_list]
+    return [gdb_expect_list $test_name "$gdb_prompt_full$" $expected_output_list]
 }
 
 \f

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

[Simon Marchi]

On 2021-01-05 4:23 a.m., Tom de Vries wrote:
> On 1/5/21 10:01 AM, Tom de Vries wrote:
>> [ I first tried to override $gdb_prompt for the duration of
>> gdb_test_sequence using save_vars, but there's the invariant that the
>> gdb_prompt variable has an implicit " " after it, which
>> gdb_test_sequence adds, so that didn't work. ]
> 
> So, if we introduce a variable gdb_prompt_full which does contain the
> space, and use it in gdb_test_sequence, we can override it.
> 
> Thanks,
> - Tom
> 

Thanks for reporting.  The test passes here 90% of the time, but when I
run it in a loop it eventually fails like the others I fixed.

I'd rather add a -prompt flag to gdb_test_sequence, what do you think?
I'll start working on that and give it a try.

Simon

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

[Simon Marchi]

On 2021-01-05 10:33 a.m., Simon Marchi via Gdb-patches wrote:
> Thanks for reporting.  The test passes here 90% of the time, but when I
> run it in a loop it eventually fails like the others I fixed.
> 
> I'd rather add a -prompt flag to gdb_test_sequence, what do you think?
> I'll start working on that and give it a try.

Here's what I propose:

From fac85012df91bc9b70e2d1d8df12de1dab2ab44c Mon Sep 17 00:00:00 2001
From: Simon Marchi <simon.marchi@polymtl.ca>
Date: Tue, 5 Jan 2021 11:02:07 -0500
Subject: [PATCH] gdb/testsuite: fix race in
 gdb.threads/signal-while-stepping-over-bp-other-thread.exp

Commit 3ec3145c5dd6 ("gdb: introduce scoped debug prints") updated some
tests using "set debug infrun" to handle the fact that a debug print is
now shown after the prompt, after an inferior stop.  The same issue
happens in gdb.threads/signal-while-stepping-over-bp-other-thread.exp.
If I run it in a loop, it eventually fails like these other tests.

The problem is that the testsuite expects to see $gdb_prompt followed by
the end of the buffer.  It happens that expect reads $gdb_prompt and the
debug print at the same time, in which case the regexp never matches and
we get a timeout.

The fix is the same as was done in 3ec3145c5dd6, make the testsuite
believe that the prompt is the standard GDB prompt followed by that
debug print.

Since that test uses gdb_test_sequence, and the expected prompt is in
gdb_test_sequence, add a -prompt switch to gdb_test_sequence to override
the prompt used for that call.

gdb/testsuite/ChangeLog:

	* lib/gdb.exp (gdb_test_sequence): Accept -prompt switch.
	* gdb.threads/signal-while-stepping-over-bp-other-thread.exp:
	Pass prompt containing debug print to gdb_test_sequence.

Change-Id: I33161c53ddab45cdfeadfd50b964f8dc3caa9729
---
 ...al-while-stepping-over-bp-other-thread.exp |  2 +-
 gdb/testsuite/lib/gdb.exp                     | 23 +++++++++++++++++--
 2 files changed, 22 insertions(+), 3 deletions(-)

diff --git a/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp b/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
index fe8425319779..cc8b3200fbc2 100644
--- a/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
+++ b/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
@@ -102,7 +102,7 @@ gdb_test "set scheduler-locking off"
 gdb_test "set debug infrun 1"
 
 set test "step"
-gdb_test_sequence $test $test {
+gdb_test_sequence $test $test -prompt "$gdb_prompt \\\[infrun\\\] fetch_inferior_event: exit\r\n"  {
     "need to step-over"
     "resume_1: step=1,"
     "signal arrived while stepping over breakpoint"
diff --git a/gdb/testsuite/lib/gdb.exp b/gdb/testsuite/lib/gdb.exp
index 3f61da8adf12..f3880ecf56bb 100644
--- a/gdb/testsuite/lib/gdb.exp
+++ b/gdb/testsuite/lib/gdb.exp
@@ -1401,6 +1401,9 @@ proc gdb_test_no_output { args } {
 # EXPECTED_OUTPUT_LIST is a list of regexps of expected output, which are
 # processed in order, and all must be present in the output.
 #
+# The -prompt switch can be used to override the prompt expected at the end of
+# the output sequence.
+#
 # It is unnecessary to specify ".*" at the beginning or end of any regexp,
 # there is an implicit ".*" between each element of EXPECTED_OUTPUT_LIST.
 # There is also an implicit ".*" between the last regexp and the gdb prompt.
@@ -1413,16 +1416,32 @@ proc gdb_test_no_output { args } {
 #    0 if the test passes,
 #   -1 if there was an internal error.
 
-proc gdb_test_sequence { command test_name expected_output_list } {
+proc gdb_test_sequence { args } {
     global gdb_prompt
+
+    parse_args {{prompt ""}}
+
+    if { $prompt == "" } {
+	set prompt "$gdb_prompt "
+    }
+
+    if { [llength $args] != 3 } {
+	error "Unexpected # of arguments, expecting: COMMAND TEST_NAME EXPECTED_OUTPUT_LIST"
+    }
+
+    lassign $args command test_name expected_output_list
+
     if { $test_name == "" } {
 	set test_name $command
     }
+
     lappend expected_output_list ""; # implicit ".*" before gdb prompt
+
     if { $command != "" } {
 	send_gdb "$command\n"
     }
-    return [gdb_expect_list $test_name "$gdb_prompt $" $expected_output_list]
+
+    return [gdb_expect_list $test_name "${prompt}$" $expected_output_list]
 }
 
 \f
-- 
2.29.2

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

[tdevries]

On 2021-01-05 18:02, Simon Marchi wrote:
> On 2021-01-05 10:33 a.m., Simon Marchi via Gdb-patches wrote:
>> Thanks for reporting.  The test passes here 90% of the time, but when 
>> I
>> run it in a loop it eventually fails like the others I fixed.
>> 
>> I'd rather add a -prompt flag to gdb_test_sequence, what do you think?

Yeah, that's not a bad idea.

The only bit that concerns me is that there's already a -prompt switch 
for gdb_test_multiple, which does not add on the terminating '$', while 
this version does.

It's probably a good idea to have the -prompt switch to behave the same 
in both cases.

Thanks,
- Tom


>> I'll start working on that and give it a try.
> 
> Here's what I propose:
> 
> From fac85012df91bc9b70e2d1d8df12de1dab2ab44c Mon Sep 17 00:00:00 2001
> From: Simon Marchi <simon.marchi@polymtl.ca>
> Date: Tue, 5 Jan 2021 11:02:07 -0500
> Subject: [PATCH] gdb/testsuite: fix race in
>  gdb.threads/signal-while-stepping-over-bp-other-thread.exp
> 
> Commit 3ec3145c5dd6 ("gdb: introduce scoped debug prints") updated some
> tests using "set debug infrun" to handle the fact that a debug print is
> now shown after the prompt, after an inferior stop.  The same issue
> happens in gdb.threads/signal-while-stepping-over-bp-other-thread.exp.
> If I run it in a loop, it eventually fails like these other tests.
> 
> The problem is that the testsuite expects to see $gdb_prompt followed 
> by
> the end of the buffer.  It happens that expect reads $gdb_prompt and 
> the
> debug print at the same time, in which case the regexp never matches 
> and
> we get a timeout.
> 
> The fix is the same as was done in 3ec3145c5dd6, make the testsuite
> believe that the prompt is the standard GDB prompt followed by that
> debug print.
> 
> Since that test uses gdb_test_sequence, and the expected prompt is in
> gdb_test_sequence, add a -prompt switch to gdb_test_sequence to 
> override
> the prompt used for that call.
> 
> gdb/testsuite/ChangeLog:
> 
> 	* lib/gdb.exp (gdb_test_sequence): Accept -prompt switch.
> 	* gdb.threads/signal-while-stepping-over-bp-other-thread.exp:
> 	Pass prompt containing debug print to gdb_test_sequence.
> 
> Change-Id: I33161c53ddab45cdfeadfd50b964f8dc3caa9729
> ---
>  ...al-while-stepping-over-bp-other-thread.exp |  2 +-
>  gdb/testsuite/lib/gdb.exp                     | 23 +++++++++++++++++--
>  2 files changed, 22 insertions(+), 3 deletions(-)
> 
> diff --git
> a/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
> b/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
> index fe8425319779..cc8b3200fbc2 100644
> --- 
> a/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
> +++ 
> b/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
> @@ -102,7 +102,7 @@ gdb_test "set scheduler-locking off"
>  gdb_test "set debug infrun 1"
> 
>  set test "step"
> -gdb_test_sequence $test $test {
> +gdb_test_sequence $test $test -prompt "$gdb_prompt \\\[infrun\\\]
> fetch_inferior_event: exit\r\n"  {
>      "need to step-over"
>      "resume_1: step=1,"
>      "signal arrived while stepping over breakpoint"
> diff --git a/gdb/testsuite/lib/gdb.exp b/gdb/testsuite/lib/gdb.exp
> index 3f61da8adf12..f3880ecf56bb 100644
> --- a/gdb/testsuite/lib/gdb.exp
> +++ b/gdb/testsuite/lib/gdb.exp
> @@ -1401,6 +1401,9 @@ proc gdb_test_no_output { args } {
>  # EXPECTED_OUTPUT_LIST is a list of regexps of expected output, which 
> are
>  # processed in order, and all must be present in the output.
>  #
> +# The -prompt switch can be used to override the prompt expected at 
> the end of
> +# the output sequence.
> +#
>  # It is unnecessary to specify ".*" at the beginning or end of any 
> regexp,
>  # there is an implicit ".*" between each element of 
> EXPECTED_OUTPUT_LIST.
>  # There is also an implicit ".*" between the last regexp and the gdb 
> prompt.
> @@ -1413,16 +1416,32 @@ proc gdb_test_no_output { args } {
>  #    0 if the test passes,
>  #   -1 if there was an internal error.
> 
> -proc gdb_test_sequence { command test_name expected_output_list } {
> +proc gdb_test_sequence { args } {
>      global gdb_prompt
> +
> +    parse_args {{prompt ""}}
> +
> +    if { $prompt == "" } {
> +	set prompt "$gdb_prompt "
> +    }
> +
> +    if { [llength $args] != 3 } {
> +	error "Unexpected # of arguments, expecting: COMMAND TEST_NAME
> EXPECTED_OUTPUT_LIST"
> +    }
> +
> +    lassign $args command test_name expected_output_list
> +
>      if { $test_name == "" } {
>  	set test_name $command
>      }
> +
>      lappend expected_output_list ""; # implicit ".*" before gdb prompt
> +
>      if { $command != "" } {
>  	send_gdb "$command\n"
>      }
> -    return [gdb_expect_list $test_name "$gdb_prompt $" 
> $expected_output_list]
> +
> +    return [gdb_expect_list $test_name "${prompt}$" 
> $expected_output_list]
>  }
> 
>  \f

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

[Simon Marchi]

On 2021-01-05 4:26 p.m., tdevries wrote:
> Yeah, that's not a bad idea.
> 
> The only bit that concerns me is that there's already a -prompt switch for gdb_test_multiple, which does not add on the terminating '$', while this version does.
> 
> It's probably a good idea to have the -prompt switch to behave the same in both cases.

Hmm I see.  Intuitively, I'd try to make gdb_test_multiple add
the terminating $.  Do you foresee some problems with that?

The prompt passed to gdb_test_multiple only appears to be used
for the various failing cases, so I don't expect that to change
any passing test (I'll give it a try).

Simon

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

[Simon Marchi]

On 2021-01-05 4:54 p.m., Simon Marchi wrote:
> On 2021-01-05 4:26 p.m., tdevries wrote:
>> Yeah, that's not a bad idea.
>>
>> The only bit that concerns me is that there's already a -prompt switch for gdb_test_multiple, which does not add on the terminating '$', while this version does.
>>
>> It's probably a good idea to have the -prompt switch to behave the same in both cases.
> 
> Hmm I see.  Intuitively, I'd try to make gdb_test_multiple add
> the terminating $.  Do you foresee some problems with that?
> 
> The prompt passed to gdb_test_multiple only appears to be used
> for the various failing cases, so I don't expect that to change
> any passing test (I'll give it a try).

Well, now that I think of it a bit more, it would be much easier and safer
to just make my gdb_test_sequence's -prompt work like gdb_test_multiple's -prompt,
and have the caller add the $ itself.

Updated patch below.

From 23d207b6f391312f82fcaeae9936c97470461415 Mon Sep 17 00:00:00 2001
From: Simon Marchi <simon.marchi@polymtl.ca>
Date: Tue, 05 Jan 2021 11:02:07 -0500
Subject: [PATCH] gdb/testsuite: fix race in gdb.threads/signal-while-stepping-over-bp-other-thread.exp

Commit 3ec3145c5dd6 ("gdb: introduce scoped debug prints") updated some
tests using "set debug infrun" to handle the fact that a debug print is
now shown after the prompt, after an inferior stop.  The same issue
happens in gdb.threads/signal-while-stepping-over-bp-other-thread.exp.
If I run it in a loop, it eventually fails like these other tests.

The problem is that the testsuite expects to see $gdb_prompt followed by
the end of the buffer.  It happens that expect reads $gdb_prompt and the
debug print at the same time, in which case the regexp never matches and
we get a timeout.

The fix is the same as was done in 3ec3145c5dd6, make the testsuite
believe that the prompt is the standard GDB prompt followed by that
debug print.

Since that test uses gdb_test_sequence, and the expected prompt is in
gdb_test_sequence, add a -prompt switch to gdb_test_sequence to override
the prompt used for that call.

gdb/testsuite/ChangeLog:

	* lib/gdb.exp (gdb_test_sequence): Accept -prompt switch.
	* gdb.threads/signal-while-stepping-over-bp-other-thread.exp:
	Pass prompt containing debug print to gdb_test_sequence.

Change-Id: I33161c53ddab45cdfeadfd50b964f8dc3caa9729
---

diff --git a/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp b/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
index fe84253..2807485 100644
--- a/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
+++ b/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
@@ -102,7 +102,7 @@
 gdb_test "set debug infrun 1"
 
 set test "step"
-gdb_test_sequence $test $test {
+gdb_test_sequence $test $test -prompt "$gdb_prompt \\\[infrun\\\] fetch_inferior_event: exit\r\n$"  {
     "need to step-over"
     "resume_1: step=1,"
     "signal arrived while stepping over breakpoint"
diff --git a/gdb/testsuite/lib/gdb.exp b/gdb/testsuite/lib/gdb.exp
index 3f61da8..140e396 100644
--- a/gdb/testsuite/lib/gdb.exp
+++ b/gdb/testsuite/lib/gdb.exp
@@ -1401,6 +1401,9 @@
 # EXPECTED_OUTPUT_LIST is a list of regexps of expected output, which are
 # processed in order, and all must be present in the output.
 #
+# The -prompt switch can be used to override the prompt expected at the end of
+# the output sequence.
+#
 # It is unnecessary to specify ".*" at the beginning or end of any regexp,
 # there is an implicit ".*" between each element of EXPECTED_OUTPUT_LIST.
 # There is also an implicit ".*" between the last regexp and the gdb prompt.
@@ -1413,16 +1416,32 @@
 #    0 if the test passes,
 #   -1 if there was an internal error.
 
-proc gdb_test_sequence { command test_name expected_output_list } {
+proc gdb_test_sequence { args } {
     global gdb_prompt
+
+    parse_args {{prompt ""}}
+
+    if { $prompt == "" } {
+	set prompt "$gdb_prompt $"
+    }
+
+    if { [llength $args] != 3 } {
+	error "Unexpected # of arguments, expecting: COMMAND TEST_NAME EXPECTED_OUTPUT_LIST"
+    }
+
+    lassign $args command test_name expected_output_list
+
     if { $test_name == "" } {
 	set test_name $command
     }
+
     lappend expected_output_list ""; # implicit ".*" before gdb prompt
+
     if { $command != "" } {
 	send_gdb "$command\n"
     }
-    return [gdb_expect_list $test_name "$gdb_prompt $" $expected_output_list]
+
+    return [gdb_expect_list $test_name $prompt $expected_output_list]
 }
 
 \f

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

[Tom de Vries]

On 1/6/21 2:00 AM, Simon Marchi wrote:
> On 2021-01-05 4:54 p.m., Simon Marchi wrote:
>> On 2021-01-05 4:26 p.m., tdevries wrote:
>>> Yeah, that's not a bad idea.
>>>
>>> The only bit that concerns me is that there's already a -prompt switch for gdb_test_multiple, which does not add on the terminating '$', while this version does.
>>>
>>> It's probably a good idea to have the -prompt switch to behave the same in both cases.
>>
>> Hmm I see.  Intuitively, I'd try to make gdb_test_multiple add
>> the terminating $.  Do you foresee some problems with that?
>>
>> The prompt passed to gdb_test_multiple only appears to be used
>> for the various failing cases, so I don't expect that to change
>> any passing test (I'll give it a try).
> 
> Well, now that I think of it a bit more, it would be much easier and safer
> to just make my gdb_test_sequence's -prompt work like gdb_test_multiple's -prompt,
> and have the caller add the $ itself.
> 
> Updated patch below.

Thanks, LGTM.

- Tom

> 
> From 23d207b6f391312f82fcaeae9936c97470461415 Mon Sep 17 00:00:00 2001
> From: Simon Marchi <simon.marchi@polymtl.ca>
> Date: Tue, 05 Jan 2021 11:02:07 -0500
> Subject: [PATCH] gdb/testsuite: fix race in gdb.threads/signal-while-stepping-over-bp-other-thread.exp
> 
> Commit 3ec3145c5dd6 ("gdb: introduce scoped debug prints") updated some
> tests using "set debug infrun" to handle the fact that a debug print is
> now shown after the prompt, after an inferior stop.  The same issue
> happens in gdb.threads/signal-while-stepping-over-bp-other-thread.exp.
> If I run it in a loop, it eventually fails like these other tests.
> 
> The problem is that the testsuite expects to see $gdb_prompt followed by
> the end of the buffer.  It happens that expect reads $gdb_prompt and the
> debug print at the same time, in which case the regexp never matches and
> we get a timeout.
> 
> The fix is the same as was done in 3ec3145c5dd6, make the testsuite
> believe that the prompt is the standard GDB prompt followed by that
> debug print.
> 
> Since that test uses gdb_test_sequence, and the expected prompt is in
> gdb_test_sequence, add a -prompt switch to gdb_test_sequence to override
> the prompt used for that call.
> 
> gdb/testsuite/ChangeLog:
> 
> 	* lib/gdb.exp (gdb_test_sequence): Accept -prompt switch.
> 	* gdb.threads/signal-while-stepping-over-bp-other-thread.exp:
> 	Pass prompt containing debug print to gdb_test_sequence.
> 
> Change-Id: I33161c53ddab45cdfeadfd50b964f8dc3caa9729
> ---
> 
> diff --git a/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp b/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
> index fe84253..2807485 100644
> --- a/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
> +++ b/gdb/testsuite/gdb.threads/signal-while-stepping-over-bp-other-thread.exp
> @@ -102,7 +102,7 @@
>  gdb_test "set debug infrun 1"
>  
>  set test "step"
> -gdb_test_sequence $test $test {
> +gdb_test_sequence $test $test -prompt "$gdb_prompt \\\[infrun\\\] fetch_inferior_event: exit\r\n$"  {
>      "need to step-over"
>      "resume_1: step=1,"
>      "signal arrived while stepping over breakpoint"
> diff --git a/gdb/testsuite/lib/gdb.exp b/gdb/testsuite/lib/gdb.exp
> index 3f61da8..140e396 100644
> --- a/gdb/testsuite/lib/gdb.exp
> +++ b/gdb/testsuite/lib/gdb.exp
> @@ -1401,6 +1401,9 @@
>  # EXPECTED_OUTPUT_LIST is a list of regexps of expected output, which are
>  # processed in order, and all must be present in the output.
>  #
> +# The -prompt switch can be used to override the prompt expected at the end of
> +# the output sequence.
> +#
>  # It is unnecessary to specify ".*" at the beginning or end of any regexp,
>  # there is an implicit ".*" between each element of EXPECTED_OUTPUT_LIST.
>  # There is also an implicit ".*" between the last regexp and the gdb prompt.
> @@ -1413,16 +1416,32 @@
>  #    0 if the test passes,
>  #   -1 if there was an internal error.
>  
> -proc gdb_test_sequence { command test_name expected_output_list } {
> +proc gdb_test_sequence { args } {
>      global gdb_prompt
> +
> +    parse_args {{prompt ""}}
> +
> +    if { $prompt == "" } {
> +	set prompt "$gdb_prompt $"
> +    }
> +
> +    if { [llength $args] != 3 } {
> +	error "Unexpected # of arguments, expecting: COMMAND TEST_NAME EXPECTED_OUTPUT_LIST"
> +    }
> +
> +    lassign $args command test_name expected_output_list
> +
>      if { $test_name == "" } {
>  	set test_name $command
>      }
> +
>      lappend expected_output_list ""; # implicit ".*" before gdb prompt
> +
>      if { $command != "" } {
>  	send_gdb "$command\n"
>      }
> -    return [gdb_expect_list $test_name "$gdb_prompt $" $expected_output_list]
> +
> +    return [gdb_expect_list $test_name $prompt $expected_output_list]
>  }
>  
>  \f
> 
> 

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

[Simon Marchi]

On 2021-01-06 2:15 a.m., Tom de Vries wrote:
> Thanks, LGTM.

Thanks, I pushed it.

Simon