BenchmarkSessions opens 10 or 50 sessions over their own connections, optionally each on a 1000 x 26 sheet, and times keys to frames while every session types at once, with heap per session and CPU per frame. Latency stays at Bubble Tea's frame pacing (p95 16.6 ms) from 10 to 50 sessions; a session holds about 1.3 MiB, mostly render buffers.
- commit
- 92ff13232dac807d7f1c00c991f04c67d6687d20
- parent
- 69c6ae51414aae558ec11877e507acc47d7f074e
- author
- Dami <dami.etoile@gmail.com>
| M | docs/ | 35 | +++++++- |
| M | internal/ | 12 | ++- |
| A | internal/ | 151 | ++++++++++++++++++++++++++++++ |
@@ -29,6 +29,7 @@ it lags, and past a second it stalls.
2929 | JEV | Up to about 1000 JEV cells: 0.3 ms of CPU per answer | 4000 JEV cells: 1.3 ms per answer, 5 s of CPU to answer them all | | Every answer recalculates every JEV cell (they're volatile) |3030 | Formula depth | 10,000 nested parentheses or IFs: under 5 ms | | No explicit limit; recursion grows the stack | Recursive parser and evaluator |3131 | Find, filter, sort, fill | Filter or sort 8191 rows: 1 to 32 ms; find over 213 k cells: 38 ms; fill 8192 rows: 4 ms | Replace all over 213 k cells: 280 ms | | Per-cell string conversion and regexp |32+| SSH sessions (`012 serve`) | 50 sessions typing at once: frames within one frame interval (p95 16.6 ms), 1.3 MiB per session plus its sheets (upper bound) | | More than `--max-sessions` (8 by default): turned away | Bubble Tea's 60 fps pacing; per session, the terminal's cell buffers |3233 3334 ## Sheet size3435 @@ -187,6 +188,37 @@ Cell reads now go through one more function call to resolve the sheet,
187188 which is most of the 3 to 5% on read-heavy shapes; undo steps key their188189 before-images by sheet and address, which is BigUndo's extra allocation.189190 191+## Serving over SSH192+193+`BenchmarkSessions` (`internal/serve/stress_test.go`) opens N sessions,194+each over its own SSH connection on loopback at 120 x 40, optionally195+opening the same 1000 x 26 sheet of numbers in every one, then has every196+session press an arrow key at once, 200 times, timing each key from the197+client's write to the first bytes of its frame arriving. The clients198+run in the same process, so the heap and CPU figures include their side199+of the connections and are upper bounds for the server. Medians of 3200+runs, `-benchtime 200x`:201+202+| Sessions, sheet | Heap per session | Key to frame p50 / p95 / max | CPU per frame |203+|---|---|---|---|204+| 10, new sheet | 1.30 MiB | 10.7 / 16.6 / 17.1 ms | 0.95 ms |205+| 10, 1000 x 26 numbers | 8.5 MiB | 11.2 / 16.6 / 18.0 ms | 1.15 ms |206+| 50, new sheet | 1.30 MiB | 9.2 / 16.3 / 19.2 ms | 0.53 ms |207+| 50, 1000 x 26 numbers | 8.5 MiB | 9.4 / 16.7 / 20.5 ms | 0.69 ms |208+209+Latency doesn't move from 10 to 50 sessions: it's Bubble Tea's frame210+pacing (at most one frame every 16.7 ms, so a key waits half a frame on211+average), not load. A heap profile with 50 sessions open212+(`SERVE_HEAP_PROFILE=file`) puts three quarters of a session's heap in213+Bubble Tea's render buffers (about 1 MiB at 120 x 40, growing with the214+window), 130 KiB in its input key table and under 50 KiB in both ends215+of the SSH connection, so the figure is close to the server's own. On216+top come about 300 B per cell of the sheets a session has open;217+sessions opening the same file each hold a copy. CPU per frame covers both ends of the connection (the218+encryption twice, the client reading the frame); at 0.7 ms, 50 sessions219+typing continuously at 60 frames a second would keep about two cores220+busy.221+190222 ## Hotspots found and fixed191223 192224 Each with its benchmark before and after, in the commit that fixed it.@@ -271,7 +303,8 @@ fast. They live in `internal/sheet/stress_test.go` (engine),
271303 `internal/sheet/hotpath_stress_test.go` (parsing and number formats),272304 `internal/ui/stress_test.go` (View, frames, keystrokes, JEV, telemetry273305 overhead), `internal/fileio/stress_test.go` (imports and exports),274-`internal/chart/stress_test.go` (charts as text and images) and306+`internal/chart/stress_test.go` (charts as text and images),307+`internal/serve/stress_test.go` (concurrent SSH sessions) and275308 `e2e/stress_test.go`; the synthetic sheets are built by276309 `internal/stress`. Results accumulate in `.deps/stress/results` and, with277310 the observability stack up, in ClickHouse.@@ -93,6 +93,7 @@ type term struct {
9393 mu sync.Mutex9494 out bytes.Buffer9595 done chan error96+ wrote chan struct{} // signalled after output arrives9697 }9798 9899 func openTerm(t testing.TB, c *gossh.Client, w, h int) *term {@@ -104,7 +105,7 @@ func openTerm(t testing.TB, c *gossh.Client, w, h int) *term {
104105 if err := sess.RequestPty("xterm-256color", h, w, gossh.TerminalModes{}); err != nil {105106 t.Fatal(err)106107 }107- tm := &term{sess: sess, done: make(chan error, 1)}108+ tm := &term{sess: sess, done: make(chan error, 1), wrote: make(chan struct{}, 1)}108109 tm.stdin, _ = sess.StdinPipe()109110 sess.Stdout = tm110111 if err := sess.Shell(); err != nil {@@ -116,8 +117,13 @@ func openTerm(t testing.TB, c *gossh.Client, w, h int) *term {
116117 117118 func (tm *term) Write(p []byte) (int, error) {118119 tm.mu.Lock()119- defer tm.mu.Unlock()120- return tm.out.Write(p)120+ n, err := tm.out.Write(p)121+ tm.mu.Unlock()122+ select {123+ case tm.wrote <- struct{}{}:124+ default:125+ }126+ return n, err121127 }122128 123129 func (tm *term) output() string {@@ -0,0 +1,151 @@
1+//go:build stress && unix2+3+// Stress benchmark of 012 serve: many sessions at once, each over its own4+// SSH connection on loopback, measuring the heap each session holds, the5+// time from a key press leaving the client to the frame answering it6+// arriving back while every session types at once, and the CPU spent per7+// frame. The clients run in the same process, so heap and CPU include8+// their side of the connections: upper bounds for the server. Only built9+// with -tags stress (see `make stress` and docs/limits.md).10+package serve11+12+import (13+ "fmt"14+ "io"15+ "os"16+ "path/filepath"17+ "runtime"18+ "runtime/pprof"19+ "slices"20+ "sync"21+ "syscall"22+ "testing"23+ "time"24+25+ "github.com/FelineStateMachine/012/internal/stress"26+)27+28+func BenchmarkSessions(b *testing.B) {29+ for _, n := range []int{10, 50} {30+ for _, shape := range []string{"empty", "dense-1000x26"} {31+ b.Run(fmt.Sprintf("sessions=%d/%s", n, shape), func(b *testing.B) { benchSessions(b, n, shape) })32+ }33+ }34+}35+36+func benchSessions(b *testing.B, n int, shape string) {37+ key := newKey(b)38+ srv, addr, dir := testServer(b, func(o *Options) { o.MaxSessions, o.IdleTimeout = n, 0 }, key)39+ if shape != "empty" {40+ writeDense(b, filepath.Join(dir, "dense.012"))41+ }42+ before := liveHeap()43+ terms := make([]*term, n)44+ for i := range terms {45+ c, err := dial(addr, key, srv.HostKey())46+ if err != nil {47+ b.Fatal(err)48+ }49+ b.Cleanup(func() { c.Close() })50+ terms[i] = openTerm(b, c, 120, 40)51+ terms[i].waitFor(b, "READY")52+ if shape != "empty" {53+ io.WriteString(terms[i].stdin, "\x0fdense\r") // Ctrl+O dense54+ terms[i].waitFor(b, "dense.012")55+ }56+ }57+ perSession := float64(liveHeap()-before) / float64(n) / 102458+ if path := os.Getenv("SERVE_HEAP_PROFILE"); path != "" {59+ // What the sessions hold, while they're open.60+ f, err := os.Create(path)61+ if err != nil {62+ b.Fatal(err)63+ }64+ pprof.WriteHeapProfile(f)65+ f.Close()66+ }67+68+ // Every session presses a key at once, b.N times; each waits for its69+ // frame.70+ keys := []string{"\x1b[B", "\x1b[A"} // down, up71+ var mu sync.Mutex72+ var lat []time.Duration73+ cpu := cpuTime()74+ b.ResetTimer()75+ for i := 0; i < b.N; i++ {76+ var wg sync.WaitGroup77+ for _, tm := range terms {78+ wg.Go(func() {79+ d := tm.press(b, keys[i%2])80+ mu.Lock()81+ lat = append(lat, d)82+ mu.Unlock()83+ })84+ }85+ wg.Wait()86+ }87+ b.StopTimer()88+ b.ReportMetric(float64((cpuTime()-cpu).Microseconds())/float64(b.N*n), "cpu_us/frame")89+ b.ReportMetric(perSession, "KiB/session")90+ slices.Sort(lat)91+ b.ReportMetric(ms(lat[len(lat)/2]), "p50_ms")92+ b.ReportMetric(ms(lat[len(lat)*95/100]), "p95_ms")93+ b.ReportMetric(ms(lat[len(lat)-1]), "max_ms")94+}95+96+// press sends k and returns how long the first bytes of the answering97+// frame took to arrive.98+func (tm *term) press(b *testing.B, k string) time.Duration {99+ tm.mu.Lock()100+ had := tm.out.Len()101+ tm.mu.Unlock()102+ select { // forget output that arrived before the key103+ case <-tm.wrote:104+ default:105+ }106+ start := time.Now()107+ io.WriteString(tm.stdin, k)108+ timeout := time.After(10 * time.Second)109+ for {110+ select {111+ case <-tm.wrote:112+ tm.mu.Lock()113+ grew := tm.out.Len() > had114+ tm.mu.Unlock()115+ if grew {116+ return time.Since(start)117+ }118+ case <-timeout:119+ b.Fatal("no frame after a key press")120+ }121+ }122+}123+124+func writeDense(b *testing.B, path string) {125+ f, err := os.Create(path)126+ if err != nil {127+ b.Fatal(err)128+ }129+ defer f.Close()130+ if err := stress.Dense(1000, 26).Write(f); err != nil {131+ b.Fatal(err)132+ }133+}134+135+// cpuTime is the CPU time the process has used, user and system.136+func cpuTime() time.Duration {137+ var ru syscall.Rusage138+ syscall.Getrusage(syscall.RUSAGE_SELF, &ru)139+ return time.Duration(ru.Utime.Nano() + ru.Stime.Nano())140+}141+142+// liveHeap is the heap in use after a full collection.143+func liveHeap() int64 {144+ runtime.GC()145+ runtime.GC()146+ var m runtime.MemStats147+ runtime.ReadMemStats(&m)148+ return int64(m.HeapAlloc)149+}150+151+func ms(d time.Duration) float64 { return float64(d.Microseconds()) / 1000 }