diff --git a/.claude/skills/ux/references/findings.md b/.claude/skills/ux/references/findings.md index c5c4711f94..25c59b9d1f 100644 --- a/.claude/skills/ux/references/findings.md +++ b/.claude/skills/ux/references/findings.md @@ -255,3 +255,37 @@ checklist.md or motion.md as well. the answers; a send no receiver took says "Not delivered to : " with a Send again button, for every kind of agent (`resend-answers`). Rule: a send reports what the receiver confirmed, never what was attempted, and every not-delivered result offers the retry in place. +- 2026-10-24 18:09 — **The hover list closed under a scrolling pointer, and the scroll went to the window below.** + Under the Glass theme the gaps between session rows were not part of the panel: SwiftUI does not hit-test Liquid + Glass itself, so with the pointer still, each gap that scrolled under it read as "the pointer left", and 220 ms later + the preview closed. Solid themes never showed it (their fill is hit-tested). A window-server probe + (`SLSFindWindowAndOwner`) showed the window did own those points, which ruled out click-through; synthetic taps in a + scratch window then showed taps on the gap reaching nothing. Fix: the glass surfaces take `.contentShape` of their + shape (`NativeGlassShapeSurface`, `NativeGlassControl`, `WidgetGlassControl`). Rule: a glass panel is tested with a + click between its rows, not only on them. +- 2026-10-24 18:09 — **A session was "missing" from the list because it showed under its first prompt.** Claude Code + names a session itself (`ai-title` lines, the name its /resume list and the terminal tab show); the history reader + knew only `custom-title` and the old `summary`, so the row read "pls /genesis-tools:research with xhigh…" while + Martin looked for "Kalendora hotfix research". Fix: `ai-title` is the summary (a `/rename` still wins), parser + version 6. Rule: a row's title is the name the user sees for that thing elsewhere. +- 2026-10-24 18:09 — **"Loading this session's inbox…" on every switch, and the pane shrank and grew back.** The cards + came only with a snapshot naming the session: a `hub widget call` process (330 ms), the watch's 180 ms debounce, the + snapshot (65 to 105 ms). Fix: every snapshot carries the cards of up to 16 sessions that need you (`warmKeys`), the + widget caches each session it saw (`WidgetSessionCache`), the pick goes to the watch's stdin at once, the pane keeps + its height while a never-seen session loads, and nearby messages show the last read while a fresh one runs. Rule: a + switch shows what is known at once and lets the fresh data replace it. +- 2026-10-24 19:43 — **Correction to the 18:09 hover-list entry: the glass gaps were not the cause.** Inside a ScrollView the gaps + between rows are hit-tested under plain glass too (probe: row and gap reach the panel; only a blank part outside the + scroll view does not), so the contentShape fix never touched this bug, and the list kept closing (19:01:00 to + 19:01:38, three times while Martin scrolled). What closes it is SwiftUI's `.onHover` reporting "left" with the + pointer still on the panel. Fix: the panel's window decides "pointer inside" by geometry (an NSTrackingArea on + `EdgePanelRootView`), and SwiftUI's hover only logs `widget.hover swiftui-left … under it: ` when it + disagrees. Rule: a window-level "pointer inside" comes from the window's geometry, never from a hit test, and a fix + is not done until the user's own repro stops. +- 2026-10-24 19:43 — **A bug that is a burst of processes was invisible to every watcher.** Genesis Markdown started one + `tools agents blame` per open note on every repository refresh: 51 to 66 at once, about 9,300 an hour, load average + 380-580 and launchservicesd at 69-159%, while its log held a blame line only when one run was slow. Fix: one blame per + repository for every note that asked (`AgentBlameQueue`), and GenesisKit's `SpawnMeter` writes `spawn.storm` to the + perf log when 40 children start within 10 s or 16 run at once; `tools hub dev monitor` reports it and now also + reads Genesis Markdown's `~/.genesis/logs/perf.log`. Rule: work that starts processes per item is queued per shared + resource, and the launcher counts what it starts. diff --git a/src/hub/commands/dev.ts b/src/hub/commands/dev.ts index ea72f8dd68..b26bf71c4b 100644 --- a/src/hub/commands/dev.ts +++ b/src/hub/commands/dev.ts @@ -64,7 +64,7 @@ export function registerDevCommands(program: Command): void { ) .action(async (flags: MonitorFlags) => { const sources = devMonitorSources(); - const start = `[${new Date().toTimeString().slice(0, 8)}] monitor watching ${sources.perfLog}, ${sources.profileLog()}, ${sources.relayLog}, ${sources.hangs}, ${sources.crashes}`; + const start = `[${new Date().toTimeString().slice(0, 8)}] monitor watching ${sources.perfLog}, ${sources.genesisPerfLog}, ${sources.profileLog()}, ${sources.relayLog}, ${sources.hangs}, ${sources.crashes}`; out.print(`${flags.json ? SafeJSON.stringify({ kind: "start", text: start }) : start}\n`); await withInterrupt((signal) => runDevMonitor({ diff --git a/src/hub/lib/dev-monitor.test.ts b/src/hub/lib/dev-monitor.test.ts index b9d62a6400..5865c65bc7 100644 --- a/src/hub/lib/dev-monitor.test.ts +++ b/src/hub/lib/dev-monitor.test.ts @@ -1,5 +1,5 @@ import { describe, expect, spyOn, test } from "bun:test"; -import { mkdtempSync, rmSync, writeFileSync } from "node:fs"; +import { mkdirSync, mkdtempSync, rmSync, writeFileSync } from "node:fs"; import { tmpdir } from "node:os"; import { join } from "node:path"; import { @@ -53,6 +53,52 @@ describe("classifyPerfLine", () => { ).toBe("hang"); }); + test("a burst of child processes is an event; only ongoing lines share a source-specific key", () => { + expect( + classifyPerfLine( + "[19:26:02.100] mark spawn.storm 51 child processes started in 10 s, 49 running; GenesisTools agents blame ×51" + ) + ).toMatchObject({ kind: "storm", time: "19:26:02.100", key: undefined }); + const ongoing = "[19:26:32.100] mark spawn.storm ongoing 30 s: 400 child processes started"; + expect(classifyPerfLine(ongoing, DEFAULT_CLASSIFY, "/tools/hangs")?.key).toBe("/tools/hangs:storm:ongoing"); + expect(classifyPerfLine(ongoing, DEFAULT_CLASSIFY, "/genesis/hangs")?.key).toBe("/genesis/hangs:storm:ongoing"); + expect(classifyPerfLine("[19:26:33.100] mark spawn.storm over after 30 s")?.key).toBeUndefined(); + }); + + test("a Genesis Markdown line carries its tag, and its hang sample lives in its own folder", () => { + const event = classifyPerfLine( + "[17:12:43.850] [md] mark main-stall 1.0s so far — sampling to hang-2026-10-23-171243.txt recent=[x]", + DEFAULT_CLASSIFY, + "/home/fixture/.genesis/logs/hangs" + ); + expect(event).toMatchObject({ + kind: "hang", + file: "/home/fixture/.genesis/logs/hangs/hang-2026-10-23-171243.txt", + text: "[md] main-stall 1.0s so far — sampling to hang-2026-10-23-171243.txt", + }); + expect(classifyPerfLine("[17:11:59.681] [md] mark main-stall recovered after 1806ms load=159")?.kind).toBe( + "stall" + ); + }); + + test("tagged helper events remain distinct from otherwise identical parent events", () => { + for (const body of [ + "spawn.storm ongoing 30 s: 100 child processes started", + "main-spin 5s at 99% cpu: the main thread never idles", + "main-stall recovered after 1806ms", + ]) { + const parent = classifyPerfLine(`[10:00:00] mark ${body}`, DEFAULT_CLASSIFY, "/genesis/hangs"); + const helper = classifyPerfLine(`[10:00:00] [md] mark ${body}`, DEFAULT_CLASSIFY, "/genesis/hangs"); + expect(parent?.text).toBe(body); + expect(helper?.text).toBe(`[md] ${body}`); + expect(helper?.kind).toBe(parent?.kind); + + if (parent && helper) { + expect(collapse([parent, helper])).toHaveLength(2); + } + } + }); + test("a main thread spinning at full CPU is an event, and its sample names the file", () => { expect(classifyPerfLine("[17:10:32.100] mark main-spin 5s at 99% cpu: the main thread never idles")?.kind).toBe( "spin" @@ -258,3 +304,112 @@ test("log tails read bounded chunks without losing lines or UTF-8 at chunk bound rmSync(dir, { recursive: true, force: true }); } }); + +test("both perf tails retain their storm updates and endings in a batch", async () => { + const dir = mkdtempSync(join(tmpdir(), "monitor-storm-")); + const sources = monitorFixtureSources(dir); + const batches: DevEvent[][] = []; + const controller = new AbortController(); + writeFileSync( + sources.perfLog, + [ + "[10:00:00] mark spawn.storm ongoing 30 s: 100 child processes started", + "[10:00:01] mark spawn.storm ongoing 60 s: 200 child processes started", + "[10:00:02] mark spawn.storm over after 60 s", + "[10:00:03] mark spawn.storm over after 1 s", + "", + ].join("\n") + ); + writeFileSync( + sources.genesisPerfLog, + [ + "[10:00:00] mark spawn.storm ongoing 30 s: 250 child processes started", + "[10:00:00] [md] mark spawn.storm ongoing 30 s: 300 child processes started", + "[10:00:02] [md] mark spawn.storm over after 30 s", + "", + ].join("\n") + ); + + try { + await runDevMonitor({ + ...DEFAULT_CLASSIFY, + sources, + fromStart: true, + intervalMs: 100, + minDelayMs: 0, + signal: AbortSignal.any([controller.signal, AbortSignal.timeout(2000)]), + emit: (events) => { + batches.push(events); + controller.abort(); + }, + }); + expect(batches).toHaveLength(1); + expect(batches[0].map((event) => event.text)).toEqual([ + "spawn.storm ongoing 60 s: 200 child processes started (×2)", + "spawn.storm over after 60 s", + "spawn.storm over after 1 s", + "Genesis: spawn.storm ongoing 30 s: 250 child processes started", + "Genesis: [md] spawn.storm ongoing 30 s: 300 child processes started", + "Genesis: [md] spawn.storm over after 30 s", + ]); + expect(batches[0][0].time).toBe("10:00:01"); + } finally { + rmSync(dir, { recursive: true, force: true }); + } +}); + +test("a logged hang in one app cannot suppress the other app's same-named unannounced hang", async () => { + const dir = mkdtempSync(join(tmpdir(), "monitor-hangs-")); + const sources = monitorFixtureSources(dir); + const name = "hang-2026-01-01-100000.txt"; + const batches: DevEvent[][] = []; + const controller = new AbortController(); + writeFileSync(sources.perfLog, `[10:00:00] mark main-stall 1s so far sampling to ${name}\n`); + + try { + await runDevMonitor({ + ...DEFAULT_CLASSIFY, + sources, + fromStart: true, + intervalMs: 100, + minDelayMs: 0, + signal: AbortSignal.any([controller.signal, AbortSignal.timeout(2000)]), + emit: (events) => { + batches.push(events); + if (batches.length === 1) { + writeFileSync(join(sources.hangs, name), "logged sample"); + writeFileSync(join(sources.genesisHangs, name), "unannounced sample"); + } else { + controller.abort(); + } + }, + }); + expect(batches).toHaveLength(2); + expect(batches[0]).toHaveLength(1); + expect(batches[0][0].file).toBe(join(sources.hangs, name)); + expect(batches[1]).toHaveLength(1); + expect(batches[1][0]).toMatchObject({ + kind: "hang", + file: join(sources.genesisHangs, name), + text: "a hang sample was written with no app-perf.log line", + }); + } finally { + rmSync(dir, { recursive: true, force: true }); + } +}); + +function monitorFixtureSources(dir: string) { + const sources = { + perfLog: join(dir, "app-perf.log"), + genesisPerfLog: join(dir, "perf.log"), + genesisHangs: join(dir, "genesis-hangs"), + profileLog: () => join(dir, "profiling.log"), + relayLog: join(dir, "relay.log"), + hangs: join(dir, "hangs"), + crashes: join(dir, "crashes"), + }; + for (const folder of [sources.hangs, sources.genesisHangs, sources.crashes]) { + mkdirSync(folder); + } + return sources; +} diff --git a/src/hub/lib/dev-monitor.ts b/src/hub/lib/dev-monitor.ts index ccc70ec504..2e0e260562 100644 --- a/src/hub/lib/dev-monitor.ts +++ b/src/hub/lib/dev-monitor.ts @@ -27,7 +27,8 @@ export interface DevEvent { | "error" | "relay" | "crash" - | "slow"; + | "slow" + | "storm"; /** The time the source line carries ("01:46:40.479"), or the file's time for a crash or a hang file. */ time: string; text: string; @@ -138,24 +139,45 @@ export function shortCommand(command: string): string { const timePattern = /^\[(\d\d:\d\d:\d\d(?:\.\d+)?)\]\s*/; -/** An app-perf.log line as an event, or null for the routine ones (spans, marks, quick stalls). */ -export function classifyPerfLine(line: string, options: ClassifyOptions = DEFAULT_CLASSIFY): DevEvent | null { +/** + * A perf log line as an event, or null for the routine ones (spans, marks, quick stalls). GenesisTools writes + * app-perf.log; Genesis Markdown writes `~/.genesis/logs/perf.log`, its lines tagged after the time (`[md] mark …`), + * and its hang samples go to `hangsDir`. + */ +export function classifyPerfLine( + line: string, + options: ClassifyOptions = DEFAULT_CLASSIFY, + hangsDir = genesisToolsDir("logs", "hangs") +): DevEvent | null { const time = line.match(timePattern)?.[1] ?? ""; - const body = line.replace(timePattern, "").replace(/^mark\s+/, ""); - const short = (text: string) => text.replace(/ recent=\[.*$/, "").slice(0, 300); + const message = line.replace(timePattern, ""); + const tag = message.match(/^(\[[a-z-]+\])\s+/)?.[1] ?? ""; + const body = message.replace(/^\[[a-z-]+\]\s+/, "").replace(/^mark\s+/, ""); + const short = (text: string) => `${tag ? `${tag} ` : ""}${text.replace(/ recent=\[.*$/, "")}`.slice(0, 300); if (/WEDGED|main-stall ongoing/.test(body)) { return { kind: "wedge", time, text: short(body) }; } + // A burst of child processes (GenesisKit `SpawnMeter`): one blame per open note was 9,300 launches an hour. + if (/^spawn\.storm /.test(body)) { + const source = tag ? `${hangsDir}:${tag}` : hangsDir; + return { + kind: "storm", + time, + text: short(body), + key: /^spawn\.storm ongoing\b/.test(body) ? `${source}:storm:ongoing` : undefined, + }; + } + const sampled = body.match(/main-(?:stall|spin) .*sampling to (\S+)/); if (sampled) { - return { kind: "hang", time, text: short(body), file: genesisToolsDir("logs", "hangs", sampled[1]) }; + return { kind: "hang", time, text: short(body), file: join(hangsDir, sampled[1]) }; } const stacks = body.match(/main-stall stacks .*→ (\S+)/); if (stacks) { - return { kind: "hang", time, text: short(body), file: genesisToolsDir("logs", "hangs", stacks[1]) }; + return { kind: "hang", time, text: short(body), file: join(hangsDir, stacks[1]) }; } // A main thread that never idles (an update loop) never delays a ping, so HangWatch reports it by CPU time. @@ -330,6 +352,8 @@ class FolderWatch { } export interface DevMonitorOptions extends ClassifyOptions { + /** Override the watched paths, for an isolated monitor or fixture. */ + sources?: ReturnType; /** Replay what the logs already hold instead of starting at their end. */ fromStart: boolean; /** How often the files are read. */ @@ -372,7 +396,7 @@ export class EventBatcher { } } -/** Events with one key become the first of them plus "×N, max …", in the place of the first. */ +/** Events with one key share a count and any measured maximum; storm updates retain their latest state. */ export function collapse(events: DevEvent[]): DevEvent[] { const groups = new Map(); const result: DevEvent[] = []; @@ -402,8 +426,10 @@ export function collapse(events: DevEvent[]): DevEvent[] { return event; } - const max = Math.max(...group.map((item) => item.ms ?? 0)); - return { ...event, text: `${event.text} (×${group.length}, max ${(max / 1000).toFixed(2)}s)` }; + const latest = event.kind === "storm" ? group[group.length - 1] : event; + const durations = group.flatMap((item) => (item.ms === undefined ? [] : [item.ms])); + const maximum = durations.length > 0 ? `, max ${(Math.max(...durations) / 1000).toFixed(2)}s` : ""; + return { ...latest, text: `${latest.text} (×${group.length}${maximum})` }; }); } @@ -411,6 +437,9 @@ export function collapse(events: DevEvent[]): DevEvent[] { export function devMonitorSources() { return { perfLog: genesisToolsDir("logs", "app-perf.log"), + /** Genesis and Genesis Markdown, which share GenesisKit's hang watcher and spawn meter. */ + genesisPerfLog: join(homedir(), ".genesis", "logs", "perf.log"), + genesisHangs: join(homedir(), ".genesis", "logs", "hangs"), profileLog: () => genesisToolsDir("logs", `${formatLocalDate(new Date())}-profiling.log`), relayLog: genesisToolsDir("app", "link-relay.log"), hangs: genesisToolsDir("logs", "hangs"), @@ -420,8 +449,9 @@ export function devMonitorSources() { /** Runs until `signal` aborts. Reads by interval: app-perf.log is written by several processes at once. */ export async function runDevMonitor(options: DevMonitorOptions): Promise { - const sources = devMonitorSources(); + const sources = options.sources ?? devMonitorSources(); const perf = new TextTail(sources.perfLog, options.fromStart); + const genesisPerf = new TextTail(sources.genesisPerfLog, options.fromStart); const relay = new TextTail(sources.relayLog, options.fromStart); const profile = new TextTail(sources.profileLog, options.fromStart); const crashes = new FolderWatch(sources.crashes, (name) => /^Genesis/.test(name) && /\.(ips|crash)$/.test(name)); @@ -429,18 +459,27 @@ export async function runDevMonitor(options: DevMonitorOptions): Promise { // process could not log any more, which is the case worth a separate event. // `.txt` only: the daily pass stores captures older than yesterday as `hang-….txt.zst`, which is not a new hang. const hangs = new FolderWatch(sources.hangs, (name) => name.startsWith("hang-") && name.endsWith(".txt")); + const genesisHangs = new FolderWatch( + sources.genesisHangs, + (name) => name.startsWith("hang-") && name.endsWith(".txt") + ); const announced = new Set(); const batcher = new EventBatcher(options.minDelayMs, options.emit); while (!options.signal.aborted) { - for (const line of perf.read()) { - const event = classifyPerfLine(line, options); - if (event) { - if (event.file) { - announced.add(basename(event.file)); - } + for (const [tail, hangsDir, app] of [ + [perf, sources.hangs, ""], + [genesisPerf, sources.genesisHangs, "Genesis: "], + ] as const) { + for (const line of tail.read()) { + const event = classifyPerfLine(line, options, hangsDir); + if (event) { + if (event.file) { + announced.add(event.file); + } - batcher.add(event); + batcher.add({ ...event, text: app + event.text }); + } } } @@ -455,8 +494,8 @@ export async function runDevMonitor(options: DevMonitorOptions): Promise { } } - for (const path of hangs.fresh()) { - if (!announced.has(basename(path))) { + for (const path of [...hangs.fresh(), ...genesisHangs.fresh()]) { + if (!announced.has(path)) { batcher.add({ kind: "hang", time: "", diff --git a/src/macos/GenesisKit/Sources/GenesisKit/Tools/ToolsLineStream.swift b/src/macos/GenesisKit/Sources/GenesisKit/Tools/ToolsLineStream.swift index 902911ca3f..51315493e8 100644 --- a/src/macos/GenesisKit/Sources/GenesisKit/Tools/ToolsLineStream.swift +++ b/src/macos/GenesisKit/Sources/GenesisKit/Tools/ToolsLineStream.swift @@ -138,10 +138,15 @@ public final class ToolsLineStream: @unchecked Sendable { } self.lock.unlock() } + let ended = SpawnMeter.started(executable: process.executableURL, arguments: process.arguments ?? []) process.terminationHandler = { [weak self] _ in + ended() self?.finish(exited: true) } - try process.run() + do { try process.run() } catch { + ended() + throw error + } priority.applyNice(to: process.processIdentifier) } diff --git a/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift b/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift new file mode 100644 index 0000000000..994d9c6855 --- /dev/null +++ b/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift @@ -0,0 +1,126 @@ +import Foundation + +/// Counts the child processes this app starts and writes a `spawn.storm` line to the perf log when they come in a +/// burst, so `tools hub dev monitor` reports it. A burst that hurts the Mac can be invisible otherwise: Genesis +/// Markdown started about 9,300 `tools agents blame` an hour, 51 to 66 at once (2026-10-24, load average 380-580, +/// launchservicesd at 69-159%), and its log held one line per blame only when a single run was slow. +public enum SpawnMeter { + private static let lock = NSLock() + nonisolated(unsafe) private static var storm = SpawnStorm() + + /// Records that a child started; call the returned closure once when it has ended. + public static func started(executable: URL?, arguments: [String]) -> @Sendable () -> Void { + let label = label(executable: executable, arguments: arguments) + let lines = lock.withLock { storm.start(label, at: CFAbsoluteTimeGetCurrent()) } + lines.forEach { PerfLog.mark($0) } + return { + let lines = lock.withLock { storm.finish(at: CFAbsoluteTimeGetCurrent()) } + lines.forEach { PerfLog.mark($0) } + } + } + + /// What a child is, in two or three words: `git status`, `GenesisTools agents blame`. Paths and options are left out, + /// except that a launcher argument `…/gt-agents` names the tool (`agents`). + public static func label(executable: URL?, arguments: [String]) -> String { + var words = [executable?.lastPathComponent ?? "?"] + var skipValue = false + for argument in arguments where words.count < 3 { + if skipValue { + skipValue = false + continue + } + if argument == "-C" || argument == "-c" || argument == "--git-dir" { + skipValue = true + continue + } + let name = (argument as NSString).lastPathComponent + if argument.contains("/"), name.hasPrefix("gt-") { + words.append(String(name.dropFirst(3))) + } else if !argument.contains("/"), !argument.hasPrefix("-"), !argument.isEmpty, !isRevision(argument) { + words.append(argument) + } + } + return words.joined(separator: " ") + } + + /// A commit id or a revision built on one (`96c986d3^{commit}`, `HEAD~2`), which would split one command's count. + private static func isRevision(_ argument: String) -> Bool { + let base = argument.prefix { $0 != "^" && $0 != "~" && $0 != ":" } + return base.count >= 7 && base.allSatisfy(\.isHexDigit) || base == "HEAD" + } +} + +/// The burst rule, apart from the clock and the log: `burstStarts` starts within `window` seconds, or `burstRunning` +/// children at once. Reporting is event-driven: a burst is reported when it starts, on the first start or finish +/// after `reportEvery` seconds while it lasts, and when it ends: +/// at the first start or finish that finds it quiet, timed to its last start, so quiet minutes are not counted. +/// The hub opening a pull request starts about 24 in 10 s with 5 running (2026-10-24 19:45), which is normal; the blame +/// waves had 51 to 66 running. +public struct SpawnStorm { + public static let burstStarts = 40 + public static let burstRunning = 16 + public static let window: TimeInterval = 10 + public static let reportEvery: TimeInterval = 30 + + private var starts: [(at: Double, label: String)] = [] + private var running = 0 + private var since: Double? + private var lastStart = 0.0 + private var lastReport = -Double.infinity + private var counts: [String: Int] = [:] + private var total = 0 + + public init() {} + + public mutating func start(_ label: String, at now: Double) -> [String] { + prune(now) + var lines = endIfQuiet().map { [$0] } ?? [] + running += 1 + starts.append((now, label)) + if since != nil { + total += 1 + counts[label, default: 0] += 1 + lastStart = now + if let ongoing = reportIfDue(at: now) { lines.append(ongoing) } + return lines + } + guard starts.count >= Self.burstStarts || running >= Self.burstRunning else { return lines } + since = now + lastStart = now + lastReport = now + total = starts.count + counts = starts.reduce(into: [:]) { $0[$1.label, default: 0] += 1 } + lines.append("spawn.storm \(starts.count) child processes started in \(Int(Self.window)) s, \(running) running; \(top)") + return lines + } + + public mutating func finish(at now: Double) -> [String] { + running = max(0, running - 1) + prune(now) + if let ended = endIfQuiet() { return [ended] } + return reportIfDue(at: now).map { [$0] } ?? [] + } + + private mutating func reportIfDue(at now: Double) -> String? { + guard let since, now - lastReport >= Self.reportEvery else { return nil } + lastReport = now + return "spawn.storm ongoing \(Int(now - since)) s: \(total) child processes started, \(running) running; \(top)" + } + + private mutating func endIfQuiet() -> String? { + guard let since, running < Self.burstRunning / 2, starts.count < Self.burstStarts / 2 else { return nil } + self.since = nil + defer { counts = [:]; total = 0 } + return "spawn.storm over after \(Int(lastStart - since)) s: \(total) child processes started; \(top)" + } + + private mutating func prune(_ now: Double) { + starts.removeAll { now - $0.at > Self.window } + } + + /// The commonest children first: `GenesisTools agents blame ×51, git status ×3`. + private var top: String { + counts.sorted { $0.value == $1.value ? $0.key < $1.key : $0.value > $1.value }.prefix(3) + .map { "\($0.key) ×\($0.value)" }.joined(separator: ", ") + } +} diff --git a/src/macos/GenesisKit/Sources/GenesisKitBase/Tools/ProcessCapture.swift b/src/macos/GenesisKit/Sources/GenesisKitBase/Tools/ProcessCapture.swift index f7c9bc5f16..a9f19ca2f5 100644 --- a/src/macos/GenesisKit/Sources/GenesisKitBase/Tools/ProcessCapture.swift +++ b/src/macos/GenesisKit/Sources/GenesisKitBase/Tools/ProcessCapture.swift @@ -40,14 +40,31 @@ extension Process { mergeStderr: Bool = false, timeout: TimeInterval = 60, afterStart: (() -> Void)? = nil + ) throws -> ProcessCapture { + try runCapturing(mergeStderr: mergeStderr, timeout: timeout, afterStart: afterStart, + meterStarted: { SpawnMeter.started(executable: $0, arguments: $1) }) + } + + func runCapturing( + mergeStderr: Bool, + timeout: TimeInterval, + afterStart: (() -> Void)?, + meterStarted: (URL?, [String]) -> @Sendable () -> Void ) throws -> ProcessCapture { let out = Pipe() let err: Pipe? = mergeStderr ? nil : Pipe() standardOutput = out standardError = err ?? out let exited = DispatchSemaphore(value: 0) - terminationHandler = { _ in exited.signal() } - try run() + let ended = meterStarted(executableURL, arguments ?? []) + terminationHandler = { _ in + ended() + exited.signal() + } + do { try run() } catch { + ended() + throw error + } let outReader = PipeReader(out, stream: "stdout") let errReader = err.map { PipeReader($0, stream: "stderr") } afterStart?() diff --git a/src/macos/GenesisKit/Sources/GenesisKitBase/Tools/ToolsBridge.swift b/src/macos/GenesisKit/Sources/GenesisKitBase/Tools/ToolsBridge.swift index 2468d4ed01..ee6743e1d0 100644 --- a/src/macos/GenesisKit/Sources/GenesisKitBase/Tools/ToolsBridge.swift +++ b/src/macos/GenesisKit/Sources/GenesisKitBase/Tools/ToolsBridge.swift @@ -305,10 +305,15 @@ public struct ToolsBridge: Sendable { let stdout = try ToolsPipeCollector(outPipe) let stderr = try ToolsPipeCollector(errPipe) let exit = ToolsProcessExit() - process.terminationHandler = { _ in exit.finish() } + let ended = SpawnMeter.started(executable: process.executableURL, arguments: process.arguments ?? []) + process.terminationHandler = { _ in + ended() + exit.finish() + } do { try process.run() } catch { + ended() stdout.stop(error) stderr.stop(error) throw error diff --git a/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift b/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift index c669ba4fd8..d7f04f421d 100644 --- a/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift +++ b/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift @@ -96,3 +96,88 @@ final class AgentBlameModelTests: XCTestCase { XCTAssertNil(model.source(forLines: 0 ... 2)) } } + +/// The spawn meter's burst rule and labels (`SpawnMeter`), which put a burst of child processes into the perf log. +final class SpawnStormTests: XCTestCase { + func testABurstIsReportedWhenItStartsWhileItLastsAndWhenItEnds() { + var storm = SpawnStorm() + let burst = SpawnStorm.burstStarts + for index in 0..<(burst - 1) { + XCTAssertEqual(storm.start("GenesisTools agents blame", at: Double(index) * 0.1), [], "under the burst size: quiet") + XCTAssertEqual(storm.finish(at: Double(index) * 0.1 + 0.05), []) + } + let first = storm.start("git status", at: Double(burst - 1) * 0.1) + XCTAssertEqual(first.count, 1) + XCTAssertTrue(first.first?.hasPrefix("spawn.storm \(burst) child processes started in 10 s") == true, first.first ?? "none") + XCTAssertTrue(first.first?.contains("GenesisTools agents blame ×\(burst - 1), git status ×1") == true, first.first ?? "none") + _ = storm.finish(at: Double(burst - 1) * 0.1 + 0.05) + + // It goes on at 4 starts a second: one "ongoing" line after 30 s, none before. + var ongoing: [String] = [] + var now = 4.0 + while now < 35 { + ongoing += storm.start("git status", at: now) + ongoing += storm.finish(at: now + 0.01) + now += 0.25 + } + XCTAssertEqual(ongoing.count, 1, ongoing.joined(separator: "\n")) + XCTAssertTrue(ongoing.first?.hasPrefix("spawn.storm ongoing 30 s") == true, ongoing.first ?? "none") + + // Minutes of quiet, then one child: it ends the burst, timed to the burst's last start (20:31 to 20:35 read + // "over after 209 s" for a 10 s burst before). + let over = storm.start("git status", at: 300) + XCTAssertEqual(over.count, 1) + XCTAssertTrue(over.first?.hasPrefix("spawn.storm over after 30 s") == true, over.first ?? "none") + XCTAssertEqual(storm.finish(at: 300.1), [], "the quiet child after it starts no new burst") + } + + func testFinishesReportAnOngoingConcurrencyStormWithoutMoreStarts() { + var storm = SpawnStorm() + for _ in 0..