fix: apt cache performance (#104)

* fix: apt cache performance

Use a single call to apt-cache to reduce the time needed to lookup
package versions.

Also:
* Added millisecond details to log timing so slow operations can be more
  easily identified.
* Perform apt update before determining package versions.

Fixes #103

* chore: descriptive variable names and use log_err

Added the review feedback, updating variable names to be more
descriptive and using log_err where appropriate.

install_and_cache_pkgs.sh

@@ -18,28 +18,6 @@ cache_dir="${1}"
 # List of the packages to use.
 input_packages="${@:3}"
 
-# Trim commas, excess spaces, sort, and version syntax.
-#
-# NOTE: Unless specified, all APT package listings of name and version use
-# colon delimited and not equals delimited syntax (i.e. <name>[:=]<ver>).
-packages="$(get_normalized_package_list "${input_packages}")"
-
-package_count=$(wc -w <<< "${packages}")
-log "Clean installing and caching ${package_count} package(s)."
-
-log_empty_line
-
-manifest_main=""
-log "Package list:"
-for package in ${packages}; do
-  read package_name package_ver < <(get_package_name_ver "${package}")
-  manifest_main="${manifest_main}${package_name}=${package_ver},"  
-  log "- ${package_name} (${package_ver})"
-done
-write_manifest "main" "${manifest_main}" "${cache_dir}/manifest_main.log"
-
-log_empty_line
-
 if ! apt-fast --version > /dev/null 2>&1; then
   log "Installing apt-fast for optimized installs..."
   # Install apt-fast for optimized installs.
@@ -59,6 +37,22 @@ fi
 
 log_empty_line
 
+packages="$(get_normalized_package_list "${input_packages}")"
+package_count=$(wc -w <<< "${packages}")
+log "Clean installing and caching ${package_count} package(s)."
+
+log_empty_line
+
+manifest_main=""
+log "Package list:"
+for package in ${packages}; do
+  manifest_main="${manifest_main}${package},"
+  log "- ${package}"
+done
+write_manifest "main" "${manifest_main}" "${cache_dir}/manifest_main.log"
+
+log_empty_line
+
 # Strictly contains the requested packages.
 manifest_main=""
 # Contains all packages including dependencies.

lib.sh

@@ -71,7 +71,7 @@ function get_installed_packages {
 ###############################################################################
 # Splits a fully action syntax APT package into the name and version.
 # Arguments:
-#   The action syntax colon delimited package pair or just the package name.
+#   The action syntax equals delimited package pair or just the package name.
 # Returns:
 #   The package name and version pair.
 ###############################################################################
@@ -81,7 +81,9 @@ function get_package_name_ver {
   IFS="${ORIG_IFS}"
   # If version not found in the fully qualified package value.
   if test -z "${ver}"; then
-    ver="$(grep "Version:" <<< "$(apt-cache show ${name})" | awk '{print $2}')"
+    # This is a fallback and should not be used any more as its slow.
+    log_err "Unexpected version resolution for package '${name}'"
+    ver="$(apt-cache show ${name} | grep '^Version:' | awk '{print $2}')"
   fi
   echo "${name}" "${ver}"  
 }
@@ -91,16 +93,63 @@ function get_package_name_ver {
 # Arguments:
 #   The comma and/or space delimited list of packages.
 # Returns:
-#   Sorted list of space delimited packages.
+#   Sorted list of space delimited package name=version pairs.
 ###############################################################################
 function get_normalized_package_list {
-  # Remove commas, and block scalar folded backslashes.
-  local stripped=$(echo "${1}" | sed 's/[,\]/ /g')
-  # Remove extraneous spaces at the middle, beginning, and end.
-  local trimmed="$(\
-    echo "${stripped}" \
-    | sed 's/\s\+/ /g; s/^\s\+//g; s/\s\+$//g')"
-  echo ${trimmed} | tr ' ' '\n' | sort | tr '\n' ' '
+  # Remove commas, and block scalar folded backslashes,
+  # extraneous spaces at the middle, beginning and end
+  # then sort.
+  packages=$(echo "${1}" \
+    | sed 's/[,\]/ /g; s/\s\+/ /g; s/^\s\+//g; s/\s\+$//g' \
+    | sort -t' ')
+
+  # Validate package names and get versions.
+  log_err "resolving package versions..."
+  data=$(apt-cache --quiet=0 --no-all-versions show ${packages} 2>&1 | \
+    grep -E '^(Package|Version|N):')
+  log_err "resolved"
+
+  local ORIG_IFS="${IFS}"
+  IFS=$'\n'
+  declare -A missing
+  local package_versions=''
+  local package='' separator=''
+  for key_value in ${data}; do
+    local key="${key_value%%: *}"
+    local value="${key_value##*: }"
+
+    case $key in
+      Package)
+        package=$value
+        ;;
+      Version)
+        package_versions="${package_versions}${separator}"${package}=${value}""
+        separator=' '
+        ;;
+      N)
+        # Warning messages.
+        case $value in
+          'Unable to locate package '*)
+            package="${value#'Unable to locate package '}"
+            # Avoid duplicate messages.
+            if [ -z "${missing[$package]}" ]; then
+              package="${value#'Unable to locate package '}"
+              log_err "Package '${package}' not found."
+              missing[$package]=1
+            fi
+            ;;
+        esac
+        ;;
+    esac
+  done
+  IFS="${ORIG_IFS}"
+
+  if [ ${#missing[@]} -gt 0 ]; then
+    echo "aborted"
+    exit 5
+  fi
+
+  echo "${package_versions}"
 }
 
 ###############################################################################
@@ -120,8 +169,8 @@ function get_tar_relpath {
   fi
 }
 
-function log { echo "$(date +%H:%M:%S)" "${@}"; }
-function log_err { >&2 echo "$(date +%H:%M:%S)" "${@}"; }
+function log { echo "$(date +%T.%3N)" "${@}"; }
+function log_err { >&2 echo "$(date +%T.%3N)" "${@}"; }
 
 function log_empty_line { echo ""; }
 

pre_cache_action.sh

@@ -53,35 +53,16 @@ log "done"
 
 log_empty_line
 
-versioned_packages=""
-log "Verifying packages..."
-for package in ${packages}; do  
-  if test ! "$(apt-cache show ${package})"; then
-    echo "aborted"
-    log "Package '${package}' not found." >&2
-    exit 5
-  fi
-  read package_name package_ver < <(get_package_name_ver "${package}")
-  versioned_packages=""${versioned_packages}" "${package_name}"="${package_ver}""
-done
-log "done"
-
-log_empty_line
-
 # Abort on any failure at this point.
 set -e
 
 log "Creating cache key..."
 
-# TODO Can we prove this will happen again?
-normalized_versioned_packages="$(get_normalized_package_list "${versioned_packages}")"
-log "- Normalized package list is '${normalized_versioned_packages}'."
-
 # Forces an update in cases where an accidental breaking change was introduced
 # and a global cache reset is required.
 force_update_inc="1"
 
-value="${normalized_versioned_packages} @ ${version} ${force_update_inc}"
+value="${packages} @ ${version} ${force_update_inc}"
 log "- Value to hash is '${value}'."
 
 key="$(echo "${value}" | md5sum | cut -f1 -d' ')"