changeset 32712:43bda143e3b2

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.

--- a/mercurial/setdiscovery.py	Sun May 28 21:33:33 2017 -0400
+++ b/mercurial/setdiscovery.py	Wed Jun 07 10:29:39 2017 +0100
@@ -53,6 +53,7 @@
 from . import (
     dagutil,
     error,
+    util,
 )
 
 def _updatesample(dag, nodes, sample, quicksamplesize=0):
@@ -136,6 +137,8 @@
     '''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 @@
     # 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:

--- a/tests/test-obsolete-changeset-exchange.t	Sun May 28 21:33:33 2017 -0400
+++ b/tests/test-obsolete-changeset-exchange.t	Wed Jun 07 10:29:39 2017 +0100
@@ -143,7 +143,7 @@
   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

--- a/tests/test-push-warn.t	Sun May 28 21:33:33 2017 -0400
+++ b/tests/test-push-warn.t	Wed Jun 07 10:29:39 2017 +0100
@@ -41,7 +41,7 @@
   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"

--- a/tests/test-setdiscovery.t	Sun May 28 21:33:33 2017 -0400
+++ b/tests/test-setdiscovery.t	Wed Jun 07 10:29:39 2017 +0100
@@ -83,7 +83,7 @@
   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 @@
   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 @@
   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 @@
   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 @@
   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 @@
   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 @@
   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 @@
   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 @@
   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 @@
   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 @@
   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