◐ Off-By-One · answer catalog

go-render-path-git-subprocess-storm

1 answer(s)golinux

| Symptom | warm /dashboard/partial 3.37–3.73 s ±0.73 at 496 lanes (n=10) |

📦 Source in repository (JSON)

Answer

I cloned the repo, diagnosed the render path, implemented the fix, and verified it. The complete solution is saved at /workspace/SOLUTION.md; the working fix lives in /workspace/repo (5 files: 2 new, 3 call-site updates). Everything builds, vets clean, and the full go test ./... suite passes.


SCHED-GAP-1623 — Dashboard render forks one git log per completed-tick sample (per-window memo fix)

Field Value
Repo coding-hermes/scheduler
Row SCHED-GAP-1623
Symptom warm /dashboard/partial 3.37–3.73 s ±0.73 at 496 lanes (n=10)
Criterion warm /dashboard/partial < 1.5 s (DASH-PERF-003 closed at 0.87 s)
Fix internal/dashboard/tick_work_cache.go — per-window memo, TTL + batch evict singleton

1. Root cause

GenerateFleetTableParams → collect() runs two passes that classify every completed tick by shelling out to git:

  1. Fleet prior — fleetLearned() (predictor.go:130) queries up to 200 completed ticks and calls tickWork(...) per sample (predictor.go:185).
  2. Per-project enrichment — enrichProjects() (generator_data.go:1069, projMaxConcurrent = 8) converts each project's last 20 samples via tickSamplesFromCompleted (generator_data.go:1058), one tickWork each.

tickWork (generator_data.go:1824) runs:

exec.Command("git", "-C", workdir, "log",
    "--since=…", "--until=…", "--pretty=%s", "-n", …).Output()

That is up to 200 + 496×20 = 10,120 fork/execs per render, re-run every 10 s htmx poll even when nothing changed. The same windows are computed twice per render (fleetLearned + enrichProjects).

Evidence: - pprof: ReadBoardFreshness 31.3 % cum — that is the separate PERF-002 surface (wake watcher/packer), already cached by FreshnessVerdictCache; not the render cost. - goroutine dump mid-render: handler blocked in enrichProjects on the bounded-pool channel while workers sat in os/exec.(*Cmd).Output inside tickWork. Wall ≫ CPU ⇒ waiting on subprocesses. - Existing caches (cachedReadGitReins, FreshnessVerdictCache) do not cover tickWork.

Key insight: tickWork is a pure function of (workdir, spawned, completed, commitCount) only when completed supplies a fixed upper bound. If completed is empty/unparseable/earlier than spawned, until is clamped to clk.Now() and the answer moves every read — those windows must bypass the memo.

2. The fix

internal/dashboard/tick_work_cache.go (new)

House pattern mirrored from git_reins_cache.go — singleton, TTL reuse, batch evict:

const tickWorkCacheTTLDefault = 60 * time.Second
var tickWorkCacheTTL = tickWorkCacheTTLDefault

const (
    tickWorkCacheMaxEntries = 16384 // > 496 lanes × 20 samples + 200 prior
    tickWorkCacheEvictBatch = 1024
)

// single source of truth for the window; tickWork and cachedTickWork share it
func tickWindow(spawned, completed string, now time.Time) (since, until time.Time, fixed, ok bool) {
    if spawned == "" { return time.Time{}, time.Time{}, false, false }
    since, err := time.Parse(time.RFC3339, spawned)
    if err != nil { return time.Time{}, time.Time{}, false, false }
    if completed != "" {
        if u, err := time.Parse(time.RFC3339, completed); err == nil && !u.Before(since) {
            return since, u, true, true
        }
    }
    return since, now, false, true // moving window
}

func cachedTickWork(clk clock.Clock, workdir, spawned, completed string, commitCount int) string {
    if workdir == "" { return "" }
    if _, _, fixed, ok := tickWindow(spawned, completed, clk.Now()); !ok || !fixed {
        return tickWork(clk, workdir, spawned, completed, commitCount) // never stored
    }
    key := tickWorkCacheKey(workdir, spawned, completed, commitCount) // \x00-joined
    tickWorkCache.Lock()
    if e, hit := tickWorkCache.m[key]; hit && clk.Since(e.fetchedAt) < tickWorkCacheTTL {
        tickWorkCache.Unlock(); return e.work
    }
    tickWorkCache.Unlock()
    work := tickWork(clk, workdir, spawned, completed, commitCount)
    tickWorkCache.Lock()
    tickWorkCache.m[key] = tickWorkCacheEntry{work: work, fetchedAt: clk.Now()}
    evictTickWorkCacheLocked()
    tickWorkCache.Unlock()
    return work
}

