[RFC] output remote protocol timestamps with "set debug remote"

[RFC] output remote protocol timestamps with "set debug remote"

[Pedro Alves]

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

I've had a use for this more than once, but I never had it
in GDB proper --- always had to patch it first.  Sometimes, I'd
like to be able to easily ask a client to give us remote protocol
timestamps, to help diagnose timing issues on stubs we don't
have easy access to --- missing TCP_NODELAY, unwanted buffering,
really slow flash writing, etc., in such cases you'll easily
spot unusual > ms delays somewhere.

I'm making use of this:

 /* Debugging level.  0 is off, and non-zero values mean to print some debug
    information (higher values, more information).  */
 extern int remote_debug;

... to enable timestamps, you do "set debug remote 2".  level 1
still outputs the same as usual.

With acks:

 1226687336.526: Sending packet: $Xf7efde30,1:U#d8...
 1226687336.526: Ack

 1226687336.526: Packet received: OK

 1226687336.526: Sending packet: $X80484d5,1:�#57...
 1226687336.526: Ack

In no-ack mode (e.g., against current gdbserver):

 1226687726.796: Sending packet: $Xf7fdfe30,1:U#d9...
 1226687726.796: Packet received: OK

 1226687726.806: Sending packet: $X80484d5,1:�#57...
 1226687726.806: Packet received: OK

WDYT?

-- 
Pedro Alves

[-- Attachment #2: timings.diff --]
[-- Type: text/x-diff, Size: 2783 bytes --]

2008-11-14  Pedro Alves  <pedro@codesourcery.com>

	* remote.c (remote_vlog, remote_log): New.
	(putpkt_binary, getpkt_sane): Use remote_log.

---
 gdb/remote.c |   44 +++++++++++++++++++++++++++++++++++++-------
 1 file changed, 37 insertions(+), 7 deletions(-)

Index: src/gdb/remote.c
===================================================================
--- src.orig/gdb/remote.c	2008-08-14 23:39:56.000000000 +0100
+++ src/gdb/remote.c	2008-11-14 18:40:04.000000000 +0000
@@ -236,6 +236,37 @@ Controlling the remote inferior in async
 		    value);
 }
 
+/* See remote_log.  */
+
+static void
+remote_vlog (const char *what, va_list ap)
+{
+  if (remote_debug > 1)
+    {
+      struct timeval tv;
+
+      gettimeofday (&tv, NULL);
+      fprintf_unfiltered (gdb_stdlog, "\n%08ld.%03ld: ",
+			  tv.tv_sec, tv.tv_usec / 1000);
+    }
+
+  vfprintf_unfiltered (gdb_stdlog, what, ap);
+}
+
+/* Print WHAT to GDB_STDLOG.  If REMOTE_DEBUG is > 1 (e.g.,
+   with 'set debug remote 2'), also print the current timestamp.  */
+
+static void remote_log (const char *what, ...) ATTR_FORMAT (printf, 1, 2);
+
+static void
+remote_log (const char *what, ...)
+{
+  va_list ap;
+  va_start (ap, what);
+  remote_vlog (what, ap);
+  va_end (ap);
+}
+
 /* For "remote".  */
 
 static struct cmd_list_element *remote_cmdlist;
