Add log timings for perf debugging.

install_and_cache_pkgs.sh

@@ -17,22 +17,22 @@ input_packages="${@:2}"
 normalized_packages="$(normalize_package_list "${input_packages}")"
 
 package_count=$(wc -w <<< "${normalized_packages}")
-echo "Clean installing and caching ${package_count} package(s)."
-echo "Package list:"
+log "Clean installing and caching ${package_count} package(s)."
+log "Package list:"
 for package in ${normalized_packages}; do
-  echo "- ${package}"
+  log "- ${package}"
 done
 
-echo -n "Updating APT package list..."
+log -n "Updating APT package list..."
 sudo apt-get update > /dev/null
-echo "done."
+"done."
 
 # Strictly contains the requested packages.
 manifest_main=""
 # Contains all packages including dependencies.
 manifest_all=""
 
-echo "Clean installing and caching ${package_count} packages..."
+log "Clean installing and caching ${package_count} packages..."
 for package in ${normalized_packages}; do
   read package_name package_ver < <(get_package_name_ver "${package}")  
 
@@ -42,10 +42,10 @@ for package in ${normalized_packages}; do
   all_packages="$(apt-get install --dry-run --yes "${package_name}" | grep "^Inst" | awk '{print $2}')"
   dep_packages="$(echo ${dep_packages} | grep -v "${package_name}" | tr '\n' ,)"
 
-  echo "- ${package_name}"
-  echo "  * Version: ${package_ver}"
-  echo "  * Dependencies: ${dep_packages:0:-1}"
-  echo -n "  * Installing..."
+  log "- ${package_name}"
+  log "  * Version: ${package_ver}"
+  log "  * Dependencies: ${dep_packages:0:-1}"
+  log -n "  * Installing..."
   # Zero interaction while installing or upgrading the system via apt.
   sudo DEBIAN_FRONTEND=noninteractive apt-get --yes install "${package}" > /dev/null
   echo "done."
@@ -55,7 +55,7 @@ for package in ${normalized_packages}; do
 
     if test ! -f "${cache_filepath}"; then
       read cache_package_name cache_package_ver < <(get_package_name_ver "${cache_package}")
-      echo -n "  * Caching ${cache_package_name} to ${cache_filepath}..."
+      log -n "  * Caching ${cache_package_name} to ${cache_filepath}..."
       # Pipe all package files (no folders) to Tar.
       dpkg -L "${cache_package_name}" |
         while IFS= read -r f; do     
@@ -69,16 +69,16 @@ for package in ${normalized_packages}; do
     manifest_all="${manifest_all}${cache_package_name}:${cache_package_ver},"
   done  
 done
-echo "done."
+log "done."
 
 manifest_all_filepath="${cache_dir}/manifest_all.log"
-echo -n "Writing all packages manifest to ${manifest_all_filepath}..."
+log -n "Writing all packages manifest to ${manifest_all_filepath}..."
 # Remove trailing comma and write to manifest_all file.
 echo "${manifest_all:0:-1}" > "${manifest_all_filepath}"
 echo "done."
 
 manifest_main_filepath="${cache_dir}/manifest_main.log"
-echo -n "Writing main requested packages manifest to ${manifest_main_filepath}..."
+log -n "Writing main requested packages manifest to ${manifest_main_filepath}..."
 # Remove trailing comma and write to manifest_main file.
 echo "${manifest_main:0:-1}" > "${manifest_main_filepath}"
 echo "done."

lib.sh

@@ -17,3 +17,13 @@ function get_package_name_ver {
   fi
   echo "${name}" "${ver}"
 }
+
+function log {
+  timestamp="$(echo -n "$(date +%H:%M:%S)")"
+  line=""${timestamp}" "$(echo ${@})""
+  if [[ "${1}" == "-n" ]]; then
+    echo -n "${line}"
+  else
+    echo "${line}"
+  fi   
+}

pre_cache_action.sh

