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

[Pedro Alves <pedro@codesourcery.com>]

[-- 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");
 	    }