test: add benchmarks and helper functions

parts/linux/cloud-init/artifacts/cse_helpers.sh

@@ -376,4 +376,41 @@ should_skip_nvidia_drivers() {
     should_skip=$(echo "$body" | jq -e '.compute.tagsList | map(select(.name | test("SkipGpuDriverInstall"; "i")))[0].value // "false" | test("true"; "i")')
     echo "$should_skip"
 }
+
+start_watch () {
+  capture_time=$(date +%s)
+  start_timestamp=$(date +%H:%M:%S)
+}
+
+stop_watch () {
+
+  local current_time=$(date +%s)
+  local end_timestamp=$(date +%H:%M:%S)
+  local difference_in_seconds=$((current_time - ${1}))
+
+  local elapsed_hours=$(($difference_in_seconds/3600))
+  local elapsed_minutes=$((($difference_in_seconds%3600)/60))
+  local elapsed_seconds=$(($difference_in_seconds%60))
+
+  printf -v benchmark "'${2}' - Total Time Elapsed: %02d:%02d:%02d" $elapsed_hours $elapsed_minutes $elapsed_seconds
+  if [ ${3} == true ]; then
+    printf -v start "     Start time: $script_start_timestamp"
+  else
+    printf -v start "     Start time: $start_timestamp"
+  fi
+  printf -v end "     End Time: $end_timestamp"
+  echo -e "\n$benchmark\n"
+  benchmarks+=("$benchmark")
+  benchmarks+=("$start")
+  benchmarks+=("$end")
+}
+
+show_benchmarks () {
+  echo -e "\nBenchmarks:\n"
+  for i in "${benchmarks[@]}"; do
+    echo "   $i"
+  done
+  echo
+}
+
 #HELPERSEOF

vhdbuilder/packer/install-dependencies.sh

@@ -1,4 +1,13 @@
 #!/bin/bash
+
+script_start_timestamp=$(date +%H:%M:%S)
+start_timestamp=$(date +%H:%M:%S)
+
+capture_script_start=$(date +%s)
+capture_time=$(date +%s)
+
+declare -a benchmarks=()
+
 OS=$(sort -r /etc/*-release | gawk 'match($0, /^(ID_LIKE=(coreos)|ID=(.*))$/, a) { print toupper(a[2] a[3]); exit }')
 OS_VERSION=$(sort -r /etc/*-release | gawk 'match($0, /^(VERSION_ID=(.*))$/, a) { print toupper(a[2] a[3]); exit }' | tr -d '"')
 UBUNTU_OS_NAME="UBUNTU"
@@ -18,6 +27,8 @@ COMPONENTS_FILEPATH=/opt/azure/components.json
 
 echo ""
 echo "Components downloaded in this VHD build (some of the below components might get deleted during cluster provisioning if they are not needed):" >> ${VHD_LOGS_FILEPATH}
+stop_watch $capture_time "Declare Variables / Configure Environment" false
+start_watch
 
 echo "Logging the kernel after purge and reinstall + reboot: $(uname -r)"
 # fix grub issue with cvm by reinstalling before other deps
@@ -42,6 +53,8 @@ APT::Periodic::AutocleanInterval "0";
 APT::Periodic::Unattended-Upgrade "0";
 EOF
 fi
+stop_watch $capture_time "Purge and Re-install Ubuntu" false
+start_watch
 
 # If the IMG_SKU does not contain "minimal", installDeps normally
 if [[ "$IMG_SKU" != *"minimal"* ]]; then
@@ -70,6 +83,8 @@ SystemMaxUse=1G
 RuntimeMaxUse=1G
 ForwardToSyslog=yes
 EOF
+stop_watch $capture_time "Install Dependencies" false
+start_watch
 
 if [[ ${CONTAINER_RUNTIME:-""} != "containerd" ]]; then
   echo "Unsupported container runtime. Only containerd is supported for new VHD builds."
@@ -96,6 +111,8 @@ if [[ "${UBUNTU_RELEASE}" == "18.04" || "${UBUNTU_RELEASE}" == "20.04" || "${UBU
   overrideNetworkConfig || exit 1
   disableNtpAndTimesyncdInstallChrony || exit 1
 fi
+stop_watch $capture_time "Check Container Runtime / Network Configurations" false
+start_watch
 
 CONTAINERD_SERVICE_DIR="/etc/systemd/system/containerd.service.d"
 mkdir -p "${CONTAINERD_SERVICE_DIR}"
@@ -151,6 +168,8 @@ containerd_version="$(echo "$installed_version" | cut -d- -f1)"
 containerd_patch_version="$(echo "$installed_version" | cut -d- -f2)"
 installStandaloneContainerd ${containerd_version} ${containerd_patch_version}
 echo "  - [installed] containerd v${containerd_version}-${containerd_patch_version}" >> ${VHD_LOGS_FILEPATH}
+stop_watch $capture_time "Create Containerd Service Directory, Download Shims, Configure Runtime and Network" false
+start_watch
 
 DOWNLOAD_FILES=$(jq ".DownloadFiles" $COMPONENTS_FILEPATH | jq .[] --monochrome-output --compact-output)
 for componentToDownload in ${DOWNLOAD_FILES[*]}; do
@@ -171,6 +190,8 @@ for CRICTL_VERSION in ${CRICTL_VERSIONS}; do
   downloadCrictl ${CRICTL_VERSION}
   echo "  - crictl version ${CRICTL_VERSION}" >> ${VHD_LOGS_FILEPATH}
 done
+stop_watch $capture_time "Download Components, Determine / Download crictl Version" false
+start_watch
 
 installAndConfigureArtifactStreaming() {
   # arguments: package name, package extension
@@ -208,6 +229,8 @@ downloadTeleportdPlugin ${TELEPORTD_PLUGIN_DOWNLOAD_URL} "0.8.0"
 
 INSTALLED_RUNC_VERSION=$(runc --version | head -n1 | sed 's/runc version //')
 echo "  - runc version ${INSTALLED_RUNC_VERSION}" >> ${VHD_LOGS_FILEPATH}
+stop_watch $capture_time "Artifact Streaming, Download Containerd Plugins" false
+start_watch
 
 if [[ $OS == $UBUNTU_OS_NAME && $(isARM64) != 1 ]]; then  # no ARM64 SKU with GPU now
   gpu_action="copy"
@@ -242,8 +265,8 @@ cat << EOF >> ${VHD_LOGS_FILEPATH}
 EOF
 
 echo "${CONTAINER_RUNTIME} images pre-pulled:" >> ${VHD_LOGS_FILEPATH}
-
-
+stop_watch $capture_time "Pull NVIDIA Image, Start installBcc subshell" false
+start_watch
 
 string_replace() {
   echo ${1//\*/$2}
