feat(debug): LP_LOAD_TRACE + 'libreportal debug load-trace' (lazy-load Phase 1)
First step toward an autoload-style lazy loader for the 499-file source tree (current cold load ~1s wall / 340ms user-time per CLI invocation, mostly spent sourcing files the command never calls). This commit only measures — no behaviour change unless LP_LOAD_TRACE=1. LP_LOAD_TRACE=1 instrumentation (scripts/source/loading/initilize_files.sh): Wraps each in the main file-list loop with EPOCHREALTIME before/after, writes `<elapsed_ms>\t<file_relpath>` to $LP_LOAD_TRACE_FILE (default /tmp/libreportal-load-trace.<pid>.log). Zero overhead when the env var is unset (one [[ test per file). libreportal debug load-trace [cmd...]: New `debug` CLI category. Spawns a child `libreportal <args>` (default 'help') with LP_LOAD_TRACE=1, then awk-aggregates the trace: wall vs cumulative source time, file count, top-15 hottest files. The diff between wall and cumulative-source = bash startup + dispatch + the command's own work. Used in the next phases to (a) validate that the lazy loader actually delivers the speedup we expect and (b) flag any single file that hogs disproportionate time (rare `heredoc | sed | base64` style work at source time would show up here as a >10ms entry). Signed-off-by: librelad <librelad@digitalangels.vip>
This commit is contained in:
librelad
parent
ef00e0444d
commit
a4d3b78cdb
83
scripts/cli/commands/debug/cli_debug_commands.sh
Normal file
83
scripts/cli/commands/debug/cli_debug_commands.sh
Normal file
@ -0,0 +1,83 @@
|
||||
#!/bin/bash
|
||||
|
||||
cliHandleDebugCommands()
|
||||
{
|
||||
local action="$initial_command2"
|
||||
|
||||
case "$action" in
|
||||
""|help)
|
||||
cliShowDebugHelp
|
||||
;;
|
||||
load-trace)
|
||||
cliDebugLoadTrace
|
||||
;;
|
||||
*)
|
||||
isNotice "Invalid debug action: $action"
|
||||
cliShowDebugHelp
|
||||
;;
|
||||
esac
|
||||
}
|
||||
|
||||
# Run `libreportal <args>` with LP_LOAD_TRACE=1, then summarise the resulting
|
||||
# trace file. We rebuild the args from initial_command3..7 (the CLI dispatcher
|
||||
# doesn't pass $@ to category handlers — same constraint as the peer commands).
|
||||
# A child shell invocation isolates the trace so it doesn't pollute the
|
||||
# currently-loaded process.
|
||||
cliDebugLoadTrace()
|
||||
{
|
||||
local args=()
|
||||
local a
|
||||
for a in "$initial_command3" "$initial_command4" "$initial_command5" "$initial_command6" "$initial_command7"; do
|
||||
[[ -n "$a" ]] && args+=("$a")
|
||||
done
|
||||
[[ ${#args[@]} -eq 0 ]] && args=(help)
|
||||
|
||||
local trace_file
|
||||
trace_file=$(mktemp -t libreportal-load-trace.XXXXXX.log)
|
||||
|
||||
isHeader "Load trace: libreportal ${args[*]}"
|
||||
|
||||
# Time the whole child invocation so we can compare 'wall' vs 'time spent
|
||||
# in sourced files'. The diff = bash startup + dispatch + the command's
|
||||
# own work (which for `help` is ~nothing, so wall ≈ load + bash startup).
|
||||
local t0 t1 wall_ms
|
||||
t0=$EPOCHREALTIME
|
||||
LP_LOAD_TRACE=1 LP_LOAD_TRACE_FILE="$trace_file" \
|
||||
libreportal "${args[@]}" >/dev/null 2>&1
|
||||
t1=$EPOCHREALTIME
|
||||
wall_ms=$(awk -v a="$t0" -v b="$t1" 'BEGIN{printf "%.1f", (b-a)*1000}')
|
||||
|
||||
if [[ ! -s "$trace_file" ]]; then
|
||||
isError "Trace file empty — did the child invocation actually source files?"
|
||||
rm -f "$trace_file"
|
||||
return 1
|
||||
fi
|
||||
|
||||
# Aggregate: total ms inside source, count, top-N hottest files. awk single
|
||||
# pass — no need for sort | head | wc dance.
|
||||
awk -v wall="$wall_ms" -v file="$trace_file" '
|
||||
{ ms=$1; sub(/^[^\t]*\t/,""); path=$0
|
||||
total+=ms; n++
|
||||
if (ms > 0.1) { top_ms[n]=ms; top_path[n]=path }
|
||||
}
|
||||
END {
|
||||
printf " Wall time (child invocation): %s ms\n", wall
|
||||
printf " Files sourced: %d\n", n
|
||||
printf " Cumulative source time: %.1f ms\n", total
|
||||
if (n>0) printf " Average per file: %.3f ms\n", total/n
|
||||
printf "\n Top 15 hottest files (>0.1 ms):\n"
|
||||
# Quick sort by ms descending (small N, n^2 is fine).
|
||||
for (i=1;i<=n;i++) for (j=i+1;j<=n;j++)
|
||||
if (top_ms[j]>top_ms[i]) {
|
||||
t=top_ms[i]; top_ms[i]=top_ms[j]; top_ms[j]=t
|
||||
t=top_path[i]; top_path[i]=top_path[j]; top_path[j]=t
|
||||
}
|
||||
shown=0
|
||||
for (i=1;i<=n && shown<15;i++) if (top_ms[i]>0) {
|
||||
printf " %8.3f ms %s\n", top_ms[i], top_path[i]
|
||||
shown++
|
||||
}
|
||||
printf "\n Full trace at: %s\n", file
|
||||
}
|
||||
' "$trace_file"
|
||||
}
|
||||
18
scripts/cli/commands/debug/cli_debug_header.sh
Normal file
18
scripts/cli/commands/debug/cli_debug_header.sh
Normal file
@ -0,0 +1,18 @@
|
||||
#!/bin/bash
|
||||
|
||||
cliShowDebugHelp()
|
||||
{
|
||||
isHeader "LibrePortal Debug Commands"
|
||||
echo "Diagnostic tools for measuring and inspecting the running install."
|
||||
echo ""
|
||||
echo "debug load-trace [cmd...]"
|
||||
echo " Run \`libreportal <cmd...>\` with LP_LOAD_TRACE=1 (default: 'help')"
|
||||
echo " and summarise where the source-loading time went — total time,"
|
||||
echo " files loaded, hottest files. Used to measure the gain from lazy"
|
||||
echo " loading (Phase 3+) and find outliers worth optimising."
|
||||
echo ""
|
||||
echo " Examples:"
|
||||
echo " libreportal debug load-trace # times 'libreportal help'"
|
||||
echo " libreportal debug load-trace peer list # times 'libreportal peer list'"
|
||||
echo " libreportal debug load-trace backup app delete linkding 1:abc"
|
||||
}
|
||||
@ -37,13 +37,32 @@ sourceInitilize()
|
||||
files_to_source=("${files_libreportal_cli[@]}")
|
||||
fi
|
||||
|
||||
# Checking for missing files
|
||||
# Checking for missing files. If LP_LOAD_TRACE=1, every source is timed
|
||||
# and logged to ${LP_LOAD_TRACE_FILE:-/tmp/libreportal-load-trace.<pid>.log}
|
||||
# — used by `libreportal debug load-trace` to pinpoint where the startup
|
||||
# second goes. Each line: <elapsed_ms>\t<file_relpath>. Zero overhead when
|
||||
# the env var is not set (one `[[` per file).
|
||||
if [[ "$LP_LOAD_TRACE" == "1" ]]; then
|
||||
: "${LP_LOAD_TRACE_FILE:=/tmp/libreportal-load-trace.$$.log}"
|
||||
export LP_LOAD_TRACE_FILE
|
||||
: > "$LP_LOAD_TRACE_FILE"
|
||||
fi
|
||||
for file_to_source in "${files_to_source[@]}"; do
|
||||
if [ ! -f "${install_scripts_dir}${file_to_source}" ]; then
|
||||
isNotice "Missing file: ${install_scripts_dir}${file_to_source}"
|
||||
else
|
||||
if [[ "$LP_LOAD_TRACE" == "1" ]]; then
|
||||
local _t0=$EPOCHREALTIME
|
||||
source "${install_scripts_dir}${file_to_source}"
|
||||
#echo "Sourced file: ${install_scripts_dir}${file_to_source}"
|
||||
local _t1=$EPOCHREALTIME
|
||||
# ms with 3 decimals. EPOCHREALTIME is `<sec>.<usec>`; awk
|
||||
# handles the float arithmetic without needing bc.
|
||||
local _ms
|
||||
_ms=$(awk -v a="$_t0" -v b="$_t1" 'BEGIN{printf "%.3f", (b-a)*1000}')
|
||||
printf '%s\t%s\n' "$_ms" "$file_to_source" >> "$LP_LOAD_TRACE_FILE"
|
||||
else
|
||||
source "${install_scripts_dir}${file_to_source}"
|
||||
fi
|
||||
fi
|
||||
done
|
||||
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user