[lit] Add --time-trace-output to lit

[russell.gallop]

Summary

This produces a chrome://tracing compatible trace file in the same way as -ftime-trace.

This can be useful in optimising test time where one long test is causing long overall test time on a wide machine.
This also helped in finding tests which have side effects on others (e.g. https://reviews.llvm.org/D84885).

Example:

trace.json257 KBDownload

[yln]

That's really cool, thanks!

I am happy with this apart from some smaller nits.

llvm/utils/lit/lit/reports.py

139

2 blank lines

143

Unused

146

Please remove comment

148

Please format the new code/use linter.
Extra space after events =, missing space in #Rebase, etc.

152

Probably better to get the first timestamp in the beginning and compute the desired ts from the start rather than rebasing everything.

161

elapsed_time = test.result.elapsed or 0.0

[yln]

llvm/utils/lit/lit/reports.py

168

One quick additional question: I am assuming this is here because we want whole numbers? I am not sure about Python numerics; there is no risk of overflowing here, right?

[russell.gallop]

Fixed comments and added test.

[russell.gallop]

llvm/utils/lit/lit/reports.py

143

Now used.

148

Not sure what formatter is normally used for python in LLVM, applied autopep8 and fixed these.

152

Done (if I have understood correctly).

168

Good question. I had a look at this.

• On python3 integers are of unlimited size so this is not a problem.
• On python2 64bit an int is 64bit so this is not likely to be a problem
• On python2 32bit an int is 32bit, which would be limit this to around 36 minutes. Python2 will promote this to a long if it goes over sys.maxint (even when creating an int with int()).
  
  Tested with the following on 32bit python2.7.15. i = int(2147483649.) # 2 more than sys.maxint as a float, like we are doing here. assert isinstance(i, long)

So it should be fine. Thanks for raising it.

[russell.gallop]

llvm/utils/lit/lit/reports.py

168

I am assuming this is here because we want whole numbers?

That's correct.

[yln]

LGTM, thanks! Please wait a few days before landing to give others a chance to comment.

llvm/utils/lit/lit/Test.py

class Result(object):
 
     def __init__(self, code, output='', elapsed=None):
         # The result code.
         self.code = code
         # The test output.
         self.output = output
         # The wall timing to execute the test, if timing.
         self.elapsed = elapsed
+        self.start = None
+        self.pid = None
         # The metrics reported by this test.
         self.metrics = {}
         # The micro-test results reported by this test.
         self.microResults = {}
 
     def addMetric(self, name, value):
         """
         addMetric(name, value)

llvm/utils/lit/lit/cl_arguments.py

execution_group.add_argument("--time-tests",
             action="store_true")
     execution_group.add_argument("--no-execute",
             dest="noExecute",
             help="Don't execute any tests (assume PASS)",
             action="store_true")
     execution_group.add_argument("--xunit-xml-output",
             type=lit.reports.XunitReport,
             help="Write XUnit-compatible XML test reports to the specified file")
+    execution_group.add_argument("--time-trace-output",
+            type=lit.reports.TimeTraceReport,
+            help="Write Chrome tracing compatible JSON to the specified file")
     execution_group.add_argument("--timeout",
             dest="maxIndividualTestTime",
             help="Maximum time to spend running a single test (in seconds). "
                  "0 means no time limit. [Default: 0]",
             type=_non_negative_int) # TODO(yln): --[no-]test-timeout, instead of 0 allowed
     execution_group.add_argument("--max-failures",
             help="Stop execution after the given number of failures.",
             type=_positive_int)
if opts.numShards or opts.runShard:
         if not opts.numShards or not opts.runShard:
             parser.error("--num-shards and --run-shard must be used together")
         if opts.runShard > opts.numShards:
             parser.error("--run-shard must be between 1 and --num-shards (inclusive)")
         opts.shard = (opts.runShard, opts.numShards)
     else:
         opts.shard = None
 
-    opts.reports = filter(None, [opts.output, opts.xunit_xml_output])
+    opts.reports = filter(None, [opts.output, opts.xunit_xml_output, opts.time_trace_output])
 
     return opts
 
 
 def _positive_int(arg):
     return _int(arg, 'positive', lambda i: i > 0)
 
 

llvm/utils/lit/lit/reports.py

def _get_skip_reason(self, test):
         if code == lit.Test.SKIPPED:
             return 'User interrupt'
 
         assert code == lit.Test.UNSUPPORTED
         features = test.getMissingRequiredFeatures()
         if features:
             return 'Missing required feature(s): ' + ', '.join(features)
         return 'Unsupported configuration'
+
+
+class TimeTraceReport(object):
+    def __init__(self, output_file):
+        self.output_file = output_file
+        self.skipped_codes = {lit.Test.EXCLUDED,
+                              lit.Test.SKIPPED, lit.Test.UNSUPPORTED}
+
+    def write_results(self, tests, elapsed):
+        # Find when first test started so we can make start times relative.
+        first_start_time = min([t.result.start for t in tests])
+        events = [self._get_test_event(
+            x, first_start_time) for x in tests if x.result.code not in self.skipped_codes]
+
+        json_data = {'traceEvents': events}
+
+        with open(self.output_file, "w") as time_trace_file:
+            json.dump(json_data, time_trace_file, indent=2, sort_keys=True)
+
+    def _get_test_event(self, test, first_start_time):
+        test_name = test.getFullName()
+        elapsed_time = test.result.elapsed or 0.0
+        start_time = test.result.start - first_start_time if test.result.start else 0.0
+        pid = test.result.pid or 0
+        return {
+            'pid': pid,
+            'tid': 1,
+            'ph': 'X',
+            'ts': int(start_time * 1000000.),
+            'dur': int(elapsed_time * 1000000.),
+            'name': test_name,
+        }

llvm/utils/lit/lit/worker.py

 """
 The functions in this module are meant to run on a separate worker process.
 Exception: in single process mode _execute is called directly.
 
 For efficiency, we copy all data needed to execute all tests into each worker
 and store it in global variables. This reduces the cost of each task.
 """
 import contextlib
+import os
 import signal
 import time
 import traceback
 
 import lit.Test
 import lit.util
 
 
def _get_parallelism_semaphore(test):
     return _parallelism_semaphores.get(pg, NopSemaphore())
 
 
 # Do not inline! Directly used by LitTestCase.py
 def _execute(test, lit_config):
     start = time.time()
     result = _execute_test_handle_errors(test, lit_config)
     result.elapsed = time.time() - start
+    result.start = start
+    result.pid = os.getpid()
     return result
 
 
 def _execute_test_handle_errors(test, lit_config):
     try:
         result = test.config.test_format.execute(test, lit_config)
         return _adapt_result(result)
     except: