Log build-script calls to .build_script_log file to help understand the build

times for each command.

Author: shahmishal

utils/build-script

@@ -1351,6 +1351,11 @@ def main_normal():
     # Create build directory.
     shell.makedirs(invocation.workspace.build_root)
 
+    # Create .build_script_log.
+    build_script_log = os.path.join(invocation.workspace.build_root,
+                                    ".build_script_log")
+    open(build_script_log, 'w').close()
+
     # Build ninja if required, which will update the toolchain.
     if args.build_ninja:
         invocation.build_ninja()

utils/build-script-impl

@@ -257,6 +257,16 @@ 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
 # these functions.
@@ -265,10 +275,14 @@ function call() {
     if [[ ${DRY_RUN} ]] || [[ "${VERBOSE_BUILD}" ]]; then
         echo "${PS4}"$(quoted_print "$@")
     fi
+
+    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
 }