debugdiscovery: display time elapsed during the discovery step

debugdiscovery: display time elapsed during the discovery step

This is a useful information. Now that we perform more analysing after the
discovery is done, it is worth have a more precise measurement. For serious
timing analysis use `hg perfdiscovery`.

--- a/mercurial/debugcommands.py	Tue Mar 26 17:26:54 2019 +0100
+++ b/mercurial/debugcommands.py	Tue Mar 26 17:35:28 2019 +0100
@@ -815,7 +815,8 @@
 
     remoterevs, _checkout = hg.addbranchrevs(repo, remote, branches, revs=None)
     localrevs = opts['rev']
-    common, hds = doit(localrevs, remoterevs)
+    with util.timedcm('debug-discovery') as t:
+        common, hds = doit(localrevs, remoterevs)
 
     # compute all statistics
     common = set(common)
@@ -823,6 +824,7 @@
     lheads = set(repo.heads())
 
     data = {}
+    data['elapsed'] = t.elapsed
     data['nb-common'] = len(common)
     data['nb-common-local'] = len(common & lheads)
     data['nb-common-remote'] = len(common & rheads)
@@ -835,6 +837,7 @@
     data['nb-revs-missing'] = data['nb-revs'] - data['nb-revs-common']
 
     # display discovery summary
+    ui.write(("elapsed time:  %(elapsed)f seconds\n") % data)
     ui.write(("heads summary:\n"))
     ui.write(("  total common heads:  %(nb-common)9d\n") % data)
     ui.write(("    also local heads:  %(nb-common-local)9d\n") % data)

--- a/tests/test-setdiscovery.t	Tue Mar 26 17:26:54 2019 +0100
+++ b/tests/test-setdiscovery.t	Tue Mar 26 17:35:28 2019 +0100
@@ -43,6 +43,7 @@
   comparing with b
   searching for changes
   unpruned common: 01241442b3c2 66f7d451a68b b5714e113bc0
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          2
       also local heads:          2
@@ -63,6 +64,7 @@
   query 1; heads
   searching for changes
   all local heads known remotely
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          2
       also local heads:          2
@@ -83,6 +85,7 @@
   query 1; heads
   searching for changes
   all local heads known remotely
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          1
@@ -102,6 +105,7 @@
   comparing with a
   searching for changes
   unpruned common: 01241442b3c2 b5714e113bc0
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          2
       also local heads:          1
@@ -122,6 +126,7 @@
   query 1; heads
   searching for changes
   all remote heads known locally
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          2
       also local heads:          1
@@ -142,6 +147,7 @@
   query 1; heads
   searching for changes
   all remote heads known locally
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          2
       also local heads:          1
@@ -168,6 +174,7 @@
   comparing with b
   searching for changes
   unpruned common: bebd167eb94d
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          1
@@ -191,6 +198,7 @@
   searching: 2 queries
   query 2; still undecided: 29, sample size is: 29
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          1
@@ -214,6 +222,7 @@
   searching: 2 queries
   query 2; still undecided: 31, sample size is: 31
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -233,6 +242,7 @@
   comparing with a
   searching for changes
   unpruned common: 66f7d451a68b bebd167eb94d
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -256,6 +266,7 @@
   searching: 2 queries
   query 2; still undecided: 2, sample size is: 2
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -279,6 +290,7 @@
   searching: 2 queries
   query 2; still undecided: 2, sample size is: 2
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -304,6 +316,7 @@
   comparing with b
   searching for changes
   unpruned common: 2dc09a01254d
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          1
@@ -327,6 +340,7 @@
   searching: 2 queries
   query 2; still undecided: 29, sample size is: 29
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          1
@@ -350,6 +364,7 @@
   searching: 2 queries
   query 2; still undecided: 31, sample size is: 31
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -369,6 +384,7 @@
   comparing with a
   searching for changes
   unpruned common: 2dc09a01254d 66f7d451a68b
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -392,6 +408,7 @@
   searching: 2 queries
   query 2; still undecided: 29, sample size is: 29
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -415,6 +432,7 @@
   searching: 2 queries
   query 2; still undecided: 29, sample size is: 29
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -441,6 +459,7 @@
   comparing with b
   searching for changes
   unpruned common: 66f7d451a68b
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -464,6 +483,7 @@
   searching: 2 queries
   query 2; still undecided: 31, sample size is: 31
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -487,6 +507,7 @@
   searching: 2 queries
   query 2; still undecided: 31, sample size is: 31
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -506,6 +527,7 @@
   comparing with a
   searching for changes
   unpruned common: 66f7d451a68b
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -529,6 +551,7 @@
   searching: 2 queries
   query 2; still undecided: 31, sample size is: 31
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -552,6 +575,7 @@
   searching: 2 queries
   query 2; still undecided: 31, sample size is: 31
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -578,6 +602,7 @@
   comparing with b
   searching for changes
   unpruned common: 66f7d451a68b
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -601,6 +626,7 @@
   searching: 2 queries
   query 2; still undecided: 51, sample size is: 51
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -624,6 +650,7 @@
   searching: 2 queries
   query 2; still undecided: 51, sample size is: 51
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -643,6 +670,7 @@
   comparing with a
   searching for changes
   unpruned common: 66f7d451a68b
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -666,6 +694,7 @@
   searching: 2 queries
   query 2; still undecided: 31, sample size is: 31
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -689,6 +718,7 @@
   searching: 2 queries
   query 2; still undecided: 31, sample size is: 31
   2 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -715,6 +745,7 @@
   comparing with b
   searching for changes
   unpruned common: 7ead0cba2838
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -741,6 +772,7 @@
   searching: 3 queries
   query 3; still undecided: 31, sample size is: 31
   3 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -767,6 +799,7 @@
   searching: 3 queries
   query 3; still undecided: 31, sample size is: 31
   3 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -786,6 +819,7 @@
   comparing with a
   searching for changes
   unpruned common: 7ead0cba2838
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -812,6 +846,7 @@
   searching: 3 queries
   query 3; still undecided: 15, sample size is: 15
   3 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -838,6 +873,7 @@
   searching: 3 queries
   query 3; still undecided: 15, sample size is: 15
   3 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -916,6 +952,7 @@
   searching: 6 queries
   query 6; still undecided: \d+, sample size is: \d+ (re)
   6 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0
@@ -941,6 +978,7 @@
   searching: 3 queries
   query 3; still undecided: 3, sample size is: 3
   3 total queries in *.????s (glob)
+  elapsed time:  * seconds (glob)
   heads summary:
     total common heads:          1
       also local heads:          0