gdb: make "set debug timestamp" work nice with new debug printouts

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

diff --git a/gdb/ChangeLog b/gdb/ChangeLog
index f113bff3c8693d96a03efc0b92c5c551c62869c7..e0da11f5e96976bb142c8d6adf1aa6e1b3a2620a 100644 (file)
--- a/gdb/ChangeLog
+++ b/gdb/ChangeLog
@@ -1,3 +1,8 @@
+2021-01-04  Simon Marchi  <simon.marchi@efficios.com>
+
+       * utils.c (vfprintf_unfiltered): Print timestamp only when
+       previous debug output ended with a newline.
+
 2021-01-04  Luis Machado  <luis.machado@linaro.org>
 
        Update all users of trad_frame_saved_reg to use the new member

diff --git a/gdb/utils.c b/gdb/utils.c
index f22beea94cc2a543ba36b1865b33c905fc7df2fe..414e7b153a027e70f9eeb1ea9787161bcb60fbe3 100644 (file)
--- 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);