Merge pull request nico#20 from rgal/embed_time_trace

Embed clang -ftime-trace timing data into ninja log data

Author: nico

ninjatracing

@@ -13,7 +13,10 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-"""Converts one (or several) .ninja_log files into chrome's about:tracing format
+"""Converts one (or several) .ninja_log files into chrome's about:tracing format.
+
+If clang -ftime-trace .json files are found adjacent to generated files they
+are embedded.
 
 Usage:
     ninja -C $BUILDDIR
@@ -22,13 +25,15 @@ Usage:
 
 from __future__ import print_function
 import json
+import os
 import optparse
 import re
 import sys
 
 
 class Target:
-    """Represents a single line read for a .ninja_log file."""
+    """Represents a single line read for a .ninja_log file. Start and end times
+    are milliseconds."""
     def __init__(self, start, end):
         self.start = int(start)
         self.end = int(end)
@@ -76,17 +81,78 @@ class Threads:
         return len(self.workers) - 1
 
 
-def log_to_dicts(log, pid, show_all):
+def read_events(trace, options):
+    """Reads all events from time-trace json file |trace|."""
+    trace_data = json.load(trace)
+
+    def include_event(event, options):
+        """Only include events if they are complete events, are longer than
+        granularity, and are not totals."""
+        return ((event['ph'] == 'X') and
+                (event['dur'] >= options['granularity']) and
+                (not event['name'].startswith('Total')))
+
+    return [x for x in trace_data['traceEvents'] if include_event(x, options)]
+
+
+def trace_to_dicts(target, trace, options, pid, tid):
+    """Read a file-like object |trace| containing -ftime-trace data and yields
+    about:tracing dict per eligible event in that log."""
+    for event in read_events(trace, options):
+        # Check if any event duration is greater than the duration from ninja.
+        ninja_time = (target.end - target.start) * 1000
+        if event['dur'] > ninja_time:
+            print("Inconsistent timing found (clang time > ninja time). Please"
+                  " ensure that timings are from consistent builds.")
+            sys.exit(1)
+
+        # Set tid and pid from ninja log.
+        event['pid'] = pid
+        event['tid'] = tid
+
+        # Offset trace time stamp by ninja start time.
+        event['ts'] += (target.start * 1000)
+
+        yield event
+
+
+def embed_time_trace(ninja_log_dir, target, pid, tid, options):
+    """Produce time trace output for the specified ninja target. Expects
+    time-trace file to be in .json file named based on .o file."""
+    for t in target.targets:
+        o_path = os.path.join(ninja_log_dir, t)
+        json_trace_path = os.path.splitext(o_path)[0] + '.json'
+        try:
+            with open(json_trace_path, 'r') as trace:
+                for time_trace_event in trace_to_dicts(target, trace, options,
+                                                       pid, tid):
+                    yield time_trace_event
+        except IOError:
+            pass
+
+
+def log_to_dicts(log, pid, options):
     """Reads a file-like object |log| containing a .ninja_log, and yields one
     about:tracing dict per command found in the log."""
     threads = Threads()
-    for target in read_targets(log, show_all):
+    for target in read_targets(log, options['showall']):
+        tid = threads.alloc(target)
+
         yield {
             'name': '%0s' % ', '.join(target.targets), 'cat': 'targets',
             'ph': 'X', 'ts': (target.start * 1000),
             'dur': ((target.end - target.start) * 1000),
-            'pid': pid, 'tid': threads.alloc(target), 'args': {},
+            'pid': pid, 'tid': tid, 'args': {},
             }
+        if options.get('embed_time_trace', False):
+            # Add time-trace information into the ninja trace.
+            try:
+                ninja_log_dir = os.path.dirname(log.name)
+            except AttributeError:
+                continue
+            for time_trace in embed_time_trace(ninja_log_dir, target, pid,
+                                               tid, options):
+                yield time_trace
 
 
 def main(argv):
@@ -97,6 +163,14 @@ def main(argv):
                       help='report on last build step for all outputs. Default '
                       'is to report just on the last (possibly incremental) '
                       'build')
