make stress-e2e (STRESS=1) imports an 8192x26 CSV with telemetry on, adds 200 SUMs over column A, and times arrow keys and entries from the write to the pty until the name box shows them; it checks the event log recorded the import, recalcs and frame summaries. On an M5 Pro: arrows p50 16.7 ms (one frame of Bubble Tea's 60 fps renderer), entries that recalculate the 200 SUMs p50 57 ms.
- commit
- 6176a98ff1acc0d45fdd526229a0cac1e7d44127
- parent
- 7cf7e0f4cb4a55931985821c3f35aa12c3435482
- author
- Dami <dami.etoile@gmail.com>
| A | e2e/ | 145 | ++++++++++++++++++++++++++++++ |
@@ -0,0 +1,145 @@
1+package e2e2+3+import (4+ "bufio"5+ "encoding/json"6+ "fmt"7+ "os"8+ "path/filepath"9+ "slices"10+ "strings"11+ "testing"12+ "time"13+)14+15+// TestStressKeyLatency imports an 8192x26 CSV with telemetry on, then16+// measures key press to screen through a real terminal: arrow keys, and17+// entries that recalculate 200 SUMs over a whole column. It checks the18+// latencies against a generous bound and that the event log recorded the19+// import, the recalcs and the frames. Slow, so only with STRESS=1 (make20+// stress-e2e); O12_E2E_LOG keeps the log, e.g. for the observability21+// stack.22+func TestStressKeyLatency(t *testing.T) {23+ if os.Getenv("STRESS") == "" {24+ t.Skip("set STRESS=1 to run")25+ }26+ dir := t.TempDir()27+ var b strings.Builder28+ for r := range 8192 {29+ for c := range 26 {30+ if c > 0 {31+ b.WriteByte(',')32+ }33+ fmt.Fprintf(&b, "%d.%02d", (r*31+c*7)%1000, (r+c)%100)34+ }35+ b.WriteByte('\n')36+ }37+ writeText(t, filepath.Join(dir, "big.csv"), b.String())38+ log := os.Getenv("O12_E2E_LOG")39+ if log == "" {40+ log = filepath.Join(dir, "events.jsonl")41+ }42+ s := startWith(t, options{dir: dir, cols: 200, rows: 60, env: []string{"O12_LOG=" + log}}, "big.csv")43+ s.waitFor("Imported big.csv (8,192 rows)")44+45+ // 200 formulas summing column A, in column AB (off screen).46+ s.keys("<f5>", "AB1", "<enter>")47+ s.waitForName("AB1")48+ for range 200 {49+ s.keys("=SUM(A1:A8192)", "<enter>")50+ }51+ s.keys("<f5>", "A1", "<enter>")52+ s.waitForName("A1")53+54+ arrows := s.latencies(60, func(i int) (string, string) {55+ if i%2 == 0 {56+ return "<down>", "A2"57+ }58+ return "<up>", "A1"59+ })60+ // Enter commits a number typed into A1, recalculating the 200 SUMs,61+ // and moves down; the next round goes back up first.62+ edits := s.latencies(20, func(i int) (string, string) {63+ if i > 0 {64+ s.keys("<up>")65+ s.waitForName("A1")66+ }67+ s.keys(fmt.Sprint(i%10))68+ s.waitForEntry(fmt.Sprint(i%10))69+ return "<enter>", "A2"70+ })71+ report(t, "arrow", arrows)72+ report(t, "edit", edits)73+ if p := pct(arrows, 95); p > 250*time.Millisecond {74+ t.Errorf("arrow key p95 %v", p)75+ }76+77+ s.keys("<ctrl+q>")78+ s.waitFor("You have unsaved changes.")79+ s.keys("d")80+ s.waitExit()81+ counts := events(t, log)82+ for _, ev := range []string{"start", "import", "recalc", "frames"} {83+ if counts[ev] == 0 {84+ t.Errorf("no %s events in %s: %v", ev, log, counts)85+ }86+ }87+ t.Logf("events: %v", counts)88+}89+90+// latencies presses n keys, each returned by next with the name box91+// text that shows it has been handled, and times each from the write92+// to the pty until the screen shows it.93+func (s *session) latencies(n int, next func(i int) (key, want string)) []time.Duration {94+ s.t.Helper()95+ var out []time.Duration96+ for i := range n {97+ key, want := next(i)98+ start := time.Now()99+ s.keys(key)100+ deadline := start.Add(waitTimeout)101+ for s.nameBox() != want {102+ if time.Now().After(deadline) {103+ s.t.Fatalf("waiting for %s after %s; screen:\n%s", want, key, s.screen())104+ }105+ time.Sleep(200 * time.Microsecond)106+ }107+ out = append(out, time.Since(start))108+ }109+ return out110+}111+112+// nameBox is the name box's text.113+func (s *session) nameBox() string {114+ l := s.line(barLine)115+ return strings.TrimSpace(l[:min(barX, len(l))])116+}117+118+func pct(ds []time.Duration, p int) time.Duration {119+ ds = slices.Clone(ds)120+ slices.Sort(ds)121+ return ds[max((len(ds)*p+99)/100-1, 0)]122+}123+124+func report(t *testing.T, what string, ds []time.Duration) {125+ t.Logf("%s: n=%d p50=%v p95=%v max=%v", what, len(ds), pct(ds, 50), pct(ds, 95), pct(ds, 100))126+}127+128+// events counts the event log's lines by event name.129+func events(t *testing.T, path string) map[string]int {130+ f, err := os.Open(path)131+ if err != nil {132+ t.Fatal(err)133+ }134+ defer f.Close()135+ counts := map[string]int{}136+ sc := bufio.NewScanner(f)137+ for sc.Scan() {138+ var ev struct{ Msg string }139+ if err := json.Unmarshal(sc.Bytes(), &ev); err != nil {140+ t.Fatalf("log line %q: %v", sc.Text(), err)141+ }142+ counts[ev.Msg]++143+ }144+ return counts145+}