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