build: add option for build profiling with clang -ftime-trace (#4475)

Document the process, too.

Signed-off-by: Larry Gritz <lg@larrygritz.com>

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.

docs/dev/Build_Profiling.md

@@ -0,0 +1,51 @@
+<!-- SPDX-License-Identifier: CC-BY-4.0 -->
+<!-- Copyright Contributors to the OpenImageIO Project. -->
+
+# 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.

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:]))

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
 #