|
| 1 | +#!/usr/bin/env python3 |
| 2 | +# Copyright 2018 Nico Weber |
| 3 | +# |
| 4 | +# Licensed under the Apache License, Version 2.0 (the "License"); |
| 5 | +# you may not use this file except in compliance with the License. |
| 6 | +# You may obtain a copy of the License at |
| 7 | +# |
| 8 | +# http://www.apache.org/licenses/LICENSE-2.0 |
| 9 | +# |
| 10 | +# Unless required by applicable law or agreed to in writing, software |
| 11 | +# distributed under the License is distributed on an "AS IS" BASIS, |
| 12 | +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| 13 | +# See the License for the specific language governing permissions and |
| 14 | +# limitations under the License. |
| 15 | + |
| 16 | +"""Converts one (or several) .ninja_log files into chrome's about:tracing format. |
| 17 | +
|
| 18 | +If clang -ftime-trace .json files are found adjacent to generated files they |
| 19 | +are embedded. |
| 20 | +
|
| 21 | +Usage: |
| 22 | + ninja -C $BUILDDIR |
| 23 | + ninjatracing $BUILDDIR/.ninja_log > trace.json |
| 24 | +""" |
| 25 | + |
| 26 | +import json |
| 27 | +import os |
| 28 | +import optparse |
| 29 | +import re |
| 30 | +import sys |
| 31 | + |
| 32 | + |
| 33 | +class Target: |
| 34 | + """Represents a single line read for a .ninja_log file. Start and end times |
| 35 | + are milliseconds.""" |
| 36 | + def __init__(self, start, end): |
| 37 | + self.start = int(start) |
| 38 | + self.end = int(end) |
| 39 | + self.targets = [] |
| 40 | + |
| 41 | + |
| 42 | +def read_targets(log, show_all): |
| 43 | + """Reads all targets from .ninja_log file |log_file|, sorted by start |
| 44 | + time""" |
| 45 | + header = log.readline() |
| 46 | + m = re.search(r'^# ninja log v(\d+)\n$', header) |
| 47 | + assert m, "unrecognized ninja log version %r" % header |
| 48 | + version = int(m.group(1)) |
| 49 | + assert 5 <= version <= 6, "unsupported ninja log version %d" % version |
| 50 | + if version == 6: |
| 51 | + # Skip header line |
| 52 | + next(log) |
| 53 | + |
| 54 | + targets = {} |
| 55 | + last_end_seen = 0 |
| 56 | + for line in log: |
| 57 | + if line.startswith('#'): |
| 58 | + continue |
| 59 | + start, end, _, name, cmdhash = line.strip().split('\t') # Ignore restat. |
| 60 | + if not show_all and int(end) < last_end_seen: |
| 61 | + # An earlier time stamp means that this step is the first in a new |
| 62 | + # build, possibly an incremental build. Throw away the previous data |
| 63 | + # so that this new build will be displayed independently. |
| 64 | + targets = {} |
| 65 | + last_end_seen = int(end) |
| 66 | + targets.setdefault(cmdhash, Target(start, end)).targets.append(name) |
| 67 | + return sorted(targets.values(), key=lambda job: job.end, reverse=True) |
| 68 | + |
| 69 | + |
| 70 | +class Threads: |
| 71 | + """Tries to reconstruct the parallelism from a .ninja_log""" |
| 72 | + def __init__(self): |
| 73 | + self.workers = [] # Maps thread id to time that thread is occupied for. |
| 74 | + |
| 75 | + def alloc(self, target): |
| 76 | + """Places target in an available thread, or adds a new thread.""" |
| 77 | + for worker in range(len(self.workers)): |
| 78 | + if self.workers[worker] >= target.end: |
| 79 | + self.workers[worker] = target.start |
| 80 | + return worker |
| 81 | + self.workers.append(target.start) |
| 82 | + return len(self.workers) - 1 |
| 83 | + |
| 84 | + |
| 85 | +def read_events(trace, options): |
| 86 | + """Reads all events from time-trace json file |trace|.""" |
| 87 | + trace_data = json.load(trace) |
| 88 | + |
| 89 | + def include_event(event, options): |
| 90 | + """Only include events if they are complete events, are longer than |
| 91 | + granularity, and are not totals.""" |
| 92 | + return ((event['ph'] == 'X') and |
| 93 | + (event['dur'] >= options['granularity']) and |
| 94 | + (not event['name'].startswith('Total'))) |
| 95 | + |
| 96 | + return [x for x in trace_data['traceEvents'] if include_event(x, options)] |
| 97 | + |
| 98 | + |
| 99 | +def trace_to_dicts(target, trace, options, pid, tid): |
| 100 | + """Read a file-like object |trace| containing -ftime-trace data and yields |
| 101 | + about:tracing dict per eligible event in that log.""" |
| 102 | + ninja_time = (target.end - target.start) * 1000 |
| 103 | + for event in read_events(trace, options): |
| 104 | + # Check if any event duration is greater than the duration from ninja. |
| 105 | + if event['dur'] > ninja_time: |
| 106 | + print("Inconsistent timing found (clang time > ninja time). Please" |
| 107 | + " ensure that timings are from consistent builds.") |
| 108 | + sys.exit(1) |
| 109 | + |
| 110 | + # Set tid and pid from ninja log. |
| 111 | + event['pid'] = pid |
| 112 | + event['tid'] = tid |
| 113 | + |
| 114 | + # Offset trace time stamp by ninja start time. |
| 115 | + event['ts'] += (target.start * 1000) |
| 116 | + |
| 117 | + yield event |
| 118 | + |
| 119 | + |
| 120 | +def embed_time_trace(ninja_log_dir, target, pid, tid, options): |
| 121 | + """Produce time trace output for the specified ninja target. Expects |
| 122 | + time-trace file to be in .json file named based on .o file.""" |
| 123 | + for t in target.targets: |
| 124 | + o_path = os.path.join(ninja_log_dir, t) |
| 125 | + json_trace_path = os.path.splitext(o_path)[0] + '.json' |
| 126 | + try: |
| 127 | + with open(json_trace_path, 'r') as trace: |
| 128 | + for time_trace_event in trace_to_dicts(target, trace, options, |
| 129 | + pid, tid): |
| 130 | + yield time_trace_event |
| 131 | + except IOError: |
| 132 | + pass |
| 133 | + |
| 134 | + |
| 135 | +def log_to_dicts(log, pid, options): |
| 136 | + """Reads a file-like object |log| containing a .ninja_log, and yields one |
| 137 | + about:tracing dict per command found in the log.""" |
| 138 | + threads = Threads() |
| 139 | + for target in read_targets(log, options['showall']): |
| 140 | + tid = threads.alloc(target) |
| 141 | + |
| 142 | + yield { |
| 143 | + 'name': '%0s' % ', '.join(target.targets), 'cat': 'targets', |
| 144 | + 'ph': 'X', 'ts': (target.start * 1000), |
| 145 | + 'dur': ((target.end - target.start) * 1000), |
| 146 | + 'pid': pid, 'tid': tid, 'args': {}, |
| 147 | + } |
| 148 | + if options.get('embed_time_trace', False): |
| 149 | + # Add time-trace information into the ninja trace. |
| 150 | + try: |
| 151 | + ninja_log_dir = os.path.dirname(log.name) |
| 152 | + except AttributeError: |
| 153 | + continue |
| 154 | + for time_trace in embed_time_trace(ninja_log_dir, target, pid, |
| 155 | + tid, options): |
| 156 | + yield time_trace |
| 157 | + |
| 158 | + |
| 159 | +def main(argv): |
| 160 | + usage = __doc__ |
| 161 | + parser = optparse.OptionParser(usage) |
| 162 | + parser.add_option('-a', '--showall', action='store_true', dest='showall', |
| 163 | + default=False, |
| 164 | + help='report on last build step for all outputs. Default ' |
| 165 | + 'is to report just on the last (possibly incremental) ' |
| 166 | + 'build') |
| 167 | + parser.add_option('-g', '--granularity', type='int', default=50000, |
| 168 | + dest='granularity', |
| 169 | + help='minimum length time-trace event to embed in ' |
| 170 | + 'microseconds. Default: %default') |
| 171 | + parser.add_option('-e', '--embed-time-trace', action='store_true', |
| 172 | + default=False, dest='embed_time_trace', |
| 173 | + help='embed clang -ftime-trace json file found adjacent ' |
| 174 | + 'to a target file') |
| 175 | + (options, args) = parser.parse_args() |
| 176 | + |
| 177 | + if len(args) == 0: |
| 178 | + print('Must specify at least one .ninja_log file') |
| 179 | + parser.print_help() |
| 180 | + return 1 |
| 181 | + |
| 182 | + entries = [] |
| 183 | + for pid, log_file in enumerate(args): |
| 184 | + with open(log_file, 'r') as log: |
| 185 | + entries += list(log_to_dicts(log, pid, vars(options))) |
| 186 | + json.dump(entries, sys.stdout) |
| 187 | + |
| 188 | + |
| 189 | +if __name__ == '__main__': |
| 190 | + sys.exit(main(sys.argv[1:])) |
0 commit comments