chg: show timestamp with debug messages

Like `strace -tr`, this helps finding performance bottlenecks.

Differential Revision: https://phab.mercurial-scm.org/D807

contrib/chg/util.c

@@ -14,6 +14,7 b''
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
+#include <sys/time.h>
 #include <sys/types.h>
 #include <sys/wait.h>
 #include <unistd.h>
@@ -59,6 +60,13 b' void abortmsgerrno(const char *fmt, ...)'
 }
 
 static int debugmsgenabled = 0;
+static double debugstart = 0;
+
+static double now() {
+	struct timeval t;
+	gettimeofday(&t, NULL);
+	return t.tv_usec / 1e6 + t.tv_sec;
+}
 
 void enablecolor(void)
 {
@@ -68,6 +76,7 b' void enablecolor(void)'
 void enabledebugmsg(void)
 {
 	debugmsgenabled = 1;
+	debugstart = now();
 }
 
 void debugmsg(const char *fmt, ...)
@@ -78,7 +87,7 b' void debugmsg(const char *fmt, ...)'
 	va_list args;
 	va_start(args, fmt);
 	fsetcolor(stderr, "1;30");
-	fputs("chg: debug: ", stderr);
+	fprintf(stderr, "chg: debug: %4.6f ", now() - debugstart);
 	vfprintf(stderr, fmt, args);
 	fsetcolor(stderr, "");
 	fputc('\n', stderr);

tests/test-chg.t

@@ -48,7 +48,7 b' by default, system() should be redirecte'
   $ touch foo
   $ CHGDEBUG= HGEDITOR=cat chg ci -Am channeled --edit 2>&1 \
   > | egrep "HG:|run 'cat"
-  chg: debug: run 'cat "*"' at '$TESTTMP/editor' (glob)
+  chg: debug: * run 'cat "*"' at '$TESTTMP/editor' (glob)
   HG: Enter commit message.  Lines beginning with 'HG:' are removed.
   HG: Leave message empty to abort commit.
   HG: --
@@ -165,16 +165,16 b' isolate socket directory for stable resu'
 warm up server:
 
   $ CHGDEBUG= chg log 2>&1 | egrep 'instruction|start'
-  chg: debug: start cmdserver at $TESTTMP/extreload/chgsock/server.* (glob)
+  chg: debug: * start cmdserver at $TESTTMP/extreload/chgsock/server.* (glob)
 
 new server should be started if extension modified:
 
   $ sleep 1
   $ touch dummyext.py
   $ CHGDEBUG= chg log 2>&1 | egrep 'instruction|start'
-  chg: debug: instruction: unlink $TESTTMP/extreload/chgsock/server-* (glob)
-  chg: debug: instruction: reconnect
-  chg: debug: start cmdserver at $TESTTMP/extreload/chgsock/server.* (glob)
+  chg: debug: * instruction: unlink $TESTTMP/extreload/chgsock/server-* (glob)
+  chg: debug: * instruction: reconnect (glob)
+  chg: debug: * start cmdserver at $TESTTMP/extreload/chgsock/server.* (glob)
 
 old server will shut down, while new server should still be reachable:
 
@@ -196,7 +196,7 b' since no server is reachable from socket'
 (this test makes sure that old server shut down automatically)
 
   $ CHGDEBUG= chg log 2>&1 | egrep 'instruction|start'
-  chg: debug: start cmdserver at $TESTTMP/extreload/chgsock/server.* (glob)
+  chg: debug: * start cmdserver at $TESTTMP/extreload/chgsock/server.* (glob)
 
 shut down servers and restore environment: