diff --git a/THIRD-PARTY.md b/THIRD-PARTY.md index 96e2a1523a..8a8afcd046 100644 --- a/THIRD-PARTY.md +++ b/THIRD-PARTY.md @@ -179,6 +179,9 @@ SPDX-License-Identifier: Apache-2.0 This is licensed under the Apache 2.0 license with LLVM Exceptions. https://llvm.org/docs/DeveloperPolicy.html#open-source-licensing-terms +* ninjatracing.py utility for build profiling is Apache-2.0 licensed + and comes from https://github.com/nico/ninjatracing. + Copyright 2018 Nico Weber. Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. diff --git a/docs/dev/Build_Profiling.md b/docs/dev/Build_Profiling.md new file mode 100644 index 0000000000..ef4c96e0b1 --- /dev/null +++ b/docs/dev/Build_Profiling.md @@ -0,0 +1,51 @@ + + + +# Build profiling + +These are instructions for profiling the build process of OpenImageIO -- +useful for figuring out where the build process is spending its time, and +where it might be optimized. + +## Profiling module compilating with clang -ftime-trace + +These instructions are based on the following references: + +- general instructions: https://www.superfunc.zone/posts/001-speeding-up-c-builds/ +- ninjatracing.py script: https://github.com/nico/ninjatracing +- Background info: https://aras-p.info/blog/2019/01/16/time-trace-timeline-flame-chart-profiler-for-Clang/ + +The steps are as follows, and they require the use of clang, ninja, and +the chrome browser: + +1. Build with clang using the `-ftime-trace`, flag which is set when you use + the OIIO build option -DOIIO_BUILD_PROFILE=1. You MUST use clang, as this + is a clang-specific feature, and you must use the ninja builder (use CMake + arguments `-G ninja`). This must be a *fresh* build, not an incremental + build (or the results will only reflect the incrementally build parts). + + This will result in a file, build/.ninja_log, containing timings from + the build process. + +2. Prepare the output using the `ninjatracing.py` script as follows: + + ``` + python3 src/build-scripts/ninjatracing.py -a build/.ninja_log > top_level.json + ``` + +3. Running the Chrome browser, visit the URL `chrome://tracing`, and LOAD that + json file created in the previous step. This will display a timeline of the + build process, showing which thread, in what order, and how long each + module took to compile. + +4. For even more detail on what's happening within the compilation of each + module, you can use the `-e` flag to expand the output: + + ``` + python3 src/build-scripts/ninjatracing.py -a -e -g 50000 build/.ninja_log > expanded.json + ``` + + Loading this in Chrome's tracing view, as above, will show a full flame + chart of the build process, showing the time spent in the different + functional parts of the compiler and which functions of OIIO it is + compiling or which templates are being instantiated. diff --git a/src/build-scripts/ninjatracing.py b/src/build-scripts/ninjatracing.py new file mode 100644 index 0000000000..60e60161ac --- /dev/null +++ b/src/build-scripts/ninjatracing.py @@ -0,0 +1,190 @@ +#!/usr/bin/env python3 +# Copyright 2018 Nico Weber +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# 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. + +If clang -ftime-trace .json files are found adjacent to generated files they +are embedded. + +Usage: + ninja -C $BUILDDIR + ninjatracing $BUILDDIR/.ninja_log > trace.json +""" + +import json +import os +import optparse +import re +import sys + + +class Target: + """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) + self.targets = [] + + +def read_targets(log, show_all): + """Reads all targets from .ninja_log file |log_file|, sorted by start + time""" + header = log.readline() + m = re.search(r'^# ninja log v(\d+)\n$', header) + assert m, "unrecognized ninja log version %r" % header + version = int(m.group(1)) + assert 5 <= version <= 6, "unsupported ninja log version %d" % version + if version == 6: + # Skip header line + next(log) + + targets = {} + last_end_seen = 0 + for line in log: + if line.startswith('#'): + continue + start, end, _, name, cmdhash = line.strip().split('\t') # Ignore restat. + if not show_all and int(end) < last_end_seen: + # An earlier time stamp means that this step is the first in a new + # build, possibly an incremental build. Throw away the previous data + # so that this new build will be displayed independently. + targets = {} + last_end_seen = int(end) + targets.setdefault(cmdhash, Target(start, end)).targets.append(name) + return sorted(targets.values(), key=lambda job: job.end, reverse=True) + + +class Threads: + """Tries to reconstruct the parallelism from a .ninja_log""" + def __init__(self): + self.workers = [] # Maps thread id to time that thread is occupied for. + + def alloc(self, target): + """Places target in an available thread, or adds a new thread.""" + for worker in range(len(self.workers)): + if self.workers[worker] >= target.end: + self.workers[worker] = target.start + return worker + self.workers.append(target.start) + return len(self.workers) - 1 + + +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.""" + ninja_time = (target.end - target.start) * 1000 + for event in read_events(trace, options): + # Check if any event duration is greater than the duration from ninja. + 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, 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': 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): + usage = __doc__ + parser = optparse.OptionParser(usage) + parser.add_option('-a', '--showall', action='store_true', dest='showall', + default=False, + 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: + print('Must specify at least one .ninja_log file') + parser.print_help() + return 1 + + entries = [] + for pid, log_file in enumerate(args): + with open(log_file, 'r') as log: + entries += list(log_to_dicts(log, pid, vars(options))) + json.dump(entries, sys.stdout) + + +if __name__ == '__main__': + sys.exit(main(sys.argv[1:])) diff --git a/src/cmake/compiler.cmake b/src/cmake/compiler.cmake index ddd6f99034..b3a602ddc8 100644 --- a/src/cmake/compiler.cmake +++ b/src/cmake/compiler.cmake @@ -421,7 +421,7 @@ endif () ########################################################################### -# Profiling +# Runtime profiling # set_cache (PROFILER "" "Build executables with profiler support (choices: gperftools)") if (PROFILER STREQUAL "gperftools") @@ -430,6 +430,16 @@ if (PROFILER STREQUAL "gperftools") endif () +########################################################################### +# Build profiling +# +set_option (${PROJ_NAME}_BUILD_PROFILER "Profile the build process" OFF) +if (${PROJ_NAME}_BUILD_PROFILER AND CMAKE_COMPILER_IS_CLANG) + add_compile_options (-ftime-trace) + message (STATUS "Profiling the build process") +endif () + + ########################################################################### # Sanitizer options #