diff --git a/tests/test-blackbox.t b/tests/test-blackbox.t
--- a/tests/test-blackbox.t
+++ b/tests/test-blackbox.t
@@ -13,9 +13,9 @@ command, exit codes, and duration
   $ echo a > a
   $ hg add a
   $ hg blackbox
-  1970/01/01 00:00:00 bob (*)> add a (glob)
-  1970/01/01 00:00:00 bob (*)> add a exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox (glob)
+  1970/01/01 00:00:00 bob (5000)> add a
+  1970/01/01 00:00:00 bob (5000)> add a exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox
 
 incoming change tracking
 
@@ -45,12 +45,12 @@ clone, commit, pull
   added 1 changesets with 1 changes to 1 files
   (run 'hg update' to get a working copy)
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob (*)> pull (glob)
-  1970/01/01 00:00:00 bob (*)> updated served branch cache in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> wrote served branch cache with 1 labels and 2 nodes (glob)
-  1970/01/01 00:00:00 bob (*)> 1 incoming changes - new heads: d02f48003e62 (glob)
-  1970/01/01 00:00:00 bob (*)> pull exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  1970/01/01 00:00:00 bob (5000)> pull
+  1970/01/01 00:00:00 bob (5000)> updated served branch cache in * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> wrote served branch cache with 1 labels and 2 nodes
+  1970/01/01 00:00:00 bob (5000)> 1 incoming changes - new heads: d02f48003e62
+  1970/01/01 00:00:00 bob (5000)> pull exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox -l 6
 
 we must not cause a failure if we cannot write to the log
 
