From a4d3b78cdbcd0954a6a99bfbcbdeee32062a936b Mon Sep 17 00:00:00 2001 From: librelad Date: Tue, 26 May 2026 20:33:22 +0100 Subject: [PATCH] feat(debug): LP_LOAD_TRACE + 'libreportal debug load-trace' (lazy-load Phase 1) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 `\t` to $LP_LOAD_TRACE_FILE (default /tmp/libreportal-load-trace..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 ` (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 --- .../cli/commands/debug/cli_debug_commands.sh | 83 +++++++++++++++++++ .../cli/commands/debug/cli_debug_header.sh | 18 ++++ scripts/source/loading/initilize_files.sh | 25 +++++- 3 files changed, 123 insertions(+), 3 deletions(-) create mode 100644 scripts/cli/commands/debug/cli_debug_commands.sh create mode 100644 scripts/cli/commands/debug/cli_debug_header.sh diff --git a/scripts/cli/commands/debug/cli_debug_commands.sh b/scripts/cli/commands/debug/cli_debug_commands.sh new file mode 100644 index 0000000..61e18fd --- /dev/null +++ b/scripts/cli/commands/debug/cli_debug_commands.sh @@ -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 ` 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" +} diff --git a/scripts/cli/commands/debug/cli_debug_header.sh b/scripts/cli/commands/debug/cli_debug_header.sh new file mode 100644 index 0000000..a664c10 --- /dev/null +++ b/scripts/cli/commands/debug/cli_debug_header.sh @@ -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 \` 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" +} diff --git a/scripts/source/loading/initilize_files.sh b/scripts/source/loading/initilize_files.sh index 001d743..7a12230 100755 --- a/scripts/source/loading/initilize_files.sh +++ b/scripts/source/loading/initilize_files.sh @@ -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..log} + # — used by `libreportal debug load-trace` to pinpoint where the startup + # second goes. Each line: \t. 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 - source "${install_scripts_dir}${file_to_source}" - #echo "Sourced file: ${install_scripts_dir}${file_to_source}" + if [[ "$LP_LOAD_TRACE" == "1" ]]; then + local _t0=$EPOCHREALTIME + source "${install_scripts_dir}${file_to_source}" + local _t1=$EPOCHREALTIME + # ms with 3 decimals. EPOCHREALTIME is `.`; 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