Merge pull request #41223 from apple/log-build-time

[Build System] Add support to log build times for each products

Author: shahmishal

utils/build-script

@@ -40,6 +40,7 @@ from swift_build_support.swift_build_support.toolchain import host_toolchain
 from swift_build_support.swift_build_support.utils \
     import exit_rejecting_arguments
 from swift_build_support.swift_build_support.utils import fatal_error
+from swift_build_support.swift_build_support.utils import log_analyzer
 
 
 # -----------------------------------------------------------------------------
@@ -716,6 +717,9 @@ def main():
 
 if __name__ == "__main__":
     try:
-        sys.exit(main())
+        exit_code = main()
     except KeyboardInterrupt:
         sys.exit(1)
+    finally:
+        log_analyzer()
+    sys.exit(exit_code)

utils/build-script-impl

@@ -293,15 +293,6 @@ for component in ${components[@]} ; do
   )
 done
 
-function log_event() {
-    build_script_log_path=${BUILD_DIR}/.build_script_log
-    event_type=$1
-    event_command=$2
-    evnet_duration=$3
-
-    build_event="{\"event\":\"${event_type}\", \"command\":\"${event_command}\", \"duration\":\"${evnet_duration}\"}"
-    echo "${build_event}" >> ${build_script_log_path}
-}
 
 # Centralized access point for traced command invocation.
 # Every operation that might mutates file system should be called via
@@ -314,11 +305,9 @@ function call() {
 
     SECONDS=0
     if [[ ! ${DRY_RUN} ]]; then
-        log_event "start" "$(quoted_print "$@")" "${SECONDS}"
         { set -x; } 2>/dev/null
         "$@"
         { set +x; } 2>/dev/null
-        log_event "finish" "$(quoted_print "$@")" "${SECONDS}"
     fi
 }
 

utils/swift_build_support/swift_build_support/build_script_invocation.py

@@ -31,9 +31,11 @@
     import ProductPipelineListBuilder
 from swift_build_support.swift_build_support.targets \
     import StdlibDeploymentTarget
+from swift_build_support.swift_build_support.utils import clear_log_time
 from swift_build_support.swift_build_support.utils \
     import exit_rejecting_arguments
 from swift_build_support.swift_build_support.utils import fatal_error
+from swift_build_support.swift_build_support.utils import log_time_in_scope
 
 
 class BuildScriptInvocation(object):
@@ -50,6 +52,8 @@ def __init__(self, toolchain, args):
 
         self.build_libparser_only = args.build_libparser_only
 
+        clear_log_time()
+
     @property
     def install_all(self):
         return self.args.install_all or self.args.infer_dependencies
@@ -790,10 +794,11 @@ def _execute_merged_host_lipo_core_action(self):
         self._execute_action("merged-hosts-lipo-core")
 
     def _execute_action(self, action_name):
-        shell.call_without_sleeping(
-            [BUILD_SCRIPT_IMPL_PATH] + self.impl_args +
-            ["--only-execute", action_name],
-            env=self.impl_env, echo=self.args.verbose_build)
+        with log_time_in_scope(action_name):
+            shell.call_without_sleeping(
+                [BUILD_SCRIPT_IMPL_PATH] + self.impl_args +
+                ["--only-execute", action_name],
+                env=self.impl_env, echo=self.args.verbose_build)
 
     def execute_product_build_steps(self, product_class, host_target):
         product_source = product_class.product_source_name()
@@ -810,14 +815,20 @@ def execute_product_build_steps(self, product_class, host_target):
             source_dir=self.workspace.source_dir(product_source),
             build_dir=build_dir)
         if product.should_clean(host_target):
-            print("--- Cleaning %s ---" % product_name)
-            product.clean(host_target)
+            log_message = "Cleaning %s" % product_name
+            print("--- {} ---".format(log_message))
+            with log_time_in_scope(log_message):
+                product.clean(host_target)
         if product.should_build(host_target):