@@ -107,12 +107,12 @@ backup bundles get logged
   0 files updated, 0 files merged, 1 files removed, 0 files unresolved
   saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/*-backup.hg (glob)
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob (*)> strip tip (glob)
-  1970/01/01 00:00:00 bob (*)> saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/73f6ee326b27-7612e004-backup.hg (glob)
-  1970/01/01 00:00:00 bob (*)> updated base branch cache in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> wrote base branch cache with 1 labels and 2 nodes (glob)
-  1970/01/01 00:00:00 bob (*)> strip tip exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  1970/01/01 00:00:00 bob (5000)> strip tip
+  1970/01/01 00:00:00 bob (5000)> saved backup bundle to $TESTTMP/blackboxtest2/.hg/strip-backup/73f6ee326b27-7612e004-backup.hg (glob)
+  1970/01/01 00:00:00 bob (5000)> updated base branch cache in * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> wrote base branch cache with 1 labels and 2 nodes
+  1970/01/01 00:00:00 bob (5000)> strip tip exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox -l 6
 
 extension and python hooks - use the eol extension for a pythonhook
 
@@ -125,12 +125,12 @@ extension and python hooks - use the eol
   1 files updated, 0 files merged, 0 files removed, 0 files unresolved
   1 other heads for branch "default"
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob (*)> update (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 0 tags (glob)
-  1970/01/01 00:00:00 bob (*)> pythonhook-preupdate: hgext.eol.preupdate finished in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> exthook-update: echo hooked finished in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> update exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  1970/01/01 00:00:00 bob (5000)> update
+  1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 0 tags
+  1970/01/01 00:00:00 bob (5000)> pythonhook-preupdate: hgext.eol.preupdate finished in * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> exthook-update: echo hooked finished in * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> update exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox -l 6
 
 log rotation
 
@@ -151,7 +151,7 @@ log rotation
   $ hg init blackboxtest3
   $ cd blackboxtest3
   $ hg blackbox
-  1970/01/01 00:00:00 bob (*)> blackbox (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox
   $ mv .hg/blackbox.log .hg/blackbox.log-
   $ mkdir .hg/blackbox.log
   $ sed -e 's/\(.*test1.*\)/#\1/; s#\(.*commit2.*\)#os.rmdir(".hg/blackbox.log")\nos.rename(".hg/blackbox.log-", ".hg/blackbox.log")\n\1#' $TESTDIR/test-dispatch.py > ../test-dispatch.py
@@ -178,9 +178,9 @@ log rotation
   
   result: None
   $ hg blackbox
-  1970/01/01 00:00:00 bob (*)> blackbox (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox
+  1970/01/01 00:00:00 bob (5000)> blackbox exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox
 
 cleanup
   $ cd ..
diff --git a/tests/test-obsolete-tag-cache.t b/tests/test-obsolete-tag-cache.t
--- a/tests/test-obsolete-tag-cache.t
+++ b/tests/test-obsolete-tag-cache.t
@@ -68,11 +68,11 @@ Hiding a non-tip changeset should change
   55482a6fb4b1881fa8f746fd52cf6f096bb21c89 test1
 
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> tags (glob)
-  1970/01/01 00:00:00 bob (*)> 2/2 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 2 tags (glob)
-  1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
+  1970/01/01 00:00:00 bob (5000)> tags
+  1970/01/01 00:00:00 bob (5000)> 2/2 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 2 tags
+  1970/01/01 00:00:00 bob (5000)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox -l 5
 
 Hiding another changeset should cause the filtered hash to change
 
@@ -88,11 +88,11 @@ Hiding another changeset should cause th
   042eb6bfcc4909bad84a1cbf6eb1ddf0ab587d41 head2
 
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> tags (glob)
-  1970/01/01 00:00:00 bob (*)> 1/1 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
+  1970/01/01 00:00:00 bob (5000)> tags
+  1970/01/01 00:00:00 bob (5000)> 1/1 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00 bob (5000)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox -l 5
 
 Resolving tags on an unfiltered repo writes a separate tags cache
 
@@ -109,8 +109,8 @@ Resolving tags on an unfiltered repo wri
   d75775ffbc6bca1794d300f5571272879bd280da test2
 
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> --hidden tags (glob)
-  1970/01/01 00:00:00 bob (*)> 2/2 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2 with 3 tags (glob)
-  1970/01/01 00:00:00 bob (*)> --hidden tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
+  1970/01/01 00:00:00 bob (5000)> --hidden tags
+  1970/01/01 00:00:00 bob (5000)> 2/2 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2 with 3 tags
+  1970/01/01 00:00:00 bob (5000)> --hidden tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox -l 5
diff --git a/tests/test-tags.t b/tests/test-tags.t
--- a/tests/test-tags.t
+++ b/tests/test-tags.t
@@ -137,12 +137,12 @@ Tag cache debug info written to blackbox
   $ hg identify
   b9154636be93 tip
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob (*)> identify (glob)
-  1970/01/01 00:00:00 bob (*)> writing 48 bytes to cache/hgtagsfnodes1 (glob)
-  1970/01/01 00:00:00 bob (*)> 0/1 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> identify exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  1970/01/01 00:00:00 bob (5000)> identify
+  1970/01/01 00:00:00 bob (5000)> writing 48 bytes to cache/hgtagsfnodes1
+  1970/01/01 00:00:00 bob (5000)> 0/1 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00 bob (5000)> identify exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox -l 6
 
 Failure to acquire lock results in no write
 
@@ -151,12 +151,12 @@ Failure to acquire lock results in no wr
   $ hg identify
   b9154636be93 tip
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob (*)> identify (glob)
-  1970/01/01 00:00:00 bob (*)> not writing .hg/cache/hgtagsfnodes1 because lock cannot be acquired (glob)
-  1970/01/01 00:00:00 bob (*)> 0/1 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> identify exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  1970/01/01 00:00:00 bob (5000)> identify
+  1970/01/01 00:00:00 bob (5000)> not writing .hg/cache/hgtagsfnodes1 because lock cannot be acquired
+  1970/01/01 00:00:00 bob (5000)> 0/1 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00 bob (5000)> identify exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox -l 6
 
   $ fnodescacheexists
   no fnodes cache
@@ -351,12 +351,12 @@ Extra junk data at the end should get ov
   bar                                1:78391a272241
 
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob (*)> tags (glob)
-  1970/01/01 00:00:00 bob (*)> writing 24 bytes to cache/hgtagsfnodes1 (glob)
-  1970/01/01 00:00:00 bob (*)> 2/3 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  1970/01/01 00:00:00 bob (5000)> tags
+  1970/01/01 00:00:00 bob (5000)> writing 24 bytes to cache/hgtagsfnodes1
+  1970/01/01 00:00:00 bob (5000)> 2/3 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00 bob (5000)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox -l 6
 
 #if unix-permissions no-root
 Errors writing to .hgtags fnodes cache are silently ignored
@@ -372,12 +372,12 @@ Errors writing to .hgtags fnodes cache a
   bar                                1:78391a272241
 
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob (*)> tags (glob)
-  1970/01/01 00:00:00 bob (*)> couldn't write cache/hgtagsfnodes1: [Errno 13] Permission denied: '$TESTTMP/t2/.hg/cache/hgtagsfnodes1' (glob)
-  1970/01/01 00:00:00 bob (*)> 2/3 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  1970/01/01 00:00:00 bob (5000)> tags
+  1970/01/01 00:00:00 bob (5000)> couldn't write cache/hgtagsfnodes1: [Errno 13] Permission denied: '$TESTTMP/t2/.hg/cache/hgtagsfnodes1' (glob)
+  1970/01/01 00:00:00 bob (5000)> 2/3 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00 bob (5000)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox -l 6
 
   $ chmod a+w .hg/cache/hgtagsfnodes1
 
@@ -387,12 +387,12 @@ Errors writing to .hgtags fnodes cache a
   bar                                1:78391a272241
 
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob (*)> tags (glob)
-  1970/01/01 00:00:00 bob (*)> writing 24 bytes to cache/hgtagsfnodes1 (glob)
-  1970/01/01 00:00:00 bob (*)> 2/3 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  1970/01/01 00:00:00 bob (5000)> tags
+  1970/01/01 00:00:00 bob (5000)> writing 24 bytes to cache/hgtagsfnodes1
+  1970/01/01 00:00:00 bob (5000)> 2/3 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00 bob (5000)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox -l 6
 
   $ f --size .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=168
@@ -416,11 +416,11 @@ Stripping doesn't truncate the tags cach
   bar                                1:78391a272241
 
   $ hg blackbox -l 5
-  1970/01/01 00:00:00 bob (*)> writing 24 bytes to cache/hgtagsfnodes1 (glob)
-  1970/01/01 00:00:00 bob (*)> 2/3 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 5 (glob)
+  1970/01/01 00:00:00 bob (5000)> writing 24 bytes to cache/hgtagsfnodes1
+  1970/01/01 00:00:00 bob (5000)> 2/3 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00 bob (5000)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox -l 5
 
   $ f --size .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=120
@@ -433,12 +433,12 @@ Stripping doesn't truncate the tags cach
   bar                                1:78391a272241
 
   $ hg blackbox -l 6
-  1970/01/01 00:00:00 bob (*)> tags (glob)
-  1970/01/01 00:00:00 bob (*)> writing 24 bytes to cache/hgtagsfnodes1 (glob)
-  1970/01/01 00:00:00 bob (*)> 2/3 cache hits/lookups in * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> writing .hg/cache/tags2-visible with 1 tags (glob)
-  1970/01/01 00:00:00 bob (*)> tags exited 0 after * seconds (glob)
-  1970/01/01 00:00:00 bob (*)> blackbox -l 6 (glob)
+  1970/01/01 00:00:00 bob (5000)> tags
+  1970/01/01 00:00:00 bob (5000)> writing 24 bytes to cache/hgtagsfnodes1
+  1970/01/01 00:00:00 bob (5000)> 2/3 cache hits/lookups in * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> writing .hg/cache/tags2-visible with 1 tags
+  1970/01/01 00:00:00 bob (5000)> tags exited 0 after * seconds (glob)
+  1970/01/01 00:00:00 bob (5000)> blackbox -l 6
   $ f --size .hg/cache/hgtagsfnodes1
   .hg/cache/hgtagsfnodes1: size=144