@@ -19,27 +19,27 @@ packages="$(normalize_package_list "${input_packages}")"
 # Create cache directory so artifacts can be saved.
 mkdir -p ${cache_dir}
 
-echo -n "Validating action arguments (version='${version}', packages='${packages}')...";
+log -n "Validating action arguments (version='${version}', packages='${packages}')...";
 if grep -q " " <<< "${version}"; then
-  echo "aborted." 
-  echo "Version value '${version}' cannot contain spaces." >&2
+  log "aborted." 
+  log "Version value '${version}' cannot contain spaces." >&2
   exit 1
 fi
 
 # Is length of string zero?
 if test -z "${packages}"; then
-  echo "aborted."
-  echo "Packages argument cannot be empty." >&2
+  log "aborted."
+  log "Packages argument cannot be empty." >&2
   exit 2
 fi
-echo "done."
+log "done."
 
 versioned_packages=""
-echo -n "Verifying packages..."
+log -n "Verifying packages..."
 for package in ${packages}; do 
   if test ! "$(apt show "${package}")"; then
     echo "aborted."
-    echo "Package '${package}' not found." >&2
+    log "Package '${package}' not found." >&2
     exit 3
   fi
   read package_name package_ver < <(get_package_name_ver "${package}")
@@ -50,20 +50,20 @@ echo "done."
 # Abort on any failure at this point.
 set -e
 
-echo "Creating cache key..."
+log "Creating cache key..."
 
 # TODO Can we prove this will happen again?
 normalized_versioned_packages="$(normalize_package_list "${versioned_packages}")"
-echo "- Normalized package list is '${normalized_versioned_packages}'."
+log "- Normalized package list is '${normalized_versioned_packages}'."
 
 value="$(echo "${normalized_versioned_packages} @ ${version}")"
-echo "- Value to hash is '${value}'."
+log "- Value to hash is '${value}'."
 
 key="$(echo "${value}" | md5sum | /bin/cut -f1 -d' ')"
-echo "- Value hashed as '${key}'."
+log "- Value hashed as '${key}'."
 
-echo "done."
+log "done."
 
 key_filepath="${cache_dir}/cache_key.md5"
 echo ${key} > ${key_filepath}
-echo "Hash value written to ${key_filepath}"
+log "Hash value written to ${key_filepath}"

restore_pkgs.sh

@@ -11,24 +11,24 @@ cache_dir="${1}"
 cache_restore_root="${2}"
 
 cache_filepaths="$(ls -1 "${cache_dir}" | sort)"
-echo "Found $(echo ${cache_filepaths} | wc -w) files in the cache."
+log "Found $(echo ${cache_filepaths} | wc -w) files in the cache."
 for cache_filepath in ${cache_filepaths}; do
-  echo "- "$(basename ${cache_filepath})""
+  log "- "$(basename ${cache_filepath})""
 done
 
-echo "Reading from main requested packages manifest..."
+log "Reading from main requested packages manifest..."
 for logline in $(cat "${cache_dir}/manifest_main.log" | tr ',' '\n' ); do
-  echo "- $(echo "${logline}" | tr ':' ' ')"
+  log "- $(echo "${logline}" | tr ':' ' ')"
 done
-echo "done."
+log "done."
 
 # Only search for archived results. Manifest and cache key also live here.
 cache_pkg_filepaths=$(ls -1 "${cache_dir}"/*.tar.gz | sort)
 cache_pkg_filecount=$(echo ${cache_pkg_filepaths} | wc -w)
-echo "Restoring ${cache_pkg_filecount} packages from cache..."
+log "Restoring ${cache_pkg_filecount} packages from cache..."
 for cache_pkg_filepath in ${cache_pkg_filepaths}; do
-  echo -n "- $(basename "${cache_pkg_filepath}") restoring..."
+  log -n "- $(basename "${cache_pkg_filepath}") restoring..."
   sudo tar -xf "${cache_pkg_filepath}" -C "${cache_restore_root}" > /dev/null
   echo "done."
 done
-echo "done."
+log "done."