# HG changeset patch
# User Pierre-Yves David <pierre-yves.david@octobus.net>
# Date 1494946597 -7200
# Node ID 694494619795a81d9df548d8af221586a1b98823
# Parent  3593442d4a0ed1778ebf6b8431dc807b9c729de7
cache: track time spend updating various cache

This produce more useful blackbox log.

diff -r 3593442d4a0e -r 694494619795 hgext3rd/evolve/obscache.py
--- a/hgext3rd/evolve/obscache.py	Tue May 16 15:20:53 2017 +0200
+++ b/hgext3rd/evolve/obscache.py	Tue May 16 16:56:37 2017 +0200
@@ -208,7 +208,11 @@
         if reset or self._cachekey is None:
             self.clear(reset=True)
 
+        starttime = util.timer()
         self._updatefrom(repo, revs, obsmarkers)
+        duration = util.timer() - starttime
+        repo.ui.log('evoext-cache', 'updated %s in %.4f seconds (%sr, %so)\n',
+                    self._cachename, duration, len(revs), len(obsmarkers))
 
         # update the key from the new data
         key = list(self._cachekey)
diff -r 3593442d4a0e -r 694494619795 tests/test-discovery-obshashrange.t
--- a/tests/test-discovery-obshashrange.t	Tue May 16 15:20:53 2017 +0200
+++ b/tests/test-discovery-obshashrange.t	Tue May 16 16:56:37 2017 +0200
@@ -50,6 +50,8 @@
   * @0000000000000000000000000000000000000000 (*)> wrote served branch cache with 1 labels and 1 nodes (glob)
   * @0000000000000000000000000000000000000000 (*)> updated served branch cache in *.???? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> wrote served branch cache with 1 labels and 1 nodes (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 0o) (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obscache in *.???? seconds (8r, 0o) (glob)
   * @0000000000000000000000000000000000000000 (*)> debugbuilddag .+7 exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> blackbox (glob)
   $ rm .hg/blackbox.log
@@ -92,6 +94,8 @@
   * @0000000000000000000000000000000000000000 (*)> log --hidden --template '{node}\n' --rev 'desc(r1)' exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> debugobsolete aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa 66f7d451a68b85ed82ff5fcc254daf50c74144bd (glob)
   * @0000000000000000000000000000000000000000 (*)> alias 'debugobsolete' expands to 'debugobsolete -d '0 0'' (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 1o) (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obscache in *.???? seconds (0r, 1o) (glob)
   * @0000000000000000000000000000000000000000 (*)> debugobsolete aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa 66f7d451a68b85ed82ff5fcc254daf50c74144bd exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> log --hidden --template '{node}\n' --rev 'desc(r2)' (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
@@ -99,11 +103,15 @@
   * @0000000000000000000000000000000000000000 (*)> debugobsolete bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb 01241442b3c2bf3211e593b549c655ea65b295e3 (glob)
   * @0000000000000000000000000000000000000000 (*)> alias 'debugobsolete' expands to 'debugobsolete -d '0 0'' (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 2o) (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obscache in *.???? seconds (8r, 2o) (glob)
   * @0000000000000000000000000000000000000000 (*)> debugobsolete bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb 01241442b3c2bf3211e593b549c655ea65b295e3 exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> log --hidden --template '{node}\n' --rev 'desc(r4)' (glob)
   * @0000000000000000000000000000000000000000 (*)> log --hidden --template '{node}\n' --rev 'desc(r4)' exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> debugobsolete cccccccccccccccccccccccccccccccccccccccc bebd167eb94d257ace0e814aeb98e6972ed2970d (glob)
   * @0000000000000000000000000000000000000000 (*)> alias 'debugobsolete' expands to 'debugobsolete -d '0 0'' (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 3o) (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obscache in *.???? seconds (0r, 1o) (glob)
   * @0000000000000000000000000000000000000000 (*)> debugobsolete cccccccccccccccccccccccccccccccccccccccc bebd167eb94d257ace0e814aeb98e6972ed2970d exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> log --hidden --template '{node}\n' --rev 'desc(r5)' (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
@@ -111,11 +119,15 @@
   * @0000000000000000000000000000000000000000 (*)> debugobsolete dddddddddddddddddddddddddddddddddddddddd c8d03c1b5e94af74b772900c58259d2e08917735 (glob)
   * @0000000000000000000000000000000000000000 (*)> alias 'debugobsolete' expands to 'debugobsolete -d '0 0'' (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 4o) (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obscache in *.???? seconds (8r, 4o) (glob)
   * @0000000000000000000000000000000000000000 (*)> debugobsolete dddddddddddddddddddddddddddddddddddddddd c8d03c1b5e94af74b772900c58259d2e08917735 exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> log --hidden --template '{node}\n' --rev 'desc(r7)' (glob)
   * @0000000000000000000000000000000000000000 (*)> log --hidden --template '{node}\n' --rev 'desc(r7)' exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> debugobsolete eeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeee 4de32a90b66cd083ebf3c00b41277aa7abca51dd (glob)
   * @0000000000000000000000000000000000000000 (*)> alias 'debugobsolete' expands to 'debugobsolete -d '0 0'' (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 5o) (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obscache in *.???? seconds (0r, 1o) (glob)
   * @0000000000000000000000000000000000000000 (*)> debugobsolete eeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeeee 4de32a90b66cd083ebf3c00b41277aa7abca51dd exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> debugobsolete (glob)
   * @0000000000000000000000000000000000000000 (*)> alias 'debugobsolete' expands to 'debugobsolete -d '0 0'' (glob)
@@ -157,6 +169,7 @@
   * @0000000000000000000000000000000000000000 (*)> debugobshashrange --subranges --rev tip (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 5o) (glob)
   * @0000000000000000000000000000000000000000 (*)> debugobshashrange --subranges --rev tip exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> serve --stdio (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
@@ -172,6 +185,8 @@
   * @0000000000000000000000000000000000000000 (*)> pull --rev 4 (glob)
   * @0000000000000000000000000000000000000000 (*)> updated served branch cache in *.???? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> wrote served branch cache with 1 labels and 1 nodes (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obshashrange in *.???? seconds (5r, 3o) (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obscache in *.???? seconds (5r, 3o) (glob)
   * @0000000000000000000000000000000000000000 (*)> 5 incoming changes - new heads: bebd167eb94d (glob)
   * @0000000000000000000000000000000000000000 (*)> pull --rev 4 exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> blackbox (glob)
@@ -204,11 +219,15 @@
   $ hg -R ../server blackbox
   * @0000000000000000000000000000000000000000 (*)> serve --stdio (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 5o) (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obscache in *.???? seconds (9r, 5o) (glob)
   * @0000000000000000000000000000000000000000 (*)> updated served branch cache in *.???? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> wrote served branch cache with 1 labels and 2 nodes (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obshashrange in *.???? seconds (9r, 6o) (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obscache in *.???? seconds (0r, 1o) (glob)
   * @0000000000000000000000000000000000000000 (*)> 1 incoming changes - new heads: 45f8b879de92 (glob)
   * @0000000000000000000000000000000000000000 (*)> -R server serve --stdio exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> blackbox (glob)
@@ -244,9 +263,12 @@
   $ hg -R ../server blackbox
   * @0000000000000000000000000000000000000000 (*)> serve --stdio (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obshashrange in *.???? seconds (9r, 6o) (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obshashrange in *.???? seconds (9r, 8o) (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obscache in *.???? seconds (9r, 8o) (glob)
   * @0000000000000000000000000000000000000000 (*)> -R server serve --stdio exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> blackbox (glob)
   $ rm ../server/.hg/blackbox.log
@@ -266,17 +288,23 @@
   * @bebd167eb94d257ace0e814aeb98e6972ed2970d (*)> add foo (glob)
   * @bebd167eb94d257ace0e814aeb98e6972ed2970d (*)> add foo exited 0 after *.?? seconds (glob)
   * @bebd167eb94d257ace0e814aeb98e6972ed2970d (*)> commit -m foo (glob)
+  * @bebd167eb94d257ace0e814aeb98e6972ed2970d (*)> updated evo-ext-obscache in *.???? seconds (6r, 3o) (glob)
   * @bebd167eb94d257ace0e814aeb98e6972ed2970d (*)> updated served branch cache in *.???? seconds (glob)
   * @bebd167eb94d257ace0e814aeb98e6972ed2970d (*)> wrote served branch cache with 1 labels and 1 nodes (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (6r, 3o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> commit -m foo exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> log --hidden --template '{node}\n' --rev . (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> log --hidden --template '{node}\n' --rev . exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> debugobsolete ffffffffffffffffffffffffffffffffffffffff 45f8b879de922f6a6e620ba04205730335b6fc7e (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> alias 'debugobsolete' expands to 'debugobsolete -d '0 0'' (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (6r, 4o) (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obscache in *.???? seconds (0r, 1o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> debugobsolete ffffffffffffffffffffffffffffffffffffffff 45f8b879de922f6a6e620ba04205730335b6fc7e exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> push -f (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> obscache is out of date, falling back to slower obsstore version (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> obscache is out of date, falling back to slower obsstore version (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (6r, 4o) (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obscache in *.???? seconds (6r, 4o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> push -f exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> log -G (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> writing .hg/cache/tags2-visible with 0 tags (glob)
@@ -286,13 +314,18 @@
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> log --hidden --template '{node}\n' --rev 'desc(r1)' exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> debugobsolete 111111111111111aaaaaaaaa1111111111111111 66f7d451a68b85ed82ff5fcc254daf50c74144bd (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> alias 'debugobsolete' expands to 'debugobsolete -d '0 0'' (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (6r, 5o) (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obscache in *.???? seconds (0r, 1o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> debugobsolete 111111111111111aaaaaaaaa1111111111111111 66f7d451a68b85ed82ff5fcc254daf50c74144bd exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> log --hidden --template '{node}\n' --rev 'desc(r3)' (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> log --hidden --template '{node}\n' --rev 'desc(r3)' exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> debugobsolete 22222222222222222bbbbbbbbbbbbb2222222222 2dc09a01254db841290af0538aa52f6f52c776e3 (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> alias 'debugobsolete' expands to 'debugobsolete -d '0 0'' (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (6r, 6o) (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obscache in *.???? seconds (6r, 6o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> debugobsolete 22222222222222222bbbbbbbbbbbbb2222222222 2dc09a01254db841290af0538aa52f6f52c776e3 exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> push (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (6r, 6o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> push exited 1 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> blackbox (glob)
   $ rm .hg/blackbox.log
@@ -341,12 +374,17 @@
   * @0000000000000000000000000000000000000000 (*)> -R ../server/ debugobsolete --rev '::tip' exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> debugobsolete aaaaaaa11111111aaaaaaaaa1111111111111111 66f7d451a68b85ed82ff5fcc254daf50c74144bd (glob)
   * @0000000000000000000000000000000000000000 (*)> alias 'debugobsolete' expands to 'debugobsolete -d '0 0'' (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obshashrange in *.???? seconds (9r, 9o) (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obscache in *.???? seconds (0r, 1o) (glob)
   * @0000000000000000000000000000000000000000 (*)> -R ../server debugobsolete aaaaaaa11111111aaaaaaaaa1111111111111111 66f7d451a68b85ed82ff5fcc254daf50c74144bd exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> debugobsolete bbbbbbb2222222222bbbbbbbbbbbbb2222222222 bebd167eb94d257ace0e814aeb98e6972ed2970d (glob)
   * @0000000000000000000000000000000000000000 (*)> alias 'debugobsolete' expands to 'debugobsolete -d '0 0'' (glob)
   * @0000000000000000000000000000000000000000 (*)> obscache is out of date, falling back to slower obsstore version (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obshashrange in *.???? seconds (9r, 10o) (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obscache in *.???? seconds (9r, 10o) (glob)
   * @0000000000000000000000000000000000000000 (*)> -R ../server debugobsolete bbbbbbb2222222222bbbbbbbbbbbbb2222222222 bebd167eb94d257ace0e814aeb98e6972ed2970d exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> serve --stdio (glob)
+  * @0000000000000000000000000000000000000000 (*)> updated evo-ext-obshashrange in *.???? seconds (9r, 10o) (glob)
   * @0000000000000000000000000000000000000000 (*)> -R server serve --stdio exited 0 after *.?? seconds (glob)
   * @0000000000000000000000000000000000000000 (*)> blackbox (glob)
   $ rm ../server/.hg/blackbox.log
@@ -370,8 +408,12 @@
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> log --hidden --template '{node}\n' --rev 'desc(r4)' (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> log --hidden --template '{node}\n' --rev 'desc(r4)' exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> pull -r 6 (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (6r, 6o) (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obscache in *.???? seconds (2r, 0o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated served branch cache in *.???? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> wrote served branch cache with 1 labels and 2 nodes (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 9o) (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obscache in *.???? seconds (0r, 3o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> 2 incoming changes - new heads: f69452c5b1af (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> pull -r 6 exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> blackbox (glob)
@@ -424,6 +466,7 @@
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> writing .hg/cache/tags2-visible with 0 tags (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> debugobsolete --rev '::6' exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> debugobshashrange --subranges --rev 'heads(all())' (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 9o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> debugobshashrange --subranges --rev 'heads(all())' exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> log --hidden --template '{node}\n' --rev 'desc(r1)' (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> writing .hg/cache/tags2 with 0 tags (glob)
@@ -433,6 +476,9 @@
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> log --hidden --template '{node}\n' --rev 'desc(r6)' (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> log --hidden --template '{node}\n' --rev 'desc(r6)' exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> pull -r f69452c5b1af6cbaaa56ef50cf94fff5bcc6ca23 (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 9o) (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 11o) (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obscache in *.???? seconds (8r, 11o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> pull -r f69452c5b1af6cbaaa56ef50cf94fff5bcc6ca23 exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> blackbox (glob)
   $ rm .hg/blackbox.log
@@ -467,12 +513,16 @@
   1 new obsolescence markers
   $ hg blackbox
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> debugobshashrange --subranges --rev 'heads(all())' (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 11o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> debugobshashrange --subranges --rev 'heads(all())' exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> log --hidden --template '{node}\n' --rev 'desc(foo)' (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> log --hidden --template '{node}\n' --rev 'desc(foo)' exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> log --hidden --template '{node}\n' --rev 'desc(r4)' (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> log --hidden --template '{node}\n' --rev 'desc(r4)' exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> pull -r bebd167eb94d257ace0e814aeb98e6972ed2970d (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 11o) (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 12o) (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obscache in *.???? seconds (0r, 1o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> pull -r bebd167eb94d257ace0e814aeb98e6972ed2970d exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> blackbox (glob)
   $ rm .hg/blackbox.log
@@ -511,10 +561,15 @@
   repository tip rolled back to revision 7 (undo pull)
   $ hg blackbox
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> debugobshashrange --subranges --rev 'heads(all())' (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 12o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> debugobshashrange --subranges --rev 'heads(all())' exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> pull (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 12o) (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obscache in *.???? seconds (9r, 12o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated served branch cache in *.???? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> wrote served branch cache with 1 labels and 2 nodes (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (9r, 13o) (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obscache in *.???? seconds (0r, 1o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> 1 incoming changes - new heads: 4de32a90b66c (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> pull exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> rollback (glob)
@@ -553,8 +608,13 @@
   (run 'hg update' to get a working copy)
   $ hg blackbox
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> debugobshashrange --subranges --rev 'heads(all())' (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 12o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> debugobshashrange --subranges --rev 'heads(all())' exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> pull (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (8r, 12o) (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obscache in *.???? seconds (9r, 12o) (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obshashrange in *.???? seconds (9r, 13o) (glob)
+  * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> updated evo-ext-obscache in *.???? seconds (0r, 1o) (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> 1 incoming changes - new heads: 4de32a90b66c (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> pull exited 0 after *.?? seconds (glob)
   * @45f8b879de922f6a6e620ba04205730335b6fc7e (*)> blackbox (glob)