Profile

# Flemma Profiling Harness — Operator Guide

This document teaches you how to use the profiling harness in `contrib/profile/` to diagnose and fix per-keystroke performance problems in Flemma. It captures the methodology, not specific findings — those belong in commit messages and code comments.

---

## What This Harness Does

The harness measures **per-keystroke cost** of editing a `.chat` buffer in a real Neovim instance. It drives edits via `tmux send-keys` into a background Neovim window, collects three layers of profiling data, and compares `.chat` (Flemma loaded) against `.md` (treesitter only, no Flemma) to isolate Flemma's overhead.

The three profiling layers:

1. **jit.p** — LuaJIT's built-in sampling profiler. Samples the Lua call stack at 1ms intervals. Catches ALL Lua code: Flemma, treesitter, any plugin. Shows where CPU time goes as percentages.
2. **`:profile`** — Neovim's VimScript profiler. Captures VimScript function timing (autocmd dispatch, plugin overhead). Won't see inside Lua functions but shows which VimScript functions are expensive.
3. **Autocmd event timing** — Wall-clock time from each autocmd event fire to the next event loop tick (via `vim.schedule`). Shows the total cost of each event type including ALL handlers and the subsequent redraw.

## Files

| File | Purpose |
|---|---|
| `run.sh` | Main entry point. Launches two Neovim instances (`.md` baseline + `.chat` with Flemma), drives edits, collects results. |
| `init.lua` | Controlled Neovim init used with `--clean`. Only loads treesitter + optionally Flemma. No copilot, lualine, hexokinase, etc. |
| `instrument.lua` | Sourced inside the running Neovim. Activates jit.p, `:profile`, wraps Flemma functions, tracks autocmd events. |
| `generate-fixture.lua` | Generates `fixture.chat` — a synthetic ~5000-line `.chat` file with realistic structure (tool blocks, thinking, frontmatter, prose). |
| `fixture.chat` | The generated fixture (gitignored). Auto-generated by `run.sh` on first use; can also be regenerated manually. |
| `SKILL.md` | This file — operator guide for future sessions. |

Results are written to `.profile/<timestamp>/` (gitignored).

## Running the Harness

### Prerequisites

- **tmux** must be running (the harness creates background windows via `tmux new-window -d`)
- **nvim-treesitter** installed (discovered automatically from the host nvim)
- You must be in the repo root directory

### Basic Run

```bash
bash contrib/profile/run.sh
```

Uses the bundled `fixture.chat`. Output:

```
=== Flemma Profile Run: 20260511-173318 ===
...
Variant                     Avg ms/key       Max ms        Calls
-------                     ----------       ------        -----
baseline-md                    6.140 ms      15.12 ms        118
chat-flemma                   34.616 ms      78.84 ms        118
```

### Custom Input File

```bash
bash contrib/profile/run.sh ~/path/to/some.chat
```

### Regenerating the Fixture

```bash
nvim --headless --noplugin -u NONE --cmd 'set rtp^=.' \
  -l contrib/profile/generate-fixture.lua
```

The generator uses `math.randomseed(42)` for reproducibility. The fixture is gitignored and auto-generated by `run.sh` on first use — no need to regenerate manually unless you've modified the generator.

The generator includes a self-verification step: after writing the file, it re-reads it through Flemma's parser and confirms that all structural elements (tool_use, tool_result, thinking, frontmatter) are parsed correctly. If verification fails, the script exits with a non-zero code and prints which elements are missing. Example output:

```
Generated 4856 lines -> contrib/profile/fixture.chat
Verified:  messages=148  tool_use=32  tool_result=32  thinking=19  text=110  frontmatter=yes
All structural checks passed.
```

**Fixture structure rules**: Tool input JSON must match each tool's expected schema (grep needs `pattern`, bash needs `command`, etc.) or the fold text preview will fall back to the raw line. `<thinking>` blocks must be the LAST segment in assistant messages, matching how real providers emit them.

## Interpreting Results

### The Key Metric: `InsertCharPre` Average

This is the total wall-clock time from the `InsertCharPre` event firing to the next event loop tick. It includes:
- The character being inserted into the buffer
- All `TextChangedI` handlers firing
- All `CursorMovedI` handlers firing
- Treesitter re-highlighting the changed region
- Fold expression re-evaluation (if `foldmethod=expr`)
- Conceal recalculation (if `conceallevel > 0`)
- The redraw that renders the change to screen

**This is what the user feels as "typing lag."**

### Reading the Autocmd Event Table

```
Event                        Calls   Total ms     Avg ms     Max ms
-------------------------------------------------------------------
InsertCharPre                  118    4084.63     34.616      78.84
CursorHoldI                     96     377.46      3.932      43.06
CursorMovedI                   125       9.44      0.076       0.30
TextChangedI                   124       4.56      0.037       0.26
```

