# HG changeset patch
# User Jun Wu <quark@fb.com>
# Date 1506203920 25200
# Node ID b94db1780365824f5f97a930edada92f779da939
# Parent  9bd003052d55128a5a444eba972d10d78c9babbb
chg: show timestamp with debug messages

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

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

diff -r 9bd003052d55 -r b94db1780365 contrib/chg/util.c
--- a/contrib/chg/util.c	Mon Sep 25 11:05:16 2017 +0200
+++ b/contrib/chg/util.c	Sat Sep 23 14:58:40 2017 -0700
@@ -14,6 +14,7 @@
 #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 @@
 }
 
 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 @@
 void enabledebugmsg(void)
 {
 	debugmsgenabled = 1;
+	debugstart = now();
 }
 
 void debugmsg(const char *fmt, ...)
@@ -78,7 +87,7 @@
 	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);
diff -r 9bd003052d55 -r b94db1780365 tests/test-chg.t
--- a/tests/test-chg.t	Mon Sep 25 11:05:16 2017 +0200
+++ b/tests/test-chg.t	Sat Sep 23 14:58:40 2017 -0700
@@ -48,7 +48,7 @@
   $ 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 @@
 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 @@
 (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: