Skip to content

Commit

Permalink
Enable profiling framework in core ZFSBootMenu tools
Browse files Browse the repository at this point in the history
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
  • Loading branch information
zdykstra committed Jan 13, 2022
1 parent fce302c commit 89b6273
Show file tree
Hide file tree
Showing 16 changed files with 282 additions and 93 deletions.
4 changes: 3 additions & 1 deletion 90zfsbootmenu/bin/zfs-chroot
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand All @@ -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"
Expand Down
1 change: 1 addition & 0 deletions 90zfsbootmenu/bin/zfsbootmenu
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
2 changes: 2 additions & 0 deletions 90zfsbootmenu/bin/zkexec
Original file line number Diff line number Diff line change
@@ -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

Expand Down
49 changes: 30 additions & 19 deletions 90zfsbootmenu/hook/zfsbootmenu-parse-commandline.sh
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,8 @@

# Critical functions
sources=(
/lib/profiling-lib.sh
/etc/zfsbootmenu.conf
/lib/kmsg-log-lib.sh
/lib/zfsbootmenu-kcl.sh
)
Expand All @@ -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
Expand All @@ -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.
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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"
Expand All @@ -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 )
Expand Down
79 changes: 43 additions & 36 deletions 90zfsbootmenu/lib/kmsg-log-lib.sh
Original file line number Diff line number Diff line change
@@ -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
20 changes: 11 additions & 9 deletions 90zfsbootmenu/lib/zfsbootmenu-core.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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}"
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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}"
Expand All @@ -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+=( "" )

Expand Down
16 changes: 10 additions & 6 deletions 90zfsbootmenu/lib/zfsbootmenu-kcl.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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%%=*}"
Expand Down Expand Up @@ -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;;
Expand Down
2 changes: 2 additions & 0 deletions 90zfsbootmenu/libexec/zfsbootmenu-help
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
1 change: 1 addition & 0 deletions 90zfsbootmenu/libexec/zfsbootmenu-init
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
6 changes: 1 addition & 5 deletions 90zfsbootmenu/libexec/zfsbootmenu-input
Original file line number Diff line number Diff line change
Expand Up @@ -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
2 changes: 2 additions & 0 deletions 90zfsbootmenu/libexec/zfsbootmenu-preview
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
3 changes: 3 additions & 0 deletions 90zfsbootmenu/libexec/zfunc
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down

0 comments on commit 89b6273

Please sign in to comment.