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

Author: shahmishal

utils/build-script-impl

@@ -283,15 +283,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
@@ -304,11 +295,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

@@ -13,6 +13,7 @@
 import os
 import pipes
 import platform
+import time
 
 from build_swift.build_swift import argparse
 from build_swift.build_swift.constants import BUILD_SCRIPT_IMPL_PATH
@@ -33,9 +34,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
 
 
 class BuildScriptInvocation(object):
@@ -52,6 +55,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
@@ -764,10 +769,13 @@ def _execute_merged_host_lipo_core_action(self):
         self._execute_action("merged-hosts-lipo-core")
 
     def _execute_action(self, action_name):
+        log_time('start', action_name)
+        t_start = time.time()
         shell.call_without_sleeping(
             [BUILD_SCRIPT_IMPL_PATH] + self.impl_args +
             ["--only-execute", action_name],
             env=self.impl_env, echo=self.args.verbose_build)
+        log_time('end', action_name, time.time() - t_start)
 
     def execute_product_build_steps(self, product_class, host_target):
         product_source = product_class.product_source_name()
@@ -784,14 +792,26 @@ 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)
+            log_message = "Cleaning %s" % product_name
+            print("--- {} ---".format(log_message))
+            t_start = time.time()
+            log_time('start', log_message)
             product.clean(host_target)
+            log_time('end', log_message, time.time() - t_start)
         if product.should_build(host_target):
-            print("--- Building %s ---" % product_name)
+            log_message = "Building %s" % product_name
+            print("--- {} ---".format(log_message))
+            t_start = time.time()
+            log_time('start', log_message, '0')
             product.build(host_target)
+            log_time('end', log_message, time.time() - t_start)
         if product.should_test(host_target):
-            print("--- Running tests for %s ---" % product_name)
+            log_message = "Running tests for %s" % product_name
+            print("--- {} ---".format(log_message))
+            t_start = time.time()
+            log_time('start', log_message)
             product.test(host_target)
+            log_time('end', log_message, time.time() - t_start)
             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.
@@ -801,5 +821,9 @@ 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)
+            log_message = "Installing %s" % product_name
+            print("--- {} ---".format(log_message))
+            t_start = time.time()
+            log_time('start', log_message)
             product.install(host_target)
+            log_time('end', log_message, time.time() - t_start)

utils/swift_build_support/swift_build_support/utils.py

@@ -12,9 +12,14 @@
 
 from __future__ import absolute_import, print_function, unicode_literals
 
+import json
+import os
 import sys
 
 
+from build_swift.build_swift.constants import SWIFT_BUILD_ROOT
+
+
 def fatal_error(message, stream=sys.stderr):
     """Writes a message to the given stream and exits. By default this
     function outputs to stderr.
@@ -30,3 +35,25 @@ 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():
+    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()