discovery: include timing in the debug output

Having such date easily available is useful. It also prepare the inclusion of
some discovery related data in blackbox.

mercurial/setdiscovery.py

@@ -53,6 +53,7 b' from .node import ('
 from . import (
     dagutil,
     error,
+    util,
 )
 
 def _updatesample(dag, nodes, sample, quicksamplesize=0):
@@ -136,6 +137,8 b' def findcommonheads(ui, local, remote,'
     '''Return a tuple (common, anyincoming, remoteheads) used to identify
     missing nodes from or in remote.
     '''
+    start = util.timer()
+
     roundtrips = 0
     cl = local.changelog
     dag = dagutil.revlogdag(cl)
@@ -235,8 +238,9 b' def findcommonheads(ui, local, remote,'
     # common.bases can include nullrev, but our contract requires us to not
     # return any heads in that case, so discard that
     result.discard(nullrev)
+    elapsed = util.timer() - start
     ui.progress(_('searching'), None)
-    ui.debug("%d total queries\n" % roundtrips)
+    ui.debug("%d total queries in %.4fs\n" % (roundtrips, elapsed))
 
     if not result and srvheadhashes != [nullid]:
         if abortwhenunrelated:

tests/test-obsolete-changeset-exchange.t

@@ -143,7 +143,7 b' client only pulls down 1 changeset'
   searching for changes
   taking quick initial sample
   query 2; still undecided: 2, sample size is: 2
-  2 total queries
+  2 total queries in *.????s (glob)
   1 changesets found
   list of changesets:
   bec0734cd68e84477ba7fc1d13e6cff53ab70129

tests/test-push-warn.t

@@ -41,7 +41,7 b' Specifying a revset that evaluates to nu'
   searching for changes
   taking quick initial sample
   query 2; still undecided: 1, sample size is: 1
-  2 total queries
+  2 total queries in *.????s (glob)
   listing keys for "phases"
   checking for updated bookmarks
   listing keys for "bookmarks"

tests/test-setdiscovery.t

@@ -83,7 +83,7 b' Many new:'
   taking initial sample
   searching: 2 queries
   query 2; still undecided: 29, sample size is: 29
-  2 total queries
+  2 total queries in *.????s (glob)
   common heads: bebd167eb94d
   
   % -- b -> a tree
@@ -99,10 +99,9 b' Many new:'
   taking initial sample
   searching: 2 queries
   query 2; still undecided: 2, sample size is: 2
-  2 total queries
+  2 total queries in *.????s (glob)
   common heads: bebd167eb94d
 
-
 Both sides many new with stub:
 
   $ testdesc '-ra1 -ra2' '-rb' '
@@ -122,7 +121,7 b' Both sides many new with stub:'
   taking initial sample
   searching: 2 queries
   query 2; still undecided: 29, sample size is: 29
-  2 total queries
+  2 total queries in *.????s (glob)
   common heads: 2dc09a01254d
   
   % -- b -> a tree
@@ -138,7 +137,7 b' Both sides many new with stub:'
   taking initial sample
   searching: 2 queries
   query 2; still undecided: 29, sample size is: 29
-  2 total queries
+  2 total queries in *.????s (glob)
   common heads: 2dc09a01254d
 
 
@@ -161,7 +160,7 b' Both many new:'
   taking quick initial sample
   searching: 2 queries
   query 2; still undecided: 31, sample size is: 31
-  2 total queries
+  2 total queries in *.????s (glob)
   common heads: 66f7d451a68b
   
   % -- b -> a tree
@@ -177,7 +176,7 b' Both many new:'
   taking quick initial sample
   searching: 2 queries
   query 2; still undecided: 31, sample size is: 31
-  2 total queries
+  2 total queries in *.????s (glob)
   common heads: 66f7d451a68b
 
 
@@ -200,7 +199,7 b' Both many new skewed:'
   taking quick initial sample
   searching: 2 queries
   query 2; still undecided: 51, sample size is: 51
-  2 total queries
+  2 total queries in *.????s (glob)
   common heads: 66f7d451a68b
   
   % -- b -> a tree
@@ -216,7 +215,7 b' Both many new skewed:'
   taking quick initial sample
   searching: 2 queries
   query 2; still undecided: 31, sample size is: 31
-  2 total queries
+  2 total queries in *.????s (glob)
   common heads: 66f7d451a68b
 
 
@@ -242,7 +241,7 b' Both many new on top of long history:'
   sampling from both directions
   searching: 3 queries
   query 3; still undecided: 31, sample size is: 31
-  3 total queries
+  3 total queries in *.????s (glob)
   common heads: 7ead0cba2838
   
   % -- b -> a tree
@@ -261,7 +260,7 b' Both many new on top of long history:'
   sampling from both directions
   searching: 3 queries
   query 3; still undecided: 15, sample size is: 15
-  3 total queries
+  3 total queries in *.????s (glob)
   common heads: 7ead0cba2838
 
 
@@ -324,7 +323,7 b' One with >200 heads, which used to use u'
   sampling from both directions
   searching: 6 queries
   query 6; still undecided: \d+, sample size is: \d+ (re)
-  6 total queries
+  6 total queries in *.????s (glob)
   common heads: 3ee37d65064a
 
 Test actual protocol when pulling one new head in addition to common heads