Enable profiling framework in core ZFSBootMenu tools

Create /lib/profiling-lib.sh, which can be sourced by any Bash script.
Once sourced, a debug trap is installed that dumps the stack (but not
the command being executed) to a serial port, which collects the data on
the host side into a log file. After the VM exits, the performance data
is converted into a format expected by flamegraph.pl
(https://github.com/brendangregg/FlameGraph) and then both a flamegraph
and a flamechart are created.

If profiling isn't enabled, a no-op /lib/profiling-lib.sh is created.

The profiling library must always exist, and must always be sourceable.

Optimizations/performance changes include:

- setting the loglevel as from the KCL as early as possible, to preserve
  all log messages > zwarn
- validating that the loglevel is an integer, otherwise defaulting to 4
- validating that zbm.timeout/timeout is an integer, otherwise
  defaulting to 10
- adding re-import guards to libraries
- removing the zlog() function and doing the logging work in the
  zerror/zwarn/... function instead. This means that everything but
  zdebug can be as lean as possible.
- gating a couple serial zdebug calls behind a single zdebug check
- added a fast-fail to timed_prompt to return 0 if delay isn't greater
  than 0. Any default values for delay/prompt are assigned after this
  test.
- add a short-circuit to get_zbm_arg that uses bashre to check if the
  kcl option string is present at all in the KCL. If it's not, the next
  option passed to get_zbm_arg is evaluated.
- Avoid pre-computing a return value until it's actually needed
- cut i18n out of testing builds unless a graphical interface is
  requested
- cut crypt-ssh and network-legacy out of testing builds unless SSH
  access is requested
- cut out 'nvdimm fs-lib rootfs-block dm dmraid lunmask' from testing
  builds. These can likely be cut from release builds as well.

Closes #245

Author: zdykstra

90zfsbootmenu/bin/zfs-chroot

@@ -2,6 +2,8 @@
 # vim: softtabstop=2 shiftwidth=2 expandtab
 
 # shellcheck disable=SC1091
+source /lib/profiling-lib.sh >/dev/null 2>&1
+source /etc/zfsbootmenu.conf 2>&1 || exit 1
 source /lib/kmsg-log-lib.sh >/dev/null 2>&1 || exit 1
 source /lib/zfsbootmenu-core.sh >/dev/null 2>&1 || exit 1
 
@@ -12,7 +14,7 @@ zdebug "started with ${selected}"
 [ -n "${selected}" ] || exit 0
 
 if mountpoint="$( allow_rw=yes mount_zfs "${selected}" )"; then
-  zdebug "Mounted ${selected} to ${mountpoint}"
+  zdebug "mounted ${selected} to ${mountpoint}"
   mount -t proc proc "${mountpoint}/proc"
   mount -t sysfs sys "${mountpoint}/sys"
   mount -B /dev "${mountpoint}/dev"

90zfsbootmenu/bin/zfsbootmenu

@@ -3,6 +3,7 @@
 
 # Source functional libraries, logging and configuration
 sources=(
+  /lib/profiling-lib.sh
   /etc/zfsbootmenu.conf
   /lib/zfsbootmenu-core.sh
   /lib/zfsbootmenu-lib.sh

90zfsbootmenu/bin/zkexec

@@ -1,6 +1,8 @@
 #!/bin/bash
 
 # shellcheck disable=SC1091
+source /lib/profiling-lib.sh >/dev/null 2>&1
+source /etc/zfsbootmenu.conf 2>&1 || exit 1
 source /lib/kmsg-log-lib.sh >/dev/null 2>&1 || exit 1
 source /lib/zfsbootmenu-core.sh >/dev/null 2>&1 || exit 1
 

90zfsbootmenu/hook/zfsbootmenu-parse-commandline.sh

@@ -3,6 +3,8 @@
 
 # Critical functions
 sources=(
+  /lib/profiling-lib.sh
+  /etc/zfsbootmenu.conf
   /lib/kmsg-log-lib.sh
   /lib/zfsbootmenu-kcl.sh
 )
@@ -17,9 +19,10 @@ done
 
 unset src sources
 
-# Source options detected at build time
-# shellcheck disable=SC1091
-[ -r /etc/zfsbootmenu.conf ] && source /etc/zfsbootmenu.conf
+if [ -z "${BYTE_ORDER}" ]; then
+  zwarn "unable to determine platform endianness; assuming little-endian"
+  BYTE_ORDER="le"
+fi
 
 # shellcheck disable=SC2154
 if [ -n "${embedded_kcl}" ]; then
@@ -30,9 +33,20 @@ fi
 # Make sure a base directory exists
 mkdir -p "${BASE:=/zfsbootmenu}"
 
-if [ -z "${BYTE_ORDER}" ]; then
-  zwarn "unable to determine platform endianness; assuming little-endian"
-  BYTE_ORDER="le"
+# Only zwarn/zerror will log prior to loglevel being updated by a KCL argument
+min_logging=4
+loglevel=$( get_zbm_arg loglevel )
+if [ -n "${loglevel}" ]; then
+  # minimum log level of 4, so we never lose error or warning messages
+  if [ "${loglevel}" -ge ${min_logging} ] >/dev/null 2>&1; then
+    # shellcheck disable=1091
+    FORCE_RELOAD=1 source /lib/kmsg-log-lib.sh >/dev/null 2>&1
+    zinfo "setting log level from command line: ${loglevel}"
+  else
+    loglevel=${min_logging}
+  fi
+else
+  loglevel=${min_logging}
 fi
 
 # Let the command line override our host id.
@@ -64,24 +78,14 @@ fi
 # Use the last defined console= to control menu output
 control_term=$( get_zbm_arg console )
 if [ -n "${control_term}" ]; then
+  #shellcheck disable=SC2034
   control_term="/dev/${control_term%,*}"
   zinfo "setting controlling terminal to: ${control_term}"
 else
   control_term="/dev/tty1"
   zinfo "defaulting controlling terminal to: ${control_term}"
 fi
 
-# Use loglevel to determine logging to /dev/kmsg
-min_logging=4
-loglevel=$( get_zbm_arg loglevel )
-if [ -n "${loglevel}" ]; then
-  # minimum log level of 4, so we never lose error or warning messages
-  [ "${loglevel}" -ge ${min_logging} ] || loglevel=${min_logging}
-  zinfo "setting log level from command line: ${loglevel}"
-else
-  loglevel=${min_logging}
-fi
-
 # hostid - discover the hostid used to import a pool on failure, assume it
 # force  - append -f to zpool import
 # strict - legacy behavior, drop to an emergency shell on failure
@@ -119,8 +123,14 @@ fi
 
 # zbm.timeout= overrides timeout=
 menu_timeout=$( get_zbm_arg zbm.timeout timeout )
-if [ -n "${menu_timeout}" ]; then
-  zinfo "setting menu timeout from command line: ${menu_timeout}"
+if [ -n "${menu_timeout}" ] ; then
+  # Ensure that menu_timeout is an integer
+  if ! [ "${menu_timeout}" -eq "${menu_timeout}" ] >/dev/null 2>&1; then
+    menu_timeout=10
+    zinfo "invalid menu timeout, defaulting to ${menu_timeout}"
+  else
+    zinfo "setting menu timeout from command line: ${menu_timeout}"
+  fi
 elif get_zbm_bool 0 zbm.show ; then
   menu_timeout=-1;
   zinfo "forcing display of menu"
@@ -129,6 +139,7 @@ elif get_zbm_bool 0 zbm.skip ; then
   zinfo "skipping display of menu"
 else
   menu_timeout=10
+  zinfo "defaulting menu timeout to ${menu_timeout}"
 fi
 
 zbm_import_delay=$( get_zbm_arg zbm.import_delay )

90zfsbootmenu/lib/kmsg-log-lib.sh

@@ -1,79 +1,86 @@
 #!/bin/bash
 # vim: softtabstop=2 shiftwidth=2 expandtab
 
+if [ -n "${_ZFSBOOTMENU_KMSG_LOG_LIB}" ]; then
+  [ -z "${FORCE_RELOAD}" ] && return
+else
+  readonly _ZFSBOOTMENU_KMSG_LOG_LIB=1
+fi
+
 : "${loglevel:=4}"
 
-# arg1: log level
-# arg2: log line
+# arg1..argN: log line
 # prints: nothing
-# returns: nothing
+# returns: 1 if loglevel isn't high enough
 
-zlog() {
+zdebug() {
+  [ ${loglevel:-4} -ge 7 ] || return 1
   local prefix trace last lines line lc i
-  [ -z "${1}" ] && return
-  [ -z "${2}" ] && return
 
   # Remove everything but new lines from the string, count the length
-  lines="${2//[!$'\n']/}"
+  lines="${1//[!$'\n']/}"
   lines="${#lines}"
-  lc=0
 
   while IFS=$'\n' read -r line ; do
-    # Only add script/function tracing to debug messages
-    if [ "${1}" -eq 7 ] && [ "${lc}" -eq "${lines}" ] ; then
+    if [ "${lc:=0}" -eq "${lines}" ] ; then
       trace=
       last=${#BASH_SOURCE[@]}
-      for (( i=2 ; i<last ; i++ )) ; do
+      for (( i=1 ; i<last ; i++ )) ; do
         trace="${FUNCNAME[$i]},${BASH_SOURCE[$i]},${BASH_LINENO[$i-1]}${trace:+;}${trace}"
       done
-      prefix="<${1}>ZBM:[$$]|${trace}|"
-    elif [ "${1}" -eq 7 ] ; then
-      prefix="<${1}>ZBM:[$$]||"
+      prefix="<7>ZBM:[$$]|${trace}|"
     else
-      prefix="<${1}>ZFSBootMenu: "
+      prefix="<7>ZBM:[$$]||"
     fi
     lc=$(( lc + 1 ))
-    echo -e "${prefix}${line}" > /dev/kmsg
-  done <<<"${2}"
+    echo "${prefix}${line}" > /dev/kmsg
+  done <<<"${1}"
 }
 
+if [ ${loglevel:-4} -ge 7 ] ; then
+  # Trap errors and send them to the debug handler
+  traperror() {
+    zdebug "trapped error from: '${BASH_COMMAND}'"
+  }
+
+  trap traperror ERR
+  set -o errtrace
+fi
+
 # arg1: log line
 # prints: nothing
 # returns: 1 if loglevel isn't high enough
 
-zdebug() {
-  [ "${loglevel:-4}" -ge 7 ] || return 1
-  zlog 7 "$@"
-}
-
 zinfo() {
   [ "${loglevel:-4}" -ge 6 ] || return 1
-  zlog 6 "$@"
+  echo "<6>ZFSBootMenu: $1" > /dev/kmsg
 }
 
+# arg1: log line
+# prints: nothing
+# returns: 1 if loglevel isn't high enough
+
 znotice() {
   [ "${loglevel:-4}" -ge 5 ] || return 1
-  zlog 5 "$@"
+  echo "<5>ZFSBootMenu: $1" > /dev/kmsg
 }
 
+# arg1: log line
+# prints: nothing
+# returns: 1 if loglevel isn't high enough
+
 zwarn() {
   [ "${loglevel:-4}" -ge 4 ] || return 1
   : > "${BASE}/have_warnings"
-  zlog 4 "$@"
+  echo "<4>ZFSBootMenu: $1" > /dev/kmsg
 }
 
+# arg1: log line
+# prints: nothing
+# returns: 1 if loglevel isn't high enough
+
 zerror() {
   [ "${loglevel:-4}" -ge 3 ] || return 1
   : > "${BASE}/have_errors"
-  zlog 3 "$@"
-}
-
-traperror() {
-  zdebug "trapped error from: '${BASH_COMMAND}'"
+  echo "<3>ZFSBootMenu: $1" > /dev/kmsg
 }
-
-if [ "${loglevel:-4}" -eq 7 ] ; then
-  set -o errtrace
-  set -o functrace
-  trap traperror ERR
-fi

90zfsbootmenu/lib/zfsbootmenu-core.sh

@@ -335,9 +335,11 @@ kexec_kernel() {
 
     return 1
   else
-    zdebug "loaded ${mnt}${kernel} and ${mnt}${initramfs} into memory"
-    zdebug "kernel command line: '${root_prefix}${fs} ${cli_args}'"
-    zdebug "${output}"
+    if zdebug ; then
+      zdebug "loaded ${mnt}${kernel} and ${mnt}${initramfs} into memory"
+      zdebug "kernel command line: '${root_prefix}${fs} ${cli_args}'"
+      zdebug "${output}"
+    fi
   fi
 
   umount "${mnt}"
@@ -747,6 +749,7 @@ find_be_kernels() {
       labels+=( "$version" )
     fi
 
+    local ext pfx lbl i
     # Use a mess of loops instead better brace expansions to control priorities
     for ext in {.img,""}{"",.{gz,bz2,xz,lzma,lz4,lzo,zstd}}; do
       for pfx in initramfs initrd; do
@@ -1221,17 +1224,13 @@ has_resume_device() {
 # -m, -r, -e are print in the order they are passed into the function
 
 timed_prompt() {
-  local prompt delay message
-
-  delay="30"
-  prompt="Press $( colorize green "[RETURN]") or wait $( colorize yellow "%0.${#delay}d" ) seconds to continue"
-  message=()
+  local prompt delay message opt OPTIND
 
-  local opt OPTIND
   while getopts "d:p:m:r:e:" opt; do
     case "${opt}" in
       d)
         delay="${OPTARG}"
+        [ "${delay}" -gt 0 ] || return 0
         ;;
       p)
         prompt="${OPTARG}"
@@ -1250,6 +1249,9 @@ timed_prompt() {
     esac
   done
 
+  [ -n "${delay}" ] || delay="30"
+  [ -n "${prompt}" ] || prompt="Press $( colorize green "[RETURN]") or wait $( colorize yellow "%0.${#delay}d" ) seconds to continue"
+
   # Add a blank line between any messages and the prompt
   message+=( "" )
 

90zfsbootmenu/lib/zfsbootmenu-kcl.sh

@@ -203,6 +203,10 @@ get_zbm_arg() {
 
   for kopt in "$@"; do
     kmatch=
+
+    # Short-circuit the entire check if the option string isn't in the KCL at all
+    [[ ${kcl} =~ ${kopt} ]] || continue
+
     while read -r karg; do
       # Ignore variables not being tested
       kkey="${karg%%=*}"
@@ -238,12 +242,12 @@ get_zbm_bool() {
   def="${1}"
   shift
 
-  case "${def,,}" in
-    ""|no|off|0) def=1;;
-    *) def=0;;
-  esac
-
-  val="$(get_zbm_arg "$@")" || return ${def}
+  if ! val="$(get_zbm_arg "$@")"; then
+    case "${def,,}" in
+      ""|no|off|0) return 1;;
+      *) return 0;;
+    esac
+  fi
 
   case "${val,,}" in
     ""|no|off|0) return 1;;

90zfsbootmenu/libexec/zfsbootmenu-help

@@ -2,6 +2,8 @@
 # vim: softtabstop=2 shiftwidth=2 expandtab
 
 # shellcheck disable=SC1091
+source /lib/profiling-lib.sh >/dev/null 2>&1
+source /etc/zfsbootmenu.conf 2>&1 || exit 1
 source /lib/kmsg-log-lib.sh >/dev/null 2>&1 || exit 1
 source /lib/zfsbootmenu-core.sh >/dev/null 2>&1 || exit 1
 

90zfsbootmenu/libexec/zfsbootmenu-init

@@ -6,6 +6,7 @@ trap '' SIGINT
 
 # Source functional libraries, logging and configuration
 sources=(
+  /lib/profiling-lib.sh
   /etc/zfsbootmenu.conf
   /lib/zfsbootmenu-kcl.sh
   /lib/zfsbootmenu-core.sh

90zfsbootmenu/libexec/zfsbootmenu-input

@@ -2,11 +2,7 @@
 trap - SIGINT
 def_args="$1"
 
-function sigint() {
-  exit 1
-}
-
-trap sigint SIGINT
+trap 'exit 1' SIGINT
 read -r -e -i "${def_args}" -p "> " input 
 echo "${input}"
 exit 0

90zfsbootmenu/libexec/zfsbootmenu-preview

@@ -2,6 +2,8 @@
 # vim: softtabstop=2 shiftwidth=2 expandtab
 
 # shellcheck disable=SC1091
+source /lib/profiling-lib.sh >/dev/null 2>&1 || true
+source /etc/zfsbootmenu.conf >/dev/null 2>&1 || exit 1
 source /lib/kmsg-log-lib.sh >/dev/null 2>&1 || exit 1
 source /lib/zfsbootmenu-core.sh >/dev/null 2>&1 || exit 1
 

90zfsbootmenu/libexec/zfunc

@@ -2,7 +2,10 @@
 # vim: softtabstop=2 shiftwidth=2 expandtab
 
 # shellcheck disable=SC1091
+source /lib/profiling-lib.sh >/dev/null 2>&1
+source /etc/zfsbootmenu.conf 2>&1 || exit 1
 source /lib/kmsg-log-lib.sh >/dev/null 2>&1 || exit 1
+source /lib/zfsbootmenu-lib.sh >/dev/null 2>&1 || exit 1
 source /lib/zfsbootmenu-core.sh >/dev/null 2>&1 || exit 1
 
 # First argument is the function name