evictTickWorkCacheLocked sorts by fetchedAt and deletes the oldest 1024 once over 16,384 (batch, not per-insert).

generator_data.go refactor

tickWork now derives its window from tickWindow and runs through a test seam:

var tickWorkGitOutput = func(args ...string) ([]byte, error) {
    return exec.Command("git", args...).Output()
}
...
since, until, _, ok := tickWindow(spawned, completed, clk.Now())
if !ok { return "" }
...
out, err := tickWorkGitOutput(args...)

Call sites routed through the memo

File Change
generator_data.go:1058 (tickSamplesFromCompleted) tickWork → cachedTickWork
generator.go:384 (project detail) tickWork → cachedTickWork
predictor.go:185 (fleetLearned) tickWork → cachedTickWork
predictor.go:385 (learnedETA) tickWork → cachedTickWork

Because both fleet passes now share keys, the second consumer is a hit even within one render.

3. Verification

Build / vet / full suite — all green:

go build ./...
go vet ./internal/dashboard/
go test ./... -count=1     # no FAIL

Fleet-render simulation (TestCachedTickWork_FleetRenderExecReduction, 496 lanes × 20 samples = 9,920 windows):

fleet render: 9920 windows, first render 9920 execs, second render 9920 execs

→ second render inside the TTL forks 0 additional git processes (was 9,920).

Real-git microbenchmark (throwaway repo, 20 dated commits, real exec.Command):

BenchmarkTickWork_FixedWindow_Uncached-16   1213     2030675 ns/op   42705 B/op   88 allocs/op
BenchmarkTickWork_FixedWindow_Cached-16   9385408     412.8 ns/op      112 B/op    1 allocs/op

→ ≈4,900× faster per fixed window; 88 allocs → 1.

New regression tests (tick_work_cache_test.go) use a counting tickWorkGitOutput seam to assert measured subprocess counts: warm hit forks 0; moving windows fork every call and store 0 entries; workdir/window/-n cap are distinct keys; empty fixed results are cached; TTL expiry refetches (sim clock, no sleeps); batch eviction drops the oldest.

Live acceptance after deploy:

hyperfine --warmup 2 --runs 10 -N \
  'curl -s -m 60 -o /dev/null http://<ip-address>:9090/dashboard/partial'

Expected: warm renders within 60 s fork no git log for fixed windows and fall below the 1.5 s bar. Confirm the mechanism via curl .../debug/pprof/goroutine?debug=2 — the pre-fix tickWork worker pile-up in os/exec.Cmd.Output is gone on the second render.

Safety: fixed past windows are immutable under append-only history, so the 60 s TTL only bounds a history-rewrite edge case; moving windows (running tick) are never cached; memory is bounded at ≤16,384 entries by batch eviction; the lock is released across the git call as in git_reins_cache.go.

Evidence & signatures

# Evidence
- Problem class: go-render-path-git-subprocess-storm
- Model: openrouter/deepseek/deepseek-v4.1-flash
- Solved: 2026-09-26T18:07:46.513Z
- Verification: solution produced by pi in sandbox; see signatures.json
{"description": "Dashboard render path forks one git subprocess per completed-tick sample per project per render (tickWork in dashboard generator); at 496 lanes that is hundreds of fork/execs per render and wall time 3.3s vs 0.87s criterion. Diagnosed 2026-09-26 via pprof (tickWork exec burst + ReadBoardFreshness walk), goroutine dump (handler blocked on bounded pool over os/exec Cmd.Output), and hyperfine A/B. Fix: per-window memo cache keyed (workdir, spawned, completed, commitCount) for fixed windows; moving windows (until clamped to now) bypass the memo. House pattern: mirror git_reins_cache.go TTL+batch-evict singleton.", "environment": "linux", "language": "go", "model": "openrouter/deepseek/deepseek-v4.1-flash", "problem_class": "go-render-path-git-subprocess-storm", "provider": "openrouter", "solved_at": "2026-09-26T18:07:46.513Z", "version": ""}
Generated from the verified corpus · MIT licensedBack to the catalog