From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (qmail 4513 invoked by alias); 14 Nov 2008 18:50:54 -0000 Received: (qmail 4442 invoked by uid 22791); 14 Nov 2008 18:50:52 -0000 X-Spam-Check-By: sourceware.org Received: from mail.codesourcery.com (HELO mail.codesourcery.com) (65.74.133.4) by sourceware.org (qpsmtpd/0.31) with ESMTP; Fri, 14 Nov 2008 18:50:16 +0000 Received: (qmail 31491 invoked from network); 14 Nov 2008 18:50:14 -0000 Received: from unknown (HELO orlando.local) (pedro@127.0.0.2) by mail.codesourcery.com with ESMTPA; 14 Nov 2008 18:50:14 -0000 From: Pedro Alves To: gdb-patches@sourceware.org Subject: [RFC] output remote protocol timestamps with "set debug remote" Date: Fri, 14 Nov 2008 23:21:00 -0000 User-Agent: KMail/1.9.10 MIME-Version: 1.0 Content-Type: Multipart/Mixed; boundary="Boundary-00=_0hcHJYQr8gLIptR" Message-Id: <200811141850.28537.pedro@codesourcery.com> X-IsSubscribed: yes Mailing-List: contact gdb-patches-help@sourceware.org; run by ezmlm Precedence: bulk List-Id: List-Subscribe: List-Archive: List-Post: List-Help: , Sender: gdb-patches-owner@sourceware.org X-SW-Source: 2008-11/txt/msg00367.txt.bz2 --Boundary-00=_0hcHJYQr8gLIptR Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: quoted-printable Content-Disposition: inline Content-length: 1171 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:=EF=BF=BD#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:=EF=BF=BD#57... 1226687726.806: Packet received: OK WDYT? --=20 Pedro Alves --Boundary-00=_0hcHJYQr8gLIptR Content-Type: text/x-diff; charset="iso 8859-15"; name="timings.diff" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="timings.diff" Content-length: 2783 2008-11-14 Pedro Alves * 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"); } --Boundary-00=_0hcHJYQr8gLIptR--