@@ -4817,7 +4848,7 @@ putpkt_binary (char *buf, int cnt)
       if (remote_debug)
 	{
 	  *p = '\0';
-	  fprintf_unfiltered (gdb_stdlog, "Sending packet: ");
+	  remote_log ("Sending packet: ");
 	  fputstrn_unfiltered (buf2, p - buf2, 0, gdb_stdlog);
 	  fprintf_unfiltered (gdb_stdlog, "...");
 	  gdb_flush (gdb_stdlog);
@@ -4855,21 +4886,20 @@ putpkt_binary (char *buf, int cnt)
 	    {
 	    case '+':
 	      if (remote_debug)
-		fprintf_unfiltered (gdb_stdlog, "Ack\n");
+		remote_log ("Ack\n");
 	      return 1;
 	    case '-':
 	      if (remote_debug)
-		fprintf_unfiltered (gdb_stdlog, "Nak\n");
+		remote_log ("Nak\n");
 	    case SERIAL_TIMEOUT:
 	      tcount++;
 	      if (tcount > 3)
 		return 0;
+	      remote_log ("Retransmit\n");
 	      break;		/* Retransmit buffer.  */
 	    case '$':
 	      {
-	        if (remote_debug)
-		  fprintf_unfiltered (gdb_stdlog,
-				      "Packet instead of Ack, ignoring it\n");
+		remote_log ("Packet instead of Ack, ignoring it\n");
 		/* It's probably an old response sent because an ACK
 		   was lost.  Gobble up the packet and ack it so it
 		   doesn't get retransmitted when we resend this
@@ -5168,7 +5198,7 @@ getpkt_sane (char **buf, long *sizeof_bu
 	{
 	  if (remote_debug)
 	    {
-	      fprintf_unfiltered (gdb_stdlog, "Packet received: ");
+	      remote_log ("Packet received: ");
 	      fputstrn_unfiltered (*buf, val, 0, gdb_stdlog);
 	      fprintf_unfiltered (gdb_stdlog, "\n");
 	    }

Re: [RFC] output remote protocol timestamps with "set debug remote"

[Joel Brobecker]

> ... to enable timestamps, you do "set debug remote 2".  level 1
> still outputs the same as usual.
[...]
> WDYT?

Sounds like a very useful feature to me. And since I was at it,
I had a quick look at the code, which looks fine. I'm in favor.

> 2008-11-14  Pedro Alves  <pedro@codesourcery.com>
> 
> 	* remote.c (remote_vlog, remote_log): New.
> 	(putpkt_binary, getpkt_sane): Use remote_log.

-- 
Joel

Re: [RFC] output remote protocol timestamps with "set debug remote"

[Michael Snyder]

Joel Brobecker wrote:
>> ... to enable timestamps, you do "set debug remote 2".  level 1
>> still outputs the same as usual.
> [...]
>> WDYT?
> 
> Sounds like a very useful feature to me. And since I was at it,
> I had a quick look at the code, which looks fine. I'm in favor.

Me too.  My only question is, now that we're distinguishing
more than just "!=0", should we define some "verbosity levels"?

Re: [RFC] output remote protocol timestamps with "set debug remote"

[Daniel Jacobowitz]

On Fri, Nov 14, 2008 at 06:50:28PM +0000, Pedro Alves wrote:
> I'm making use of this:
> 
>  /* Debugging level.  0 is off, and non-zero values mean to print some debug
>     information (higher values, more information).  */
>  extern int remote_debug;
> 
> ... to enable timestamps, you do "set debug remote 2".  level 1
> still outputs the same as usual.

It's such a good idea, that it's already there :-)  "set debug
timestamp".  However, I'd never tried it with remote; it clearly
does not work right for multiple printf calls in a single debugging
message.  I'd suggest fixing that, instead.


1227044669:904148 Sending packet: 1227044669:904155 $1227044669:904161
q1227044669:904166 S1227044669:904172 y1227044669:904177
m1227044669:904182 b1227044669:904188 o1227044669:904193
l1227044669:904198 :1227044669:904205 :1227044669:904211
#1227044669:904217 51227044669:904222 b1227044669:904228
...1227044669:904279 Ack

-- 
Daniel Jacobowitz
CodeSourcery

Re: [RFC] output remote protocol timestamps with "set debug remote"

[Pedro Alves]

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

On Tuesday 18 November 2008 21:45:35, Daniel Jacobowitz wrote:
> On Fri, Nov 14, 2008 at 06:50:28PM +0000, Pedro Alves wrote:
> > I'm making use of this:
> > 
> >  /* Debugging level.  0 is off, and non-zero values mean to print some debug
> >     information (higher values, more information).  */
> >  extern int remote_debug;
> > 
> > ... to enable timestamps, you do "set debug remote 2".  level 1
> > still outputs the same as usual.
> 
> It's such a good idea, that it's already there :-)  "set debug
> timestamp".  However, I'd never tried it with remote; it clearly
> does not work right for multiple printf calls in a single debugging
> message.  I'd suggest fixing that, instead.

Ah, sneaky!  I missed that going in.

> 1227044669:904148 Sending packet: 1227044669:904155 $1227044669:904161
> q1227044669:904166 S1227044669:904172 y1227044669:904177
> m1227044669:904182 b1227044669:904188 o1227044669:904193
> l1227044669:904198 :1227044669:904205 :1227044669:904211
> #1227044669:904217 51227044669:904222 b1227044669:904228
> ...1227044669:904279 Ack

That attached patch make two changes to address this.

1) Makes sure that timestamped output always ends with a newline, so we
   get this,

  un-timestamped, like before, unchanged:

    Sending packet: $m80484d1,1#67... Packet received: 51

  and timestamped:

    1227058218:708583 Sending packet: $m80484d1,1#67...
    1227058218:708675 Packet received: 51

  [ If other output other than gdb_stdlog is mixed, then you still
  don't have the nice alignment, but, that doesn't seem as bad. ]

