| 1 | #!/usr/bin/env python3 |
| 2 | # SPDX-License-Identifier: Apache-2.0 |
| 3 | # SPDX-FileCopyrightText: Copyright contributors to the vLLM project |
| 4 | |
| 5 | # Copyright (c) 2018 The Chromium Authors. All rights reserved. |
| 6 | # Use of this source code is governed by a BSD-style license that can be |
| 7 | # found in the LICENSE file. |
| 8 | |
| 9 | # Modified version of: https://chromium.googlesource.com/chromium/tools/depot_tools.git/+/refs/heads/main/post_build_ninja_summary.py |
| 10 | """Summarize the last ninja build, invoked with ninja's -C syntax. |
| 11 | |
| 12 | > python3 tools/report_build_time_ninja.py -C build/.. |
| 13 | |
| 14 | Typical output looks like this: |
| 15 | ``` |
| 16 | Longest build steps for .cpp.o: |
| 17 | 1.0 weighted s to build ...torch_bindings.cpp.o (12.4 s elapsed time) |
| 18 | 2.0 weighted s to build ..._attn_c.dir/csrc... (23.5 s elapsed time) |
| 19 | 2.6 weighted s to build ...torch_bindings.cpp.o (31.5 s elapsed time) |
| 20 | 3.2 weighted s to build ...torch_bindings.cpp.o (38.5 s elapsed time) |
| 21 | Longest build steps for .so (linking): |
| 22 | 0.1 weighted s to build _moe_C.abi3.so (1.0 s elapsed time) |
| 23 | 0.5 weighted s to build ...flash_attn_c.abi3.so (1.1 s elapsed time) |
| 24 | 6.2 weighted s to build _C.abi3.so (6.2 s elapsed time) |
| 25 | Longest build steps for .cu.o: |
| 26 | 15.3 weighted s to build ...machete_mm_... (183.5 s elapsed time) |
| 27 | 15.3 weighted s to build ...machete_mm_... (183.5 s elapsed time) |
| 28 | 15.3 weighted s to build ...machete_mm_... (183.6 s elapsed time) |
| 29 | 15.3 weighted s to build ...machete_mm_... (183.7 s elapsed time) |
| 30 | 15.5 weighted s to build ...machete_mm_... (185.6 s elapsed time) |
| 31 | 15.5 weighted s to build ...machete_mm_... (185.9 s elapsed time) |
| 32 | 15.5 weighted s to build ...machete_mm_... (186.2 s elapsed time) |
| 33 | 37.4 weighted s to build ...scaled_mm_c3x.cu... (449.0 s elapsed time) |
| 34 | 43.9 weighted s to build ...scaled_mm_c2x.cu... (527.4 s elapsed time) |
| 35 | 344.8 weighted s to build ...attention_...cu.o (1087.2 s elapsed time) |
| 36 | 1110.0 s weighted time (10120.4 s elapsed time sum, 9.1x parallelism) |
| 37 | 134 build steps completed, average of 0.12/s |
| 38 | ``` |
| 39 | """ |
| 40 | |
| 41 | import argparse |
| 42 | import errno |
| 43 | import fnmatch |
| 44 | import os |
| 45 | import sys |
| 46 | from collections import defaultdict |
| 47 | |
| 48 | # The number of long build times to report: |
| 49 | long_count = 10 |
| 50 | # The number of long times by extension to report |
| 51 | long_ext_count = 10 |
| 52 | |
| 53 | |
| 54 | class Target: |
| 55 | """Represents a single line read for a .ninja_log file.""" |
| 56 | |
| 57 | def __init__(self, start, end): |
| 58 | """Creates a target object by passing in the start/end times in seconds |
| 59 | as a float.""" |
| 60 | self.start = start |
| 61 | self.end = end |
| 62 | # A list of targets, appended to by the owner of this object. |
| 63 | self.targets = [] |
| 64 | self.weighted_duration = 0.0 |
| 65 | |
| 66 | def Duration(self): |
| 67 | """Returns the task duration in seconds as a float.""" |
| 68 | return self.end - self.start |
| 69 | |
| 70 | def SetWeightedDuration(self, weighted_duration): |
| 71 | """Sets the duration, in seconds, passed in as a float.""" |
| 72 | self.weighted_duration = weighted_duration |
| 73 | |
| 74 | def WeightedDuration(self): |
| 75 | """Returns the task's weighted duration in seconds as a float. |
| 76 | |
| 77 | Weighted_duration takes the elapsed time of the task and divides it |
| 78 | by how many other tasks were running at the same time. Thus, it |
| 79 | represents the approximate impact of this task on the total build time, |
| 80 | with serialized or serializing steps typically ending up with much |
| 81 | longer weighted durations. |
| 82 | weighted_duration should always be the same or shorter than duration. |
| 83 | """ |
| 84 | # Allow for modest floating-point errors |
| 85 | epsilon = 0.000002 |
| 86 | if self.weighted_duration > self.Duration() + epsilon: |
| 87 | print("{} > {}?".format(self.weighted_duration, self.Duration())) |
| 88 | assert self.weighted_duration <= self.Duration() + epsilon |
| 89 | return self.weighted_duration |
| 90 | |
| 91 | def DescribeTargets(self): |
| 92 | """Returns a printable string that summarizes the targets.""" |
| 93 | # Some build steps generate dozens of outputs - handle them sanely. |
| 94 | # The max_length was chosen so that it can fit most of the long |
| 95 | # single-target names, while minimizing word wrapping. |
| 96 | result = ", ".join(self.targets) |
| 97 | max_length = 65 |
| 98 | if len(result) > max_length: |
| 99 | result = result[:max_length] + "..." |
| 100 | return result |
| 101 | |
| 102 | |
| 103 | # Copied with some modifications from ninjatracing |
| 104 | def ReadTargets(log, show_all): |
| 105 | """Reads all targets from .ninja_log file |log_file|, sorted by duration. |
| 106 | |
| 107 | The result is a list of Target objects.""" |
| 108 | header = log.readline() |
| 109 | assert header == "# ninja log v5\n", "unrecognized ninja log version {!r}".format( |
| 110 | header |
| 111 | ) |
| 112 | targets_dict = {} |
| 113 | last_end_seen = 0.0 |
| 114 | for line in log: |
| 115 | parts = line.strip().split("\t") |
| 116 | if len(parts) != 5: |
| 117 | # If ninja.exe is rudely halted then the .ninja_log file may be |
| 118 | # corrupt. Silently continue. |
| 119 | continue |
| 120 | start, end, _, name, cmdhash = parts # Ignore restart. |
| 121 | # Convert from integral milliseconds to float seconds. |
| 122 | start = int(start) / 1000.0 |
| 123 | end = int(end) / 1000.0 |
| 124 | if not show_all and end < last_end_seen: |
| 125 | # An earlier time stamp means that this step is the first in a new |
| 126 | # build, possibly an incremental build. Throw away the previous |
| 127 | # data so that this new build will be displayed independently. |
| 128 | # This has to be done by comparing end times because records are |
| 129 | # written to the .ninja_log file when commands complete, so end |
| 130 | # times are guaranteed to be in order, but start times are not. |
| 131 | targets_dict = {} |
| 132 | target = None |
| 133 | if cmdhash in targets_dict: |
| 134 | target = targets_dict[cmdhash] |
| 135 | if not show_all and (target.start != start or target.end != end): |
| 136 | # If several builds in a row just run one or two build steps |
| 137 | # then the end times may not go backwards so the last build may |
| 138 | # not be detected as such. However in many cases there will be a |
| 139 | # build step repeated in the two builds and the changed |
| 140 | # start/stop points for that command, identified by the hash, |
| 141 | # can be used to detect and reset the target dictionary. |
| 142 | targets_dict = {} |
| 143 | target = None |
| 144 | if not target: |
| 145 | targets_dict[cmdhash] = target = Target(start, end) |
| 146 | last_end_seen = end |
| 147 | target.targets.append(name) |
| 148 | return list(targets_dict.values()) |
| 149 | |
| 150 | |
| 151 | def GetExtension(target, extra_patterns): |
| 152 | """Return the file extension that best represents a target. |
| 153 | |
| 154 | For targets that generate multiple outputs it is important to return a |
| 155 | consistent 'canonical' extension. Ultimately the goal is to group build steps |
| 156 | by type.""" |
| 157 | for output in target.targets: |
| 158 | if extra_patterns: |
| 159 | for fn_pattern in extra_patterns.split(";"): |
| 160 | if fnmatch.fnmatch(output, "*" + fn_pattern + "*"): |
| 161 | return fn_pattern |
| 162 | # Not a true extension, but a good grouping. |
| 163 | if output.endswith("type_mappings"): |
| 164 | extension = "type_mappings" |
| 165 | break |
| 166 | |
| 167 | # Capture two extensions if present. For example: file.javac.jar should |
| 168 | # be distinguished from file.interface.jar. |
| 169 | root, ext1 = os.path.splitext(output) |
| 170 | _, ext2 = os.path.splitext(root) |
| 171 | extension = ext2 + ext1 # Preserve the order in the file name. |
| 172 | |
| 173 | if len(extension) == 0: |
| 174 | extension = "(no extension found)" |
| 175 | |
| 176 | if ext1 in [".pdb", ".dll", ".exe"]: |
| 177 | extension = "PEFile (linking)" |
| 178 | # Make sure that .dll and .exe are grouped together and that the |
| 179 | # .dll.lib files don't cause these to be listed as libraries |
| 180 | break |
| 181 | if ext1 in [".so", ".TOC"]: |
| 182 | extension = ".so (linking)" |
| 183 | # Attempt to identify linking, avoid identifying as '.TOC' |
| 184 | break |
| 185 | # Make sure .obj files don't get categorized as mojo files |
| 186 | if ext1 in [".obj", ".o"]: |
| 187 | break |
| 188 | # Jars are the canonical output of java targets. |
| 189 | if ext1 == ".jar": |
| 190 | break |
| 191 | # Normalize all mojo related outputs to 'mojo'. |
| 192 | if output.count(".mojom") > 0: |
| 193 | extension = "mojo" |
| 194 | break |
| 195 | return extension |
| 196 | |
| 197 | |
| 198 | def SummarizeEntries(entries, extra_step_types): |
| 199 | """Print a summary of the passed in list of Target objects.""" |
| 200 | # Create a list that is in order by time stamp and has entries for the |
| 201 | # beginning and ending of each build step (one time stamp may have multiple |
| 202 | # entries due to multiple steps starting/stopping at exactly the same time). |
| 203 | # Iterate through this list, keeping track of which tasks are running at all |
| 204 | # times. At each time step calculate a running total for weighted time so |
| 205 | # that when each task ends its own weighted time can easily be calculated. |
| 206 | task_start_stop_times = [] |
| 207 | |
| 208 | earliest = -1 |
| 209 | latest = 0 |
| 210 | total_cpu_time = 0 |
| 211 | for target in entries: |
| 212 | if earliest < 0 or target.start < earliest: |
| 213 | earliest = target.start |
| 214 | if target.end > latest: |
| 215 | latest = target.end |
| 216 | total_cpu_time += target.Duration() |
| 217 | task_start_stop_times.append((target.start, "start", target)) |
| 218 | task_start_stop_times.append((target.end, "stop", target)) |
| 219 | length = latest - earliest |
| 220 | weighted_total = 0.0 |
| 221 | |
| 222 | # Sort by the time/type records and ignore |target| |
| 223 | task_start_stop_times.sort(key=lambda times: times[:2]) |
| 224 | # Now we have all task start/stop times sorted by when they happen. If a |
| 225 | # task starts and stops on the same time stamp then the start will come |
| 226 | # first because of the alphabet, which is important for making this work |
| 227 | # correctly. |
| 228 | # Track the tasks which are currently running. |
| 229 | running_tasks = {} |
| 230 | # Record the time we have processed up to so we know how to calculate time |
| 231 | # deltas. |
| 232 | last_time = task_start_stop_times[0][0] |
| 233 | # Track the accumulated weighted time so that it can efficiently be added |
| 234 | # to individual tasks. |
| 235 | last_weighted_time = 0.0 |
| 236 | # Scan all start/stop events. |
| 237 | for event in task_start_stop_times: |
| 238 | time, action_name, target = event |
| 239 | # Accumulate weighted time up to now. |
| 240 | num_running = len(running_tasks) |
| 241 | if num_running > 0: |
| 242 | # Update the total weighted time up to this moment. |
| 243 | last_weighted_time += (time - last_time) / float(num_running) |
| 244 | if action_name == "start": |
| 245 | # Record the total weighted task time when this task starts. |
| 246 | running_tasks[target] = last_weighted_time |
| 247 | if action_name == "stop": |
| 248 | # Record the change in the total weighted task time while this task |
| 249 | # ran. |
| 250 | weighted_duration = last_weighted_time - running_tasks[target] |
| 251 | target.SetWeightedDuration(weighted_duration) |
| 252 | weighted_total += weighted_duration |
| 253 | del running_tasks[target] |
| 254 | last_time = time |
| 255 | assert len(running_tasks) == 0 |
| 256 | |
| 257 | # Warn if the sum of weighted times is off by more than half a second. |
| 258 | if abs(length - weighted_total) > 500: |
| 259 | print( |
| 260 | "Warning: Possible corrupt ninja log, results may be " |
| 261 | "untrustworthy. Length = {:.3f}, weighted total = {:.3f}".format( |
| 262 | length, weighted_total |
| 263 | ) |
| 264 | ) |
| 265 | |
| 266 | entries_by_ext = defaultdict(list) |
| 267 | for target in entries: |
| 268 | extension = GetExtension(target, extra_step_types) |
| 269 | entries_by_ext[extension].append(target) |
| 270 | |
| 271 | for key, values in entries_by_ext.items(): |
| 272 | print(" Longest build steps for {}:".format(key)) |
| 273 | values.sort(key=lambda x: x.WeightedDuration()) |
| 274 | for target in values[-long_count:]: |
| 275 | print( |
| 276 | " {:8.1f} weighted s to build {} ({:.1f} s elapsed time)".format( |
| 277 | target.WeightedDuration(), |
| 278 | target.DescribeTargets(), |
| 279 | target.Duration(), |
| 280 | ) |
| 281 | ) |
| 282 | |
| 283 | print( |
| 284 | " {:.1f} s weighted time ({:.1f} s elapsed time sum, {:1.1f}x " |
| 285 | "parallelism)".format(length, total_cpu_time, total_cpu_time * 1.0 / length) |
| 286 | ) |
| 287 | print( |
| 288 | " {} build steps completed, average of {:1.2f}/s".format( |
| 289 | len(entries), len(entries) / (length) |
| 290 | ) |
| 291 | ) |
| 292 | |
| 293 | |
| 294 | def main(): |
| 295 | log_file = ".ninja_log" |
| 296 | parser = argparse.ArgumentParser() |
| 297 | parser.add_argument("-C", dest="build_directory", help="Build directory.") |
| 298 | parser.add_argument( |
| 299 | "-s", |
| 300 | "--step-types", |
| 301 | help="semicolon separated fnmatch patterns for build-step grouping", |
| 302 | ) |
| 303 | parser.add_argument("--log-file", help="specific ninja log file to analyze.") |
| 304 | args, _extra_args = parser.parse_known_args() |
| 305 | if args.build_directory: |
| 306 | log_file = os.path.join(args.build_directory, log_file) |
| 307 | if args.log_file: |
| 308 | log_file = args.log_file |
| 309 | if args.step_types: |
| 310 | # Make room for the extra build types. |
| 311 | global long_ext_count |
| 312 | long_ext_count += len(args.step_types.split(";")) |
| 313 | |
| 314 | try: |
| 315 | with open(log_file) as log: |
| 316 | entries = ReadTargets(log, False) |
| 317 | SummarizeEntries(entries, args.step_types) |
| 318 | except OSError: |
| 319 | print("Log file {!r} not found, no build summary created.".format(log_file)) |
| 320 | return errno.ENOENT |
| 321 | |
| 322 | |
| 323 | if __name__ == "__main__": |
| 324 | sys.exit(main()) |