diff --git a/docs/CHANGELOG.md b/docs/CHANGELOG.md index 26ed2a7e..f6fb1762 100644 --- a/docs/CHANGELOG.md +++ b/docs/CHANGELOG.md @@ -1,5 +1,16 @@ # Changelog +## 2026-10-15: post-TUI lag — re-investigation, timestamped recorder + +- **Status: root cause still unproven.** Not reproducible in fresh shells: a PTY harness (with and without a real zellij 0.45.1 session, fish 4.9.3, the real config and a copy of the real history) showed no echo-latency change after hx (with nixd/marksman/rumdl running), jjui, yazi, vim, less, lazygit or Claude Code, nor with huge history autosuggestions or concurrent history writers. +- New facts: + - Timeline: fish 4.8.0 first landed in the store on 2026-07-05 and the first lag fix attempt was 2026-08-08. 4.8.0 changed history timestamps/merging (fish #10300), which is the data autosuggestions search on every keystroke. + - Today's (2026-10-15) lag was in a 36-day-old fish **4.8.1** pane. 57 of 85 running fish processes are still 4.8.1 (started before 4.9.3 was installed on 2026-09-24); there is no evidence yet either way that 4.9.3 shells lag. Long-lived shells are the main difference from every failed reproduction. + - In the shell history, the command run right before a heal was `hx` in 4 of the 5 cases with usable context (Helix, not previously on the trigger list). +- Corrections to earlier entries: the thread-pool starvation theory (2026-08-31) is not supported. In all September flight logs every enqueued work item was picked up by a worker (2090/2090). The September logs had no timestamps, so they cannot show whether fish was slow to handle keys or the delay was downstream (zellij/ghostty). In most pre-heal windows fish handled keys one at a time with a repaint after each (no input backlog), which weakly points away from fish's input loop. +- Recorder upgrade (`zellij.nix` `fish-no-query-term`, `lag-triage/flight_filter.pl`): when `~/.local/state/lag-triage/RECORD` exists, new pane shells stream `FISH_DEBUG` through a FIFO into a Perl filter that adds millisecond timestamps and redacts typed/pasted content and command lines (the September logs contained pasted secrets in clear text). Added `reader-render`, `complete`, `autoload`, `history` and `uvar-notifier` categories. `config.fish` now drops `FISH_DEBUG`/`FISH_DEBUG_OUTPUT` so subshells and `fish -c` children no longer write into the recorder's path (they previously truncated the same log file). +- `heal-autosuggest` (Ctrl-b) now first copies the last 20k lines of the pane's timestamped log to `~/.local/state/lag-triage/episodes/`, so pressing it during a lag preserves the evidence. Next step: analyze the first episode (time from each `Read byte` to the following `Writing terminal command` decides fish-side versus downstream). + ## 2026-10-11 - **Configured `arrow` host for AWS EC2 deployment**: diff --git a/platforms/home-manager/modules/nmasur/presets/programs/lag-triage/default.nix b/platforms/home-manager/modules/nmasur/presets/programs/lag-triage/default.nix index 736db247..95d110e8 100644 --- a/platforms/home-manager/modules/nmasur/presets/programs/lag-triage/default.nix +++ b/platforms/home-manager/modules/nmasur/presets/programs/lag-triage/default.nix @@ -23,6 +23,17 @@ in home.packages = [ term-probe ]; + # The zellij pane wrapper (fish-no-query-term) exports FISH_DEBUG and + # FISH_DEBUG_OUTPUT so the pane shell records itself. fish reads them once + # at startup, so drop them here to keep subshells and `fish -c` children + # from writing into the recorder's FIFO path. + programs.fish.shellInit = lib.mkBefore '' + if set -q FISH_FLIGHT_LOG + set -e FISH_DEBUG + set -e FISH_DEBUG_OUTPUT + end + ''; + # Ctrl-b: EXECUTE the proven manual cure as a real commandline. The cure # is not the variable's end value (it starts and ends at 1) — it is the # reader fully exiting readline and re-entering, which only command @@ -60,8 +71,15 @@ in # execute it. Executing (not inline-setting) is what cures: it forces # the reader to leave and re-enter readline. Runs in place of whatever # is currently typed. + # When the flight recorder is armed, first copy the recent timestamped + # log so the lag that made you press Ctrl-b is preserved for analysis. body = # fish '' + if set -q FISH_FLIGHT_LOG; and test -f "$FISH_FLIGHT_LOG" + set -l dir ~/.local/state/lag-triage/episodes + mkdir -p $dir + tail -n 20000 $FISH_FLIGHT_LOG >$dir/episode-(date +%Y%m%d-%H%M%S)-$fish_pid.log + end commandline -r 'set -g fish_autosuggestion_enabled 0; and set -g fish_autosuggestion_enabled 1' commandline -f execute ''; diff --git a/platforms/home-manager/modules/nmasur/presets/programs/lag-triage/flight_filter.pl b/platforms/home-manager/modules/nmasur/presets/programs/lag-triage/flight_filter.pl new file mode 100644 index 00000000..ffc556a9 --- /dev/null +++ b/platforms/home-manager/modules/nmasur/presets/programs/lag-triage/flight_filter.pl @@ -0,0 +1,52 @@ +# Flight-recorder filter for fish's FISH_DEBUG stream (see fish-no-query-term +# in zellij.nix). Reads the FIFO fish writes its debug log to, prefixes every +# line with a millisecond wall-clock timestamp, and redacts anything typed or +# pasted so the always-on log never holds secrets. +# +# Timing is the whole point: the gap between "Read byte" and the following +# "Writing terminal command" is how long fish itself took to handle a key. If +# that gap stays small while the pane feels laggy, the delay is downstream of +# fish (zellij/ghostty), not in fish. +# +# Usage: perl flight_filter.pl +use strict; +use warnings; +use Time::HiRes qw(time); +use POSIX qw(strftime); + +my ($fifo, $logfile) = @ARGV; +open(my $in, '<', $fifo) or exit 1; +# fish has the FIFO open now; nothing else needs the path. +unlink $fifo; +open(my $out, '>>', $logfile) or exit 1; +$out->autoflush(1); + +# Commands worth naming in the log; everything else is redacted. +my $keep_cmd = qr/^(heal-autosuggest|set -g fish_autosuggestion_enabled|exec fish|lag-)/; + +while (my $line = <$in>) { + $line =~ s/\0//g; + # Keystrokes: keep control/escape identities, drop printable content. + if ($line =~ /^(reader: Read byte) (.*)$/) { + my ($prefix, $b) = ($1, $2); + $b = '' unless $b =~ /^\\(e|r|t|n|x[0-9a-fA-F]+)$/; + $line = "$prefix $b\n"; + } + elsif ($line =~ /^(reader: Read char) (\S+)/) { + my ($prefix, $k) = ($1, $2); + $k = '' + unless $k =~ /^(enter|tab|escape|backspace|delete|space|up|down|left|right|home|end)$|^(ctrl|alt|shift|super)-/; + $line = "$prefix $k\n"; + } + elsif ($line =~ /^reader: adding peeked /) { + $line = "reader: adding peeked \n"; + } + elsif ($line =~ /^reader: Found binding .*?commands: (\[[^\]]*\])/) { + $line = "reader: Found binding $1\n"; + } + $line =~ s/(Error while expanding string ).*/$1/; + $line =~ s/(CommandStart\(")(.*)("\))/$1 . ($2 =~ $keep_cmd ? $2 : '') . $3/e; + $line =~ s/(WindowTitle\().*(\))/$1$2/; + my $t = time; + printf $out "%s.%03d %s", strftime('%H:%M:%S', localtime $t), ($t - int $t) * 1000, $line; +} diff --git a/platforms/home-manager/modules/nmasur/presets/programs/zellij.nix b/platforms/home-manager/modules/nmasur/presets/programs/zellij.nix index bd61b191..2b183aa9 100644 --- a/platforms/home-manager/modules/nmasur/presets/programs/zellij.nix +++ b/platforms/home-manager/modules/nmasur/presets/programs/zellij.nix @@ -20,11 +20,14 @@ let # harness on fish 4.8.1 (see docs/CHANGELOG.md 2026-08-29 and # presets/programs/lag-triage/upstream_repro.py). Spawning fish with the # variable already exported makes every pane shell immune. - # Flight recorder for the still-unsolved post-TUI typing lag: sampling the - # process CURES the lag (a wedged thread gets kicked loose), so the only way - # to observe it is a recorder that is already running before the lag starts. - # Armed by `touch ~/.local/state/lag-triage/RECORD`; new panes then log - # fish's reader/thread internals to ~/.local/state/lag-triage/flight/. + # Flight recorder for the still-unsolved post-TUI typing lag: the lag only + # shows up in long-lived pane shells and has never reproduced in a fresh + # shell, so the recorder must already be running when it starts. + # Armed by `touch ~/.local/state/lag-triage/RECORD`; new panes then stream + # fish's debug log through flight_filter.pl, which adds millisecond + # timestamps (the September logs had none, which made them inconclusive) + # and redacts typed/pasted text. Ctrl-b (heal-autosuggest) snapshots the + # recent log into ~/.local/state/lag-triage/episodes/ before healing. # Remove the RECORD file to disable (zero overhead when off). fish-no-query-term = pkgs.writeShellScriptBin "fish-no-query-term" '' export fish_features=no-query-term @@ -32,8 +35,16 @@ let if [ -e "$dir/RECORD" ]; then mkdir -p "$dir/flight" find "$dir/flight" -type f -mtime +3 -delete 2>/dev/null - export FISH_DEBUG='reader,term-support,proc-termowner,iothread,fd-monitor,topic-monitor' - export FISH_DEBUG_OUTPUT="$dir/flight/fish-$(date +%Y%m%d-%H%M%S)-$$.log" + log="$dir/flight/fish-$(date +%Y%m%d-%H%M%S)-$$.log" + fifo="$dir/flight/.fifo-$$" + rm -f "$fifo" + if mkfifo -m 600 "$fifo"; then + # The filter exits on EOF once fish (this pid after exec) exits. + ${lib.getExe pkgs.perl} ${./lag-triage/flight_filter.pl} "$fifo" "$log" </dev/null >/dev/null 2>&1 & + export FISH_DEBUG='reader,reader-render,term-support,proc-termowner,iothread,fd-monitor,topic-monitor,complete,autoload,history,uvar-notifier' + export FISH_DEBUG_OUTPUT="$fifo" + export FISH_FLIGHT_LOG="$log" + fi fi exec ${lib.getExe pkgs.fish} "$@" '';