2) Makes sure a single fprintf_unfiltered is used to dump a packet,
   so we get a single timestamp for a packet, unlike your output
   above, where there's one timestamp per octet (that's from
   fputstrn_unfiltered ending up on fprintf_unfiltered once
   per char).

Something like this?

(I'm running it through the testsuite against gdbserver with
"set debug remote 1"/"set debug timestamp" just in case).

-- 
Pedro Alves

[-- Attachment #2: remote_timestamps.diff --]
[-- Type: text/x-diff, Size: 5520 bytes --]

2008-11-19  Pedro Alves  <pedro@codesourcery.com>

	* remote.c (escape_buffer): New.
	(putpkt_binary, read_frame, getpkt_or_notif_sane_1): Use it.  Make
	sure debug output printing a packet buffer goes through a single
	fprintf_unfiltered call.
	* utils.c (vfprintf_unfiltered): If outputting timestamps, end
	output with a newline if it wasn't going to already.

---
 gdb/remote.c |   81 ++++++++++++++++++++++++++++++++++++++++++++++-------------
 gdb/utils.c  |   13 ++++++++-
 2 files changed, 75 insertions(+), 19 deletions(-)

Index: src/gdb/remote.c
===================================================================
--- src.orig/gdb/remote.c	2008-11-19 01:41:52.000000000 +0000
+++ src/gdb/remote.c	2008-11-19 01:42:26.000000000 +0000
@@ -5847,6 +5847,28 @@ remote_send (char **buf,
     error (_("Remote failure reply: %s"), *buf);
 }
 
+/* Return a pointer to an xmalloc'ed string representing an escaped
+   version of BUF, of len N.  E.g. \n is converted to \\n, \t to \\t,
+   etc.  The caller is responsible for releasing the returned
+   memory.  */
+
+static char *
+escape_buffer (const char *buf, int n)
+{
+  struct cleanup *old_chain;
+  struct ui_file *stb;
+  char *str;
+  long length;
+
+  stb = mem_fileopen ();
+  old_chain = make_cleanup_ui_file_delete (stb);
+
+  fputstrn_unfiltered (buf, n, 0, stb);
+  str = ui_file_xstrdup (stb, &length);
+  do_cleanups (old_chain);
+  return str;
+}
+
 /* Display a null-terminated packet on stdout, for debugging, using C
    string notation.  */
 
@@ -5919,11 +5941,15 @@ putpkt_binary (char *buf, int cnt)
 
       if (remote_debug)
 	{
+	  struct cleanup *old_chain;
+	  char *str;
+
 	  *p = '\0';
-	  fprintf_unfiltered (gdb_stdlog, "Sending packet: ");
-	  fputstrn_unfiltered (buf2, p - buf2, 0, gdb_stdlog);
-	  fprintf_unfiltered (gdb_stdlog, "...");
+	  str = escape_buffer (buf2, p - buf2);
+	  old_chain = make_cleanup (xfree, str);
+	  fprintf_unfiltered (gdb_stdlog, "Sending packet: %s...", str);
 	  gdb_flush (gdb_stdlog);
+	  do_cleanups (old_chain);
 	}
       if (serial_write (remote_desc, buf2, p - buf2))
 	perror_with_name (_("putpkt: write failed"));
@@ -5997,9 +6023,15 @@ putpkt_binary (char *buf, int cnt)
 		  {
 		    if (remote_debug)
 		      {
-			fprintf_unfiltered (gdb_stdlog, "  Notification received: ");
-			fputstrn_unfiltered (rs->buf, val, 0, gdb_stdlog);
-			fprintf_unfiltered (gdb_stdlog, "\n");
+			struct cleanup *old_chain;
+			char *str;
+
+			str = escape_buffer (rs->buf, val);
+			old_chain = make_cleanup (xfree, str);
+			fprintf_unfiltered (gdb_stdlog,
+					    "  Notification received: %s\n",
+					    str);
+			do_cleanups (old_chain);
 		      }
 		    handle_notification (rs->buf, val);
 		    /* We're in sync now, rewait for the ack.  */
@@ -6163,11 +6195,16 @@ read_frame (char **buf_p,
 
 	    if (remote_debug)
 	      {
-		fprintf_filtered (gdb_stdlog,
-			      "Bad checksum, sentsum=0x%x, csum=0x%x, buf=",
-				  pktcsum, csum);
-		fputstrn_filtered (buf, bc, 0, gdb_stdlog);
-		fputs_filtered ("\n", gdb_stdlog);
+		struct cleanup *old_chain;
+		char *str;
+
+		str = escape_buffer (buf, bc);
+		old_chain = make_cleanup (xfree, str);
+		fprintf_unfiltered (gdb_stdlog,
+				    "\
+Bad checksum, sentsum=0x%x, csum=0x%x, buf=%s\n",
+				    pktcsum, csum, str);
+		do_cleanups (old_chain);
 	      }
 	    /* Number of characters in buffer ignoring trailing
                NULL.  */
@@ -6340,9 +6377,13 @@ getpkt_or_notif_sane_1 (char **buf, long
 	{
 	  if (remote_debug)
 	    {
-	      fprintf_unfiltered (gdb_stdlog, "Packet received: ");
-	      fputstrn_unfiltered (*buf, val, 0, gdb_stdlog);
-	      fprintf_unfiltered (gdb_stdlog, "\n");
+	     struct cleanup *old_chain;
+	     char *str;
+
+	     str = escape_buffer (*buf, val);
+	     old_chain = make_cleanup (xfree, str);
+	     fprintf_unfiltered (gdb_stdlog, "Packet received: %s\n", str);
+	     do_cleanups (old_chain);
 	    }
 
 	  /* Skip the ack char if we're in no-ack mode.  */
@@ -6359,9 +6400,15 @@ getpkt_or_notif_sane_1 (char **buf, long
 
 	  if (remote_debug)
 	    {
-	      fprintf_unfiltered (gdb_stdlog, "  Notification received: ");
-	      fputstrn_unfiltered (*buf, val, 0, gdb_stdlog);
-	      fprintf_unfiltered (gdb_stdlog, "\n");
+	      struct cleanup *old_chain;
+	      char *str;
+
+	      str = escape_buffer (*buf, val);
+	      old_chain = make_cleanup (xfree, str);
+	      fprintf_unfiltered (gdb_stdlog,
+				  "  Notification received: %s\n",
+				  str);
+	      do_cleanups (old_chain);
 	    }
 
 	  handle_notification (*buf, val);
Index: src/gdb/utils.c
===================================================================
--- src.orig/gdb/utils.c	2008-11-19 01:41:52.000000000 +0000
+++ src/gdb/utils.c	2008-11-19 01:42:26.000000000 +0000
@@ -2286,13 +2286,22 @@ vfprintf_unfiltered (struct ui_file *str
     {
       struct timeval tm;
       char *timestamp;
+      int len, need_nl;
 
       gettimeofday (&tm, NULL);
-      timestamp = xstrprintf ("%ld:%ld ", (long) tm.tv_sec, (long) tm.tv_usec);
+
+      len = strlen (linebuffer);
+      need_nl = (len > 0 && linebuffer[len - 1] != '\n');
+
+      timestamp = xstrprintf ("%ld:%ld %s%s",
+			      (long) tm.tv_sec, (long) tm.tv_usec,
+			      linebuffer,
+			      need_nl ? "\n": "");
       make_cleanup (xfree, timestamp);
       fputs_unfiltered (timestamp, stream);
     }
-  fputs_unfiltered (linebuffer, stream);
+  else
+    fputs_unfiltered (linebuffer, stream);
   do_cleanups (old_cleanups);
 }
 

Re: [RFC] output remote protocol timestamps with "set debug remote"

[Daniel Jacobowitz]

On Wed, Nov 19, 2008 at 01:46:42AM +0000, Pedro Alves wrote:
> Something like this?

Looks good to me!

-- 
Daniel Jacobowitz
CodeSourcery

Re: [RFC] output remote protocol timestamps with "set debug remote"

[Pedro Alves]

Thanks guys, I've checked it in.

-- 
Pedro Alves