-            print("--- Building %s ---" % product_name)
-            product.build(host_target)
+            log_message = "Building %s" % product_name
+            print("--- {} ---".format(log_message))
+            with log_time_in_scope(log_message):
+                product.build(host_target)
         if product.should_test(host_target):
-            print("--- Running tests for %s ---" % product_name)
-            product.test(host_target)
+            log_message = "Running tests for %s" % product_name
+            print("--- {} ---".format(log_message))
+            with log_time_in_scope(log_message):
+                product.test(host_target)
             print("--- Finished tests for %s ---" % product_name)
         # Install the product if it should be installed specifically, or
         # if it should be built and `install_all` is set to True.
@@ -827,5 +838,7 @@ def execute_product_build_steps(self, product_class, host_target):
         if product.should_install(host_target) or \
            (self.install_all and product.should_build(host_target) and
            not product.is_ignore_install_all_product()):
-            print("--- Installing %s ---" % product_name)
-            product.install(host_target)
+            log_message = "Installing %s" % product_name
+            print("--- {} ---".format(log_message))
+            with log_time_in_scope(log_message):
+                product.install(host_target)

utils/swift_build_support/swift_build_support/utils.py

@@ -10,7 +10,14 @@
 #
 # ===---------------------------------------------------------------------===#
 
+import contextlib
+import json
+import os
 import sys
+import time
+
+
+from build_swift.build_swift.constants import SWIFT_BUILD_ROOT
 
 
 def fatal_error(message, stream=sys.stderr):
@@ -28,3 +35,70 @@ def exit_rejecting_arguments(message, parser=None):
     if parser:
         parser.print_usage(sys.stderr)
     sys.exit(2)  # 2 is the same as `argparse` error exit code.
+
+
+def log_time_path():
+    return os.path.join(SWIFT_BUILD_ROOT, '.build_script_log')
+
+
+def clear_log_time():
+    if os.path.exists(log_time_path()):
+        f = open(log_time_path(), "w")
+        f.close()
+
+
+def log_time(event, command, duration=0):
+    f = open(log_time_path(), "a")
+
+    log_event = {
+        "event": event,
+        "command": command,
+        "duration": "%.2f" % float(duration),
+    }
+
+    f.write("{}\n".format(json.dumps(log_event)))
+    f.close()
+
+
+@contextlib.contextmanager
+def log_time_in_scope(action_name):
+    log_time('start', action_name)
+    t_start = time.time()
+    try:
+        yield
+    finally:
+        log_time('end', action_name, time.time() - t_start)
+
+
+def log_analyzer():
+    """
+    Analyze .build_script_log and provide a summary of the time execution.
+    """
+    build_script_log_path = log_time_path()
+    print("--- Build Script Analyzer ---")
+    build_events = []
+    total_duration = 0
+    if os.path.exists(build_script_log_path):
+        print("Build Script Log: {}".format(build_script_log_path))
+        with open(build_script_log_path) as f:
+            for event in f:
+                build_event = json.loads(event)
+                build_event["duration"] = float(build_event["duration"])
+                total_duration += build_event["duration"]
+                build_events.append(build_event)
+        finish_events = [x for x in build_events if x["event"] == "end"]
+        finish_events.sort(key=lambda x: x["duration"], reverse=True)
+
+        print("Build Percentage \t Build Duration (sec) \t Build Phase")
+        print("================ \t ==================== \t ===========")
+        event_row = '{:<17.1%} \t {:<21} \t {}'
+        for build_event in finish_events:
+            duration_percentage = \
+                (float(build_event["duration"]) / float(total_duration))
+            print(event_row.format(duration_percentage,
+                                   build_event["duration"],
+                                   build_event["command"]))
+        print("Total Duration: {}".format(total_duration))
+    else:
+        print("Skip build script analyzer")
+        print(".build_script_log file not found at {}".format(build_script_log_path))