+    parser.add_option('-g', '--granularity', type='int', default=50000,
+                      dest='granularity',
+                      help='minimum length time-trace event to embed in '
+                      'microseconds. Default: %default')
+    parser.add_option('-e', '--embed-time-trace', action='store_true',
+                      default=False, dest='embed_time_trace',
+                      help='embed clang -ftime-trace json file found adjacent '
+                      'to a target file')
     (options, args) = parser.parse_args()
 
     if len(args) == 0:
@@ -107,7 +181,7 @@ def main(argv):
     entries = []
     for pid, log_file in enumerate(args):
         with open(log_file, 'r') as log:
-            entries += list(log_to_dicts(log, pid, options.showall))
+            entries += list(log_to_dicts(log, pid, vars(options)))
     json.dump(entries, sys.stdout)
 
 

ninjatracing_test

@@ -27,7 +27,7 @@ class TestNinjaTracing(unittest.TestCase):
         log = StringIO("# ninja log v5\n"
                        "100\t200\t0\tmy_output\tdeadbeef\n"
                        "50\t120\t0\tmy_first_output\t0afef\n")
-        dicts = list(ninjatracing.log_to_dicts(log, 42, True))
+        dicts = list(ninjatracing.log_to_dicts(log, 42, {'showall': True}))
         expected = [{
                 'name': 'my_output', 'cat': 'targets', 'ph': 'X',
                 'ts': 100000, 'dur': 100000, 'pid': 42, 'tid': 0,
@@ -45,7 +45,7 @@ class TestNinjaTracing(unittest.TestCase):
         log = StringIO("# ninja log v5\n"
                        "100\t200\t0\tmy_output\tdeadbeef\n"
                        "50\t120\t0\tmy_first_output\t0afef\n")
-        dicts = list(ninjatracing.log_to_dicts(log, 42, False))
+        dicts = list(ninjatracing.log_to_dicts(log, 42, {'showall': False}))
         expected = [{
                 'name': 'my_first_output', 'cat': 'targets', 'ph': 'X',
                 'ts': 50000, 'dur': 70000, 'pid': 42, 'tid': 0,
@@ -60,7 +60,7 @@ class TestNinjaTracing(unittest.TestCase):
         log = StringIO("# ninja log v5\n"
                        "100\t200\t0\toutput\tdeadbeef\n"
                        "100\t200\t0\tother_output\tdeadbeef\n")
-        dicts = list(ninjatracing.log_to_dicts(log, 42, True))
+        dicts = list(ninjatracing.log_to_dicts(log, 42, {'showall': True}))
         expected = [{
                 'name': 'output, other_output', 'cat': 'targets', 'ph': 'X',
                 'ts': 100000, 'dur': 100000, 'pid': 42, 'tid': 0,
@@ -69,6 +69,22 @@ class TestNinjaTracing(unittest.TestCase):
             ]
         self.assertEqual(expected, dicts)
 
+    def test_trace(self):
+        # Simple test for converting time trace to dictionaries. Tests removing
+        # incomplete, "Total" and short events, replacing tid and pid and
+        # adjusting timestamp.
+        trace = StringIO('{ "traceEvents": ['
+                       '{ "dur": 1500, "name": "LongEvent", "ph": "X", "pid": 1, "tid": 12345, "ts": 1000 },'
+                       '{ "dur": 500, "name": "TooShort", "ph": "X", "pid": 1, "tid": 12345, "ts": 1000 },'
+                       '{ "args": { "avg ms": 1, "count": 2 }, "dur": 1111, "name": "Total Count", "ph": "X", "pid": 1, "tid": 12345, "ts": 0 },'
+                       '{ "args": { "name": "clang" }, "cat": "", "name": "process_name", "ph": "M", "pid": 1, "tid": 0, "ts": 0 }'
+                       ']}')
+        target = ninjatracing.Target(5, 10)
+        dicts = list(ninjatracing.trace_to_dicts(target, trace, {'granularity': 1000}, 42, 5))
+        expected = [{
+            'dur': 1500, 'name': 'LongEvent', 'ph': 'X', 'pid': 42, 'tid': 5, 'ts': 6000},
+            ]
+        self.assertEqual(expected, dicts)
 
 if __name__ == '__main__':
     unittest.main()