lag-triage: timestamped, redacted flight recorder with heal-time episode snapshots

2026-10-18 21:39:54 +00:00 · 2026-10-17 13:11:32 -04:00
parent 33c426bc8e
commit bc43f3dfaf
4 changed files with 99 additions and 7 deletions
@@ -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
          '';
@@ -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 <fifo> <logfile>
+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 = '<printable>' 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 = '<printable>'
+          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 <redacted>\n";
+    }
+    elsif ($line =~ /^reader: Found binding .*?commands: (\[[^\]]*\])/) {
+        $line = "reader: Found binding $1\n";
+    }
+    $line =~ s/(Error while expanding string ).*/$1<redacted>/;
+    $line =~ s/(CommandStart\(")(.*)("\))/$1 . ($2 =~ $keep_cmd ? $2 : '<cmd>') . $3/e;
+    $line =~ s/(WindowTitle\().*(\))/$1<title>$2/;
+    my $t = time;
+    printf $out "%s.%03d %s", strftime('%H:%M:%S', localtime $t), ($t - int $t) * 1000, $line;
+}
@@ -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} "$@"
  '';