@@ -290,6 +313,8 @@ watcherStaticImg=${watcherBaseImg//\*/static}
 
 # can't use cliTool because crictl doesn't support retagging.
 retagContainerImage "ctr" ${watcherFullImg} ${watcherStaticImg}
+stop_watch $capture_time "Pull and Re-tag Container Images" false
+start_watch
 
 # doing this at vhd allows CSE to be faster with just mv
 unpackAzureCNI() {
@@ -351,6 +376,8 @@ done
 if [[ $OS == $UBUNTU_OS_NAME || ( $OS == $MARINER_OS_NAME && $OS_VERSION == "2.0" ) ]]; then
   systemctlEnableAndStart ipv6_nftables || exit 1
 fi
+stop_watch $capture_time "Configure Networking and Interface" false
+start_watch
 
 if [[ $OS == $UBUNTU_OS_NAME && $(isARM64) != 1 ]]; then  # no ARM64 SKU with GPU now
 NVIDIA_DEVICE_PLUGIN_VERSIONS="
@@ -378,6 +405,8 @@ if grep -q "fullgpu" <<< "$FEATURE_FLAGS" && grep -q "gpudaemon" <<< "$FEATURE_F
   systemctlEnableAndStart nvidia-device-plugin || exit 1
 fi
 fi
+stop_watch $capture_time "GPU Device plugin" false
+start_watch
 
 mkdir -p /var/log/azure/Microsoft.Azure.Extensions.CustomScript/events
 
@@ -412,6 +441,8 @@ for KUBE_PROXY_IMAGE_VERSION in ${KUBE_PROXY_IMAGE_VERSIONS}; do
   # shellcheck disable=SC2181
   echo "  - ${CONTAINER_IMAGE}" >>${VHD_LOGS_FILEPATH}
 done
+stop_watch $capture_time "Configure Telemetry, Create Logging Directory, Kube-proxy" false
+start_watch
 
 # download kubernetes package from the given URL using MSI for auth for azcopy
 # if it is a kube-proxy package, extract image from the downloaded package
@@ -476,5 +507,8 @@ for PATCHED_KUBE_BINARY_VERSION in ${KUBE_BINARY_VERSIONS}; do
 done
 
 rm -f ./azcopy # cleanup immediately after usage will return in two downloads
+stop_watch $capture_time "Download and Process Kubernetes Packages / Extract Binaries" false
 
 echo "install-dependencies step completed successfully"
+stop_watch $capture_script_start "install-dependencies.sh" true
+show_benchmarks

vhdbuilder/packer/post-install-dependencies.sh

@@ -1,4 +1,13 @@
 #!/bin/bash
+
+script_start_timestamp=$(date +%H:%M:%S)
+start_timestamp=$(date +%H:%M:%S)
+
+capture_script_start=$(date +%s)
+capture_time=$(date +%s)
+
+declare -a benchmarks=()
+
 OS=$(sort -r /etc/*-release | gawk 'match($0, /^(ID_LIKE=(coreos)|ID=(.*))$/, a) { print toupper(a[2] a[3]); exit }')
 UBUNTU_OS_NAME="UBUNTU"
 
@@ -8,12 +17,16 @@ source /home/packer/provision_source.sh
 source /home/packer/provision_source_distro.sh
 source /home/packer/tool_installs.sh
 source /home/packer/tool_installs_distro.sh
+stop_watch $capture_time "Determine OS / Set Comparison / Execute home/packer files" false
+start_watch
 
 CPU_ARCH=$(getCPUArch)  #amd64 or arm64
 VHD_LOGS_FILEPATH=/opt/azure/vhd-install.complete
 
 # Hardcode the desired size of the OS disk so we don't accidently rely on extra disk space
 MAX_BLOCK_COUNT=30298176 # 30 GB
+stop_watch $capture_time "Set Variables" false
+start_watch
 
 if [[ $OS == $UBUNTU_OS_NAME ]]; then
   # shellcheck disable=SC2021
@@ -36,6 +49,8 @@ if [[ $OS == $UBUNTU_OS_NAME ]]; then
   ua status
   detachAndCleanUpUA
 fi
+stop_watch $capture_time "Log / Detach UA and Clean-up" false
+start_watch
 
 # shellcheck disable=SC2129
 echo "kubelet/kubectl downloaded:" >> ${VHD_LOGS_FILEPATH}
@@ -45,6 +60,8 @@ ls -ltr /usr/local/bin/* >> ${VHD_LOGS_FILEPATH}
 ls -ltr /dev/* | grep sgx >>  ${VHD_LOGS_FILEPATH} 
 
 echo -e "=== Installed Packages Begin\n$(listInstalledPackages)\n=== Installed Packages End" >> ${VHD_LOGS_FILEPATH}
+stop_watch $capture_time "List Installed Packages" false
+start_watch
 
 echo "Disk usage:" >> ${VHD_LOGS_FILEPATH}
 df -h >> ${VHD_LOGS_FILEPATH}
@@ -56,6 +73,8 @@ usage=$(awk -v used=${used_blocks} -v capacity=${MAX_BLOCK_COUNT} 'BEGIN{print (
 usage=${usage%.*}
 [ ${usage} -ge 99 ] && echo "ERROR: root partition on OS device (${os_device}) already passed 99% of the 30GB cap!" && exit 1
 [ ${usage} -ge 75 ] && echo "WARNING: root partition on OS device (${os_device}) already passed 75% of the 30GB cap!"
+stop_watch $capture_time "Determine Disk Usage" false
+start_watch
 
 echo -e "=== os-release Begin" >> ${VHD_LOGS_FILEPATH}
 cat /etc/os-release >> ${VHD_LOGS_FILEPATH}
@@ -74,16 +93,23 @@ tee -a ${VHD_LOGS_FILEPATH} < /proc/version
   echo "Container runtime: ${CONTAINER_RUNTIME}"
   echo "FIPS enabled: ${ENABLE_FIPS}"
 } >> ${VHD_LOGS_FILEPATH}
+stop_watch $capture_time "Write Logs" false
+start_watch
 
 if [[ $(isARM64) != 1 ]]; then
   # no asc-baseline-1.1.0-268.arm64.deb
   installAscBaseline
 fi
+stop_watch $capture_time "Instal Asc Baseline" false
+start_watch
 
 if [[ ${UBUNTU_RELEASE} == "18.04" || ${UBUNTU_RELEASE} == "20.04" || ${UBUNTU_RELEASE} == "22.04" ]]; then
   if [[ ${ENABLE_FIPS,,} == "true" || ${CPU_ARCH} == "arm64" ]]; then
     relinkResolvConf
   fi
 fi
+stop_watch $capture_time "RelinkResolveConf" false
 
-echo "post-install-dependencies step completed successfully"
+echo "post-install-dependencies step completed successfully"
+stop_watch $capture_script_start "post-install-dependencies.sh" true
+show_benchmarks

vhdbuilder/packer/pre-install-dependencies.sh

@@ -1,4 +1,13 @@
 #!/bin/bash
+
+script_start_timestamp=$(date +%H:%M:%S)
+start_timestamp=$(date +%H:%M:%S)
+
+capture_script_start=$(date +%s)
+capture_time=$(date +%s)
+
+declare -a benchmarks=()
+
 OS=$(sort -r /etc/*-release | gawk 'match($0, /^(ID_LIKE=(coreos)|ID=(.*))$/, a) { print toupper(a[2] a[3]); exit }')
 OS_VERSION=$(sort -r /etc/*-release | gawk 'match($0, /^(VERSION_ID=(.*))$/, a) { print toupper(a[2] a[3]); exit }' | tr -d '"')
 THIS_DIR="$(cd "$(dirname ${BASH_SOURCE[0]})" && pwd)"
@@ -14,6 +23,8 @@ source /home/packer/provision_source_distro.sh
 source /home/packer/tool_installs.sh
 source /home/packer/tool_installs_distro.sh
 source /home/packer/packer_source.sh
+stop_watch $capture_time "Declare Variables / Remove Comments / Execute home/packer files" false
+start_watch
 
 CPU_ARCH=$(getCPUArch)  #amd64 or arm64
 VHD_LOGS_FILEPATH=/opt/azure/vhd-install.complete
@@ -25,32 +36,46 @@ cat components.json > ${COMPONENTS_FILEPATH}
 cat manifest.json > ${MANIFEST_FILEPATH}
 cat ${THIS_DIR}/kube-proxy-images.json > ${KUBE_PROXY_IMAGES_FILEPATH}
 echo "Starting build on " $(date) > ${VHD_LOGS_FILEPATH}
+stop_watch $capture_time "Create Post-build Test" false
+start_watch
 
 if [[ $OS == $MARINER_OS_NAME ]]; then
   chmod 755 /opt
   chmod 755 /opt/azure
   chmod 644 ${VHD_LOGS_FILEPATH}
 fi
+stop_watch $capture_time "Set Permissions if Mariner" false
+start_watch
 
 copyPackerFiles
 systemctlEnableAndStart disk_queue || exit 1
+stop_watch $capture_time "Copy Packer Files" false
+start_watch
 
 mkdir /opt/certs
 chmod 1666 /opt/certs
 systemctlEnableAndStart update_certs.path || exit 1
+stop_watch $capture_time "Make Certs Directory / Set Permissions / Update Certs" false
+start_watch
 
 systemctlEnableAndStart ci-syslog-watcher.path || exit 1
 systemctlEnableAndStart ci-syslog-watcher.service || exit 1
 
 # enable AKS log collector
 echo -e "\n# Disable WALA log collection because AKS Log Collector is installed.\nLogs.Collect=n" >> /etc/waagent.conf || exit 1
 systemctlEnableAndStart aks-log-collector.timer || exit 1
+stop_watch $capture_time "Start System Logs / AKS Log Collector" false
+start_watch
 
 # enable the modified logrotate service and remove the auto-generated default logrotate cron job if present
 systemctlEnableAndStart logrotate.timer || exit 1
 rm -f /etc/cron.daily/logrotate
+stop_watch $capture_time "Start Modified Log-rotate Service / Remove Auto-generated Service" false
+start_watch
 
 systemctlEnableAndStart sync-container-logs.service || exit 1
+stop_watch $capture_time "Sync Container Logs" false
+start_watch
 
 # First handle Mariner + FIPS
 if [[ ${OS} == ${MARINER_OS_NAME} ]]; then
@@ -85,6 +110,8 @@ else
     installFIPS
   fi
 fi
+stop_watch $capture_time "Handle Mariner / FIPS Configurations" false
+start_watch
 
 # Handle Azure Linux + CgroupV2
 if [[ ${OS} == ${MARINER_OS_NAME} ]] && [[ "${ENABLE_CGROUPV2,,}" == "true" ]]; then
@@ -105,5 +132,8 @@ if [[ "${UBUNTU_RELEASE}" == "22.04" ]]; then
 
   update-grub
 fi
+stop_watch $capture_time "Handle Azure Linux / CgroupV2" false
 
-echo "pre-install-dependencies step finished successfully"
+echo "pre-install-dependencies step finished successfully"
+stop_watch $capture_script_start "pre-install-dependencies.sh" true
+show_benchmarks