**Important**: The event timing uses `vim.schedule()` to measure wall-clock time from event fire to the next event loop tick. This means:

- `InsertCharPre` captures EVERYTHING that happens during a keystroke (all other events, redraw, fold eval, etc.). It's not just the cost of `InsertCharPre` handlers.
- `CursorMovedI` and `TextChangedI` fire WITHIN the same keystroke cycle as `InsertCharPre`. Their times may overlap or be subsets.
- `CursorHoldI` fires BETWEEN keystrokes (after `updatetime` ms of no typing). Its cost is separate from per-keystroke cost.
- High `CursorHoldI` cost means `update_ui` / `invalidate_folds` is expensive on pause.

### Reading the Function Timings Table

```
Function                                         Calls   Total ms     Avg ms     Max ms
---------------------------------------------------------------------------------------
parser.get_parsed_document                         617     995.84      1.614      18.08
parser.parse_lines                                 108     488.37      4.522      10.42
bridge.update_ui                                    94    1357.97     14.446      29.56
folding.get_fold_level                              47      18.50      0.394      18.46
```

- **`parser.get_parsed_document`** — called from foldexpr, update_ui, processor. High call count means multiple callers per event. Most calls are cache hits (check `parse_lines` count for actual parses).
- **`parser.parse_lines`** — actual full-buffer AST parses. Each costs ~2-5ms on a 5000-line buffer. The ratio `parse_lines / get_parsed_document` shows cache hit rate.
- **`bridge.update_ui` / `ui.update_ui`** — fires on CursorHold/CursorHoldI. Includes: parsing, fold invalidation, fold auto-close, line highlights, tool indicators, turn indicators.
- **`folding.get_fold_level`** — the foldexpr callback. Called for every visible line on each fold re-evaluation. Low total time despite high call count means the per-call cost is fine — the expensive part is Neovim's C-level fold engine processing the return values.
- **`folding.invalidate_folds`** — fires from `update_ui`. Rebuilds fold map + calls `set foldmethod=expr`. The `set foldmethod=expr` call is what triggers Neovim to re-evaluate all visible fold levels.

### Reading the jit.p Output

```
31%  fn
  -- 56%  highlighter.lua:360
  -- 29%  highlighter.lua:209
18%  (for generator)
  -- 94%  query.lua:1087
 8%  tcall
  -- 99%  languagetree.lua:208
 6%  add_rulers
  -- 64%  init.lua:58
```

- Top-level percentages show where CPU samples land. `fn`, `tcall`, `(for generator)` are LuaJIT internal categories.
- `highlighter.lua` = treesitter highlighting. `query.lua` = treesitter query evaluation. `languagetree.lua` = tree parsing.
- Flemma-specific functions appear by name (e.g., `add_rulers`, `run_text_handlers`, `emit_text`).
- The `.md` and `.chat` profiles should have similar treesitter percentages. If `.chat` has additional entries (like `parser.lua` or `init.lua`), those are Flemma's contribution.
- **jit.p only captures Lua execution time**, not Neovim C code. If jit.p shows 80% treesitter but the wall clock is 10x higher than expected, the remaining time is in Neovim's C rendering/fold engine.

### Reading the VimScript Profile

```
count  total (s)   self (s)  function
    6   0.473547             nvim_treesitter#indent()
  259   0.012189   0.010482  <SNR>16_Highlight_Matching_Pair()
    3   0.020382   0.019942  hexokinase#v2#scraper#on()
```

