// Moved from docs/src/performance-profiling/PROFILER.adoc to docs/working/scratch/src/performance-profiling/PROFILER.adoc on 2026-06-16 (docs reorg Phase 2) == StarForth Profiler Guide :toc: left :toc-title: Contents :toclevels: 3 xref:../README.adoc[← Back to Documentation Index] *Complete guide to using StarForth’s built-in word execution profiler for performance analysis and optimization* ''''' === Overview StarForth includes a lightweight, zero-overhead profiler that tracks word execution frequency and provides data-driven optimization recommendations. The profiler helps identify hot paths (frequently executed code) that are candidates for inline assembly optimization. ==== Key Features * *Lightweight Frequency Tracking* - Minimal overhead call counting * *Hot Word Analysis* - Identifies optimization candidates by execution percentage * *Multiple Profiling Levels* - From basic frequency tracking to detailed timing * *Optimization Recommendations* - Data-driven suggestions for assembly optimization * *Integration with PGO* - Complements Profile-Guided Optimization workflow ''''' === Quick Start ==== Basic Profiling [source,bash] ---- ./build/starforth --profile 1 --profile-report < script.fth ---- This will: [arabic] . Enable PROFILE_BASIC level (frequency tracking only) . Execute your Forth script . Print a profiling report showing the most frequently called words ==== Example Output .... ======================================== StarForth Profiler Report ======================================== Global Statistics: Dictionary lookups: 0 Most Frequently Called Words: Word Calls ---------------------------------------- . 661 CR 464 LIT 199 HERE 149 I 114 (LOOP) 105 EXIT 102 DUP 93 : 74 (0BRANCH) 68 ======================================== .... ''''' === Profiling Levels The profiler supports multiple detail levels, controlled by the `+--profile+` flag: ==== Level 0: PROFILE_DISABLED [source,bash] ---- ./build/starforth # Default - no profiling ---- *Use when:* Maximum performance, no profiling overhead ==== Level 1: PROFILE_BASIC (Recommended) [source,bash] ---- ./build/starforth --profile 1 --profile-report ---- *Features:* * Word execution frequency tracking * Zero-overhead call counting * Dictionary lookup counts * Lightweight, minimal performance impact *Use when:* You want to identify hot words for optimization ==== Level 2: PROFILE_DETAILED [source,bash] ---- ./build/starforth --profile 2 --profile-report ---- *Features:* * Everything from PROFILE_BASIC * Word execution timing (nanosecond precision) * Average, min, max execution times * Top words by total execution time *Use when:* You need timing data in addition to frequency *Performance impact:* ~5-10% overhead due to timing calls ==== Level 3: PROFILE_VERBOSE [source,bash] ---- ./build/starforth --profile 3 --profile-report ---- *Features:* * Everything from PROFILE_DETAILED * Stack operation counts * Memory read/write tracking (bytes) * Detailed memory access patterns *Use when:* Deep performance analysis required *Performance impact:* ~15-20% overhead ''''' === Command-Line Flags ==== `+--profile [N]+` Enable profiler at specified level (0-3). [source,bash] ---- --profile 1 # Basic frequency tracking --profile 2 # Detailed timing --profile 3 # Full verbose profiling ---- ==== `+--profile-report+` Print profiling report on exit. [source,bash] ---- ./build/starforth --profile 1 --profile-report < script.fth ---- *Note:* Must be used with `+--profile+` to have any effect. ''''' === Understanding the Report ==== Global Statistics .... Global Statistics: Dictionary lookups: 0 .... * *Dictionary lookups* - Number of word lookups performed (tracked at PROFILE_BASIC+) * *Stack operations* - Stack pushes/pops (tracked at PROFILE_VERBOSE+) * *Memory reads/writes* - Memory access patterns (tracked at PROFILE_VERBOSE+) ==== Most Frequently Called Words .... Word Calls ---------------------------------------- LIT 1560 EXIT 562 (LOOP) 525 .... Shows top 15 words by execution count: * *LIT* - Literal values pushed to stack * *EXIT* - End of word definition (every : word ends with EXIT) * *(LOOP)* - Loop runtime implementation * *I* - Loop counter access *Interpretation:* * High call counts indicate hot paths * These words are prime candidates for assembly optimization * Words with >5% of total executions should be optimized first ==== Top Words by Execution Time (PROFILE_DETAILED) .... Top Words by Execution Time: Word Calls Total (µs) Avg (ns) Max (ns) -------------------------------------------------------------------------------- DUP 500 1234.56 2469 12000 + 500 987.32 1975 8500 .... * *Total (µs)* - Total time spent in this word (microseconds) * *Avg (ns)* - Average execution time per call (nanoseconds) * *Max (ns)* - Longest single execution (nanoseconds) ''''' === Hot Word Analysis The profiler includes a hot word analysis function `+profiler_print_hotspots()+` that provides optimization recommendations. ==== Optimization Priority Levels [width="100%",cols="18%,13%,69%",options="header",] |=== |% of Total |Priority |Recommendation |≥ 5.0% |⚡ HIGH |Inline assembly candidate - optimize immediately |≥ 2.0% |🔥 |Consider assembly optimization |≥ 1.0% |💡 |Monitor for optimization |≥ 0.5% |📊 |Profile for PGO |< 0.5% |— |Low priority |=== ==== Example Hot Word Report .... ======================================== Hot Word Analysis & Optimization ======================================== Top 25 Most Frequently Called Words: Word Calls % Total Optimization Suggestion -------------------------------------------------------------------------------- LIT 1560 32.5% ⚡ HIGH PRIORITY: Inline assembly candidate EXIT 562 11.7% ⚡ HIGH PRIORITY: Inline assembly candidate (LOOP) 525 10.9% ⚡ HIGH PRIORITY: Inline assembly candidate I 500 10.4% ⚡ HIGH PRIORITY: Inline assembly candidate + 500 10.4% ⚡ HIGH PRIORITY: Inline assembly candidate * 500 10.4% ⚡ HIGH PRIORITY: Inline assembly candidate DROP 500 10.4% ⚡ HIGH PRIORITY: Inline assembly candidate Summary: Total word executions: 4800 Unique words tracked: 25 Top 10 coverage: 95.3% .... *Key Insights:* * *Top 10 coverage: 95.3%* - Optimizing just 10 words affects 95% of executions * Focus optimization efforts on words with ≥5% execution percentage * Use PGO to guide compiler optimization for words with 0.5-5% coverage ''''' === Integration with Development Workflow ==== 1. Profile Your Workload [source,bash] ---- # Run your typical Forth program with profiling ./build/starforth --profile 1 --profile-report < my_program.fth ---- ==== 2. Identify Hot Words Look for words with high call counts or high percentage of total executions. ==== 3. Optimize Hot Words *For words ≥5% execution:* * Implement inline assembly version (see `+docs/ASM_OPTIMIZATIONS.md+`) * Add to `+src/word_source/*_words.c+` with `+USE_ASM_OPT+` guards *For words 0.5-5% execution:* * Let PGO handle optimization: `+make pgo+` * Compiler will inline and optimize based on profile data ==== 4. Verify Performance Gains [source,bash] ---- # Benchmark before optimization ./build/starforth --benchmark 10000 # Implement optimization # ... # Rebuild and benchmark again make clean && make ./build/starforth --benchmark 10000 ---- ''''' === Profiling Best Practices ==== ✅ Do * *Profile realistic workloads* - Use actual programs, not toy examples * *Run sufficient iterations* - Ensure statistical significance (1000+ word executions) * *Profile at BASIC level first* - Minimal overhead, identifies hot words quickly * *Use DETAILED level for timing* - When you need to know execution duration * *Combine with PGO* - Profile → identify hot words → optimize → PGO build ==== ❌ Don’t * *Don’t profile with LOG_DEBUG* - Logging overhead skews results * *Don’t optimize prematurely* - Profile first, then optimize hot paths only * *Don’t ignore top 10 coverage* - If <80%, workload may not be representative * *Don’t profile error paths* - Focus on normal execution, not exceptional cases ''''' === Profiler Implementation Details ==== Architecture The profiler tracks word execution in two places: [arabic] . *Outer Interpreter* (`+vm_interpret_word()+` in `+src/vm.c:492+`) * Tracks words executed from REPL or scripts * Direct word execution (not compiled) . *Inner Interpreter* (`+execute_colon_word()+` in `+src/vm.c:426+`) * Tracks words executed from compiled definitions * Threaded code execution ==== Data Structure [source,c] ---- typedef struct { const DictEntry *entry; // Dictionary entry pointer uint64_t call_count; // Number of executions uint64_t total_time_ns; // Total time (DETAILED+) uint64_t min_time_ns; // Minimum time (DETAILED+) uint64_t max_time_ns; // Maximum time (DETAILED+) } WordStats; ---- ==== Frequency Tracking Function [source,c] ---- void profiler_word_count(const DictEntry *entry) { if (!profiler_state.enabled || !entry) return; WordStats *stats = get_word_stats(entry); if (stats) { stats->call_count++; } } ---- *Zero-overhead design:* * No timing calls (just counter increment) * O(1) lookup for existing entries * O(n) only on first call per word * Capacity: 256 unique words (expandable) ''''' === Advanced Usage ==== Profiling Specific Code Sections [source,forth] ---- \ Profile a specific algorithm : BENCHMARK-SECTION \ ... your code here ... ; \ Run multiple times for statistical significance : RUN-PROFILE 1000 0 DO BENCHMARK-SECTION LOOP ; RUN-PROFILE BYE ---- [source,bash] ---- ./build/starforth --profile 1 --profile-report < profile_test.fth ---- ==== Comparing Different Implementations *Version A:* [source,bash] ---- ./build/starforth --profile 1 --profile-report < version_a.fth > profile_a.txt ---- *Version B:* [source,bash] ---- ./build/starforth --profile 1 --profile-report < version_b.fth > profile_b.txt ---- Compare call counts and execution patterns to determine which implementation is more efficient. ==== Integration with CI/CD [source,bash] ---- #!/bin/bash # profile-ci.sh - Automated profiling in CI ./build/starforth --profile 1 --profile-report < test_suite.fth > profile_report.txt # Extract top 10 hot words grep -A 10 "Most Frequently Called" profile_report.txt > hot_words.txt # Check if any new hot words need optimization # (add logic to compare with baseline) ---- ''''' === Troubleshooting ==== Issue: "`No profiling data available`" *Cause:* Profiler not enabled or report flag missing *Solution:* [source,bash] ---- ./build/starforth --profile 1 --profile-report # Enable both flags ---- ==== Issue: Report shows 0 calls for all words *Cause:* No Forth code executed (BYE called immediately) *Solution:* Ensure your script executes Forth words before BYE ==== Issue: Profiler overhead too high *Cause:* Using PROFILE_DETAILED or PROFILE_VERBOSE *Solution:* Use PROFILE_BASIC (–profile 1) for minimal overhead ==== Issue: Missing words in report *Cause:* Profiler capacity limit reached (256 unique words) *Solution:* Profiler tracks first 256 unique words only. Primitive words always tracked. ''''' === Example Workflows ==== Workflow 1: Optimize a Recursive Function [source,bash] ---- # 1. Profile the recursive function cat > fib_test.fth <<'EOF' : FIB ( n -- fib ) DUP 2 < IF DROP 1 EXIT THEN DUP 1 - FIB SWAP 2 - FIB + ; 10 FIB . BYE EOF ./build/starforth --profile 1 --profile-report < fib_test.fth # 2. Identify hot words (DUP, <, DROP, -, +, SWAP) # 3. Implement assembly optimizations for top words # 4. Rebuild and verify performance gain ---- ==== Workflow 2: PGO-Guided Optimization [source,bash] ---- # 1. Build with profiling make clean make CFLAGS="-O2 -fprofile-generate" LDFLAGS="-fprofile-generate -lgcov" # 2. Run profiler to identify hot Forth words ./build/starforth --profile 1 --profile-report --run-tests > forth_profile.txt # 3. Run PGO workload ./scripts/pgo-workload.sh ./build/starforth # 4. Build optimized binary with both profile types make clean-obj make CFLAGS="-O3 -DUSE_ASM_OPT=1 -fprofile-use" LDFLAGS="-fprofile-use" # 5. Verify combined optimization ./build/starforth --benchmark 10000 ---- ''''' === Integration with Other Tools ==== With perf [source,bash] ---- # Combine StarForth profiler with Linux perf sudo perf record -g ./build/starforth --profile 1 --run-tests sudo perf report # C-level profiling # StarForth profiler shows Forth-level hot words # perf shows C-level hot functions ---- ==== With Valgrind [source,bash] ---- # Get instruction counts alongside word frequency valgrind --tool=callgrind ./build/starforth --profile 1 --benchmark 1000 kcachegrind callgrind.out.* ---- ==== With gprof [source,bash] ---- # Build with gprof make CFLAGS="-pg -O2" LDFLAGS="-pg" # Run with profiling ./build/starforth --profile 1 --run-tests # Generate reports gprof ./build/starforth gmon.out > gprof_report.txt ./build/starforth --profile 1 --profile-report --run-tests > forth_profile.txt ---- ''''' === API Reference ==== C API [source,c] ---- // Initialize profiler int profiler_init(ProfileLevel level); // Shutdown profiler void profiler_shutdown(void); // Track word execution (lightweight) void profiler_word_count(const DictEntry *entry); // Track word execution with timing void profiler_word_enter(const DictEntry *entry); void profiler_word_exit(const DictEntry *entry); // Generate reports void profiler_generate_report(void); void profiler_print_hotspots(void); // Reset profiling data void profiler_reset(void); ---- ==== Profiling Levels [source,c] ---- typedef enum { PROFILE_DISABLED = 0, // No profiling PROFILE_BASIC = 1, // Frequency tracking only PROFILE_DETAILED = 2, // + timing data PROFILE_VERBOSE = 3, // + stack/memory tracking PROFILE_FULL = 4 // Reserved for future use } ProfileLevel; ---- ''''' === Performance Impact [width="100%",cols="25%,13%,62%",options="header",] |=== |Level |Overhead |Use Case |PROFILE_DISABLED |0% |Production |PROFILE_BASIC |<1% |Always-on profiling, hot word identification |PROFILE_DETAILED |5-10% |Detailed timing analysis |PROFILE_VERBOSE |15-20% |Deep performance investigation |=== *Recommendation:* Use PROFILE_BASIC for continuous profiling, PROFILE_DETAILED for targeted optimization work. ''''' === Summary *Key Takeaways:* [arabic] . *Start with `+--profile 1 --profile-report+`* - Minimal overhead, maximum insight . *Focus on top 10 words* - Usually 80-95% of execution time . *Optimize words with ≥5% coverage* - Best ROI for assembly optimization . *Use PGO for 0.5-5% words* - Let compiler optimize based on profile data . *Combine with perf/valgrind* - Multi-level profiling for complete picture *Quick Reference:* [source,bash] ---- # Basic profiling ./build/starforth --profile 1 --profile-report < script.fth # Detailed timing ./build/starforth --profile 2 --profile-report < script.fth # Profile test suite ./build/starforth --profile 1 --profile-report --run-tests # Profile with benchmarks ./build/starforth --profile 1 --profile-report --benchmark 10000 ---- ''''' *End of Profiler Guide*