tracing: log perftraces to the blackbox

Summary:
Now that we're recording perftraces, let's log their results to the
blackbox if the command exceeds a configurable threshold.

Reviewed By: sfilipco

Differential Revision: D14426366

fbshipit-source-id: 24f261aaa2b089dbc959d709e51de1c0359d976d

edenscm/mercurial/configitems.py

@@ -428,6 +428,8 @@ coreconfigitem("smtp", "tls", default="none")
 coreconfigitem("smtp", "username", default=None)
 coreconfigitem("sparse", "missingwarning", default=False)
 coreconfigitem("templates", ".*", default=None, generic=True)
+coreconfigitem("tracing", "stderr", default=False)
+coreconfigitem("tracing", "threshold", default=10)
 coreconfigitem("treestate", "mingcage", default=1209600)
 coreconfigitem("treestate", "minrepackthreshold", default="10M")
 coreconfigitem("treestate", "repackfactor", default=3)

edenscm/mercurial/dispatch.py

@@ -452,6 +452,17 @@ def dispatch(req):
             ret or 0,
             duration,
         )
+
+        traces = perftrace.traces()
+        if traces:
+            threshold = req.ui.configint("tracing", "threshold")
+            for trace in traces:
+                if trace.duration() > threshold:
+                    output = perftrace.asciirender(trace)
+                    if req.ui.configbool("tracing", "stderr"):
+                        req.ui.warn("%s\n" % output)
+                    req.ui.log("perftrace", "Trace:\n%s\n" % output)
+
         req.ui._measuredtimes["command_duration"] = duration * 1000
         retmask = req.ui.configint("ui", "exitcodemask")
 

edenscm/mercurial/help/config.txt

@@ -1995,6 +1995,19 @@ Alias definitions for templates. See :hg:`help templates` for details.
 Use the ``[templates]`` section to define template strings.
 See :hg:`help templates` for details.
 
+``tracing``
+-------------
+
+``stderr``
+    Whether to print the trace to stderr if it meets the ``tracing.threshold``
+    cutoff.
+    (default: false).
+
+``threshold``
+    Integer. Minimum duration, in seconds, a command must run in order for the
+    trace to be logged (usually to the blackbox).
+    (default: 10)
+
 ``treestate``
 -------------
 

edenscm/mercurial/perftrace.py

@@ -8,7 +8,7 @@ import time
 
 from contextlib import contextmanager
 
-from . import error
+from . import encoding, error
 
 spans = []
 
@@ -34,6 +34,18 @@ def traces():
     return finished_traces
 
 
+lasttime = 0
+
+
+def gettime():
+    # Make it "run-tests.py -i" friendly
+    if "TESTTMP" in encoding.environ:
+        global lasttime
+        lasttime += 1
+        return lasttime
+    return time.time()
+
+
 @contextmanager
 def trace(name):
     try:
@@ -46,10 +58,10 @@ def trace(name):
         if latest:
             latest.children.append(span)
 
-        span.start = time.time()
+        span.start = gettime()
         yield
     finally:
-        span.end = time.time()
+        span.end = gettime()
         spans.pop(-1)
         if not spans:
             finished_traces.append(span)

tests/test-perftrace.t

@@ -0,0 +1,21 @@
+  $ setconfig blackbox.track=perftrace tracing.threshold=0
+  $ newrepo
+  $ drawdag << 'EOS'
+  > C
+  > |
+  > B
+  > |
+  > A
+  > EOS
+  $ enable blackbox
+
+  $ hg up $C --config tracing.stderr=True
+  3 files updated, 0 files merged, 0 files removed, 0 files unresolved
+  0.0  hg up 26805aba1e600a82e93661149f2313866a221a7b --config 'tracing.stderr=True' (*) (glob)
+  1.0
+  
+  $ cat .hg/blackbox.log
+  1970/01/01 00:00:00 * @26805aba1e600a82e93661149f2313866a221a7b (*)> Trace: (glob)
+  0.0  hg up 26805aba1e600a82e93661149f2313866a221a7b --config 'tracing.stderr=True' (*) (glob)
+  1.0
+