- Shows VimScript function costs. Neovim's built-in `matchparen`, `hexokinase`, and `nvim_treesitter#indent()` are common entries.
- `nvim_treesitter#indent()` is the `indentexpr` — fires on Enter/newline. Can cost 50-70ms per call on large buffers.
- Flemma's Lua functions don't appear here (they're Lua, not VimScript). This profile catches the VimScript wrapper cost.

## Methodology for Diagnosing Performance Issues

### Step 1: Establish Baselines

Run the harness as-is. Compare `.md` vs `.chat`. The delta is Flemma's total overhead. If `.md` is already slow, the issue is treesitter/Neovim, not Flemma.

### Step 2: Identify the Dominant Cost

Look at the function timings. Rank by total time:
- If `parser.parse_lines` dominates → too many full re-parses per keystroke
- If `bridge.update_ui` dominates → CursorHold work is too expensive
- If `folding.get_fold_level` dominates → foldexpr is doing expensive work per visible line
- If none of the Flemma functions are significant but the delta is large → the cost is in Neovim internals triggered by Flemma's settings (foldmethod, conceallevel, extmarks)

### Step 3: Isolate Individual Factors

To test a hypothesis, add a `run_profile` call to `run.sh`. Each call auto-registers itself in the `VARIANTS` array — the comparison table and full reports at the end pick it up automatically. No need to edit the reporting section.

The 4th argument is an optional ex command that runs after Neovim loads but before instrumentation starts. Use it to disable a specific Flemma feature or Neovim setting:

```bash
# Example: test with conceallevel=0
run_profile "chat-no-conceal" "chat" "yes" "set conceallevel=0"

# Example: test with foldexpr neutered
run_profile "chat-trivial-folds" "chat" "yes" \
  "lua require('flemma.ui.folding').get_fold_level = function() return '=' end"

# Example: test with update_ui disabled
run_profile "chat-no-ui" "chat" "yes" \
  "lua require('flemma.bridge').update_ui = function() end"

# Example: test with treesitter disabled
run_profile "chat-no-ts" "chat" "yes" "lua vim.treesitter.stop(0)"

# Example: source a Lua script for complex setup
run_profile "chat-patched" "chat" "yes" \
  "luafile contrib/profile/some-patch.lua"
```

Compare the `InsertCharPre` averages between variants. The delta tells you the cost of each factor. Keep the two core variants (`baseline-md`, `chat-flemma`) as the first entries — they're the control and treatment. Add experimental variants below them.

### Step 4: Verify the Fix

1. Stash or commit the fix
2. Run `make qa` — tests must pass
3. Run the harness — compare against the pre-fix baseline
4. The `.md` baseline should be unchanged (it's your control)
5. Report the improvement as a percentage reduction in avg and max

Include profiling numbers in the commit body:
```
Profiled with contrib/profile/ harness on a ~5000-line .chat buffer:
  Before: 122ms avg / 712ms max per keystroke
  After:   72ms avg / 299ms max per keystroke
```

## Critical Lessons Learned

### Headless Neovim Is NOT Representative

Early in the profiling work, we tried headless Neovim (`nvim --headless`) to measure performance. The results were misleading:

- `redraw` costs 57-191ms headlessly but only 18-29ms interactively
- CursorHold behavior differs (no real screen to render)
- Event timing is compressed (no real input delays)

**Always profile in a real tmux-driven session.** The harness exists precisely because headless profiling led us to chase the wrong bottleneck.

### `set foldmethod=expr` Is Expensive — Even With a Trivial Callback

Calling `set foldmethod=expr` forces Neovim to re-evaluate the foldexpr for every visible line (~300 on a typical screen). Even if `get_fold_level` returns instantly, Neovim's C-level fold engine must:
1. Call into Lua for each line (Lua↔C boundary cost)
2. Parse the return string (`>1`, `<1`, `=`, etc.)
3. Update the fold tree data structure
4. Recalculate which lines are visible/hidden

On a 5000-line buffer, this costs 50-100ms. If done on every CursorHold (every `updatetime` ms during typing pauses), it makes editing feel sluggish.

**Key insight**: Returning `"="` (fold level unchanged) from the foldexpr is drastically faster than returning actual fold levels, because Neovim can fast-path the "nothing changed" case. This is why deferring fold computation during insert mode works — `"="` for every line tells Neovim "don't touch the fold state."

### The User's Plugins Dominate in Uncontrolled Environments

When we first profiled with the user's full Neovim config, `.chat` buffers showed ~350ms per keystroke. After switching to the controlled init (treesitter only), the same buffer showed ~35ms. The 315ms difference came from copilot, hexokinase, lualine, autopairs, and other plugins — none of which are Flemma's responsibility.

**Always use the controlled init (`--clean -u contrib/profile/init.lua`) for profiling Flemma.** The user's full config is irrelevant for diagnosing Flemma-specific issues.

**Why `--clean` is mandatory, not optional**: Even `--noplugin` won't prevent Flemma from loading for `.chat` files if Flemma is installed system-wide (e.g., via NixOS home-manager or lazy.nvim). The `.chat` filetype triggers Flemma's `BufRead *.chat` autocmd, which runs `setup_folding`, sets `foldmethod=expr`, and registers all CursorHold handlers. The only way to get a clean baseline is `--clean` (which removes all user rtp entries) combined with the explicit treesitter path injection described below.

### Treesitter Path Discovery With `--clean`

`--clean` strips the user's runtimepath, so treesitter parsers and queries aren't findable. The harness solves this in two layers:

1. **run.sh** probes the host nvim (which HAS the user's rtp) to find `lua/nvim-treesitter/configs.lua`, extracts the plugin root, and exports it as `FLEMMA_PROFILE_TS_PATH`.
2. **init.lua** reads that env var and prepends it to rtp. As a fallback (for manual runs without run.sh), it also tries `nvim_get_runtime_file` directly — which works when nvim isn't fully `--clean` but just `--noplugin`.

### Fold Text Fallback Indicates a Preview Formatter Crash

If a folded tool_use or tool_result line shows the raw header text (e.g., `**Tool Use:** \`grep\` (\`toolu_...\`)`) instead of Flemma's styled preview (icon + name + path + content), it means the tool's `format_preview` function crashed. The error is caught by a pcall wrapper in `get_fold_text` and logged at WARN level. Check `~/.cache/nvim/flemma.log` for the specific error.

Common cause: the tool input JSON doesn't contain the fields the preview formatter expects (e.g., grep needs `pattern`, bash needs `command`). This happens with malformed LLM output or synthetic test data.

### Mode Checks and tmux send-keys

`tmux send-keys` feeds characters one at a time into Neovim. Each character is processed in its own event loop iteration. When checking `vim.api.nvim_get_mode().mode`:

- During a keystroke in insert mode, the mode IS `"i"` — mode checks work correctly
- Between keystrokes, the mode transitions briefly but returns to `"i"` for the next key
- `CursorHoldI` fires IN insert mode (mode is `"i"`) — this is important for guards that want to skip work during typing pauses

### `changedtick` Advances on Every Keystroke

`vim.api.nvim_buf_get_changedtick(bufnr)` increments on every buffer modification. If you use it as a cache key in a foldexpr callback, the cache will miss on EVERY keystroke, forcing a rebuild. This was the root cause of the original performance problem.

### Autocmd Event Timing Captures Everything

The `vim.schedule()` trick in `instrument.lua` measures wall-clock time from event fire to the next event loop tick. This means `InsertCharPre` timing includes the cost of ALL subsequent events (`TextChangedI`, `CursorMovedI`), all their handlers, treesitter re-highlighting, fold re-evaluation, and the redraw.

This is by design — it measures what the user perceives as input latency. But it means you can't sum up individual event times to get the total cost; they overlap.

### Parser Cache Hit Rate Matters

`parser.get_parsed_document` caches by `changedtick`. When called multiple times within the same event loop tick (same changedtick), only the first call parses; the rest are cache hits. The ratio `parse_lines calls / get_parsed_document calls` shows the cache effectiveness.

If `parse_lines` count equals `get_parsed_document` count, caching is broken. If `parse_lines` is ~1x per keystroke and `get_parsed_document` is ~4x, the cache is working (3 out of 4 calls are hits from different callers within the same tick).

### When Function Timings Don't Explain the Delta, Check the Buffer/Window Options

The report prints `Buffer/Window Options` (foldmethod, conceallevel, syntax, filetype, etc.) for every variant. These are the settings that differ between `.md` and `.chat`. If the profiled Flemma functions account for far less time than the `InsertCharPre` delta, the cost is in Neovim's C-level rendering triggered by one of those settings — jit.p can't see C code, so the time appears "missing."

Compare the options block between baseline and chat variants. The setting that's different is your suspect. Add ONE isolation variant that resets that setting and re-run.

For deeper investigation into Neovim's C rendering (`src/nvim/drawline.c`, `src/nvim/decoration.c`, `src/nvim/drawscreen.c`), clone the source if not already present:

```bash
[ -d contrib/neovim.git ] || git clone --depth 1 https://github.com/neovim/neovim.git contrib/neovim.git
```

## Modifying the Harness

### Adding a New Wrapped Function

In `instrument.lua`, add a `wrap()` call:

```lua
wrap("flemma.some.module", "function_name", "module.function_name")
```

The third argument is the label that appears in the report.

### Changing the Typing Pattern

In `run.sh`, the three editing phases simulate frontmatter editing, mid-file insertion, and end-of-file appending. To test a specific scenario (e.g., editing inside a tool result block), modify the phase commands:

```bash
# Navigate to a specific line
$send ':150' Enter; sleep 0.3
$send 'o'; sleep 0.2
type_string "$pane" "your test text here"
```

### Adding More Tracked Events

In `instrument.lua`, add event names to the tracked events list:

```lua
for _, ev in ipairs({
  "TextChanged", "TextChangedI", -- ...existing...
  "WinScrolled", "DiagnosticChanged", -- ...new ones...
}) do
```

### Changing the jit.p Sampling Parameters

In `instrument.lua`, the `jitp.start()` call controls sampling:

```lua
jitp.start("fli1", JITP_OUT)
--         ^^^^
-- f = flat profile (vs "F" for tree)
-- l = include file:line info
-- i1 = sample every 1ms (vs "i10" for 10ms)
```

Use `"Fli1"` for a tree/call-graph profile instead of flat.

## Relationship to `make qa`

The profiling harness is NOT part of `make qa`. It's a manual diagnostic tool. Performance regressions are caught by running the harness before and after a change, not by automated tests.

A future goal is to add a `make profile` target that runs the harness and fails if `InsertCharPre` average exceeds a threshold. The infrastructure is ready for this — the harness exits cleanly and writes machine-readable results to `.profile/`.