test(instrumentation): add build step duration tracking

images/instrumentation/test/build_time_profiling

@@ -0,0 +1,45 @@
+declare -A all_build_step_times
+
+print_time() {
+  local t="$1"
+  printf '%02dh:%02dm:%02ds\n' $((t/3600)) $((t%3600/60)) $((t%60))
+}
+
+store_build_step_duration() {
+  local step_label=$1
+  local start=$2
+  local end=$(date +%s)
+  local duration=$(($end-$start))
+  all_build_step_times["$step_label"]="$duration"
+}
+
+print_build_step_duration() {
+  local step_label=$1
+  local start=$2
+  local end=$(date +%s)
+  local duration=$(($end-$start))
+  printf "[build time] $step_label:"'\t'"$(print_time "$duration")"'\n'
+}
+
+print_total_build_time_info() {
+  local total_build_end=$(date +%s)
+  local total_build_duration=$(($total_build_end-$start_time_build))
+  local accounted_for_total=0
+  echo
+  echo "**build step durations**"
+  for label in "${!all_build_step_times[@]}"; do
+    local d="${all_build_step_times[$label]}"
+    printf "[build time] $label:"'\t'"$(print_time "$d")"'\n'
+    accounted_for_total=$(($accounted_for_total+$d))
+  done
+
+  echo ----------------------------------------
+  echo "**summary**"
+  print_build_step_duration "**total build time**" "$start_time_build"
+
+  # check that we are actually measuring all relevant build steps:
+  local unaccounted=$(($total_build_duration-$accounted_for_total))
+  printf "[build time] build time account for by individual build steps:"'\t'"$(print_time "$accounted_for_total")"'\n'
+  printf "[build time] build time unaccounted for by individual build steps:"'\t'"$(print_time "$unaccounted")"'\n'
+}
+

images/instrumentation/test/test-all.sh

@@ -7,12 +7,19 @@
 set -euo pipefail
 shopt -s lastpipe
 
+start_time_build=$(date +%s)
+
 RED='\033[0;31m'
 GREEN='\033[0;32m'
 NC='\033[0m'
 
 cd "$(dirname "${BASH_SOURCE[0]}")"/..
 
+# shellcheck source=images/instrumentation/test/build_time_profiling
+source ./test/build_time_profiling
+
+trap print_total_build_time_info EXIT
+
 # shellcheck source=images/instrumentation/injector/test/scripts/util
 source injector/test/scripts/util
 
@@ -23,6 +30,8 @@ exit_code=0
 summary=""
 
 build_or_pull_instrumentation_image() {
+  # shellcheck disable=SC2155
+  local start_time_step=$(date +%s)
   if [[ -n "${INSTRUMENTATION_IMAGE:-}" ]]; then
     instrumentation_image="$INSTRUMENTATION_IMAGE"
 
@@ -36,6 +45,7 @@ build_or_pull_instrumentation_image() {
       echo "using existing local instrumentation image: $instrumentation_image"
       echo ----------------------------------------
     fi
+    store_build_step_duration "pull instrumentation image" "$start_time_step"
   else
     echo ----------------------------------------
     echo "building multi-arch instrumentation image for platforms ${all_docker_platforms} from local sources"
@@ -51,6 +61,8 @@ build_or_pull_instrumentation_image() {
       echo "${build_output}"
       exit 1
     fi
+
+    store_build_step_duration "build instrumentation image" "$start_time_step"
   fi
   echo
 }
@@ -70,6 +82,8 @@ run_tests_for_runtime() {
   fi
 
   for t in "${script_dir}"/"${runtime}"/test-cases/*/ ; do
+    # shellcheck disable=SC2155
+    local start_time_test_case=$(date +%s)
     test=$(basename "$(realpath "${t}")")
 
     case "$runtime" in
@@ -102,6 +116,7 @@ run_tests_for_runtime() {
       exit_code=1
       summary="$summary\n${runtime}/${base_image}\t- ${test}:\tfailed"
     fi
+    store_build_step_duration "test case $image_name_test/$runtime/$test" "$start_time_test_case"
   done
 }
 
@@ -132,6 +147,8 @@ run_tests_for_architecture() {
       echo "- base image: '${base_image}'"
       image_name_test="test-${runtime}-${arch}:latest"
       echo "building test image for ${arch}/${runtime}/${base_image} with instrumentation image ${instrumentation_image}"
+      # shellcheck disable=SC2155
+      local start_time_docker_build=$(date +%s)
       if ! build_output=$(
         docker build \
           --platform "$docker_platform" \
@@ -144,6 +161,7 @@ run_tests_for_architecture() {
         echo "${build_output}"
         exit 1
       fi
+      store_build_step_duration "docker build $arch/$runtime/$base_image" "$start_time_docker_build"
       run_tests_for_runtime "${runtime}" "$image_name_test" "$base_image"
       echo
     done