From 3efed059e8ee1e1306f6e0125c42a4d7dd243909 Mon Sep 17 00:00:00 2001 From: Martin Date: Sat, 24 Oct 2026 19:44:54 +0200 Subject: [PATCH 1/6] feat(GenesisKit, GenesisHub, hub): a burst of child processes is logged as spawn.storm (24 starts in 10 s or 12 running, with the commonest commands) by GenesisKit's launchers, and tools hub dev monitor reports it and reads Genesis Markdown's perf log and hangs too --- src/hub/commands/dev.ts | 2 +- src/hub/lib/dev-monitor.test.ts | 26 +++++ src/hub/lib/dev-monitor.ts | 63 ++++++++--- .../GenesisKit/Tools/ToolsLineStream.swift | 7 +- .../GenesisKitBase/Perf/SpawnMeter.swift | 101 ++++++++++++++++++ .../GenesisKitBase/Tools/ProcessCapture.swift | 2 + .../GenesisKitBase/Tools/ToolsBridge.swift | 7 +- .../Diff/AgentBlameModelTests.swift | 41 +++++++ 8 files changed, 232 insertions(+), 17 deletions(-) create mode 100644 src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift 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..358a27d6ff 100644 --- a/src/hub/lib/dev-monitor.test.ts +++ b/src/hub/lib/dev-monitor.test.ts @@ -53,6 +53,32 @@ describe("classifyPerfLine", () => { ).toBe("hang"); }); + test("a burst of child processes is an event; its ongoing and over lines collapse into one", () => { + 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 }); + expect(classifyPerfLine("[19:26:32.100] mark spawn.storm ongoing 30 s: 400 child processes started")?.key).toBe( + "storm" + ); + }); + + 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", + }); + expect(classifyPerfLine("[17:11:59.681] [md] mark main-stall recovered after 1806ms load=159")?.kind).toBe( + "stall" + ); + }); + 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" diff --git a/src/hub/lib/dev-monitor.ts b/src/hub/lib/dev-monitor.ts index ccc70ec504..3cc0536f78 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 body = line + .replace(timePattern, "") + .replace(/^\[[a-z-]+\]\s+/, "") + .replace(/^mark\s+/, ""); const short = (text: string) => 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)) { + return { + kind: "storm", + time, + text: short(body), + key: /^spawn\.storm (ongoing|over)/.test(body) ? "storm" : 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. @@ -411,6 +433,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"), @@ -422,6 +447,7 @@ export function devMonitorSources() { export async function runDevMonitor(options: DevMonitorOptions): Promise { const 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 +455,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(basename(event.file)); + } - batcher.add(event); + batcher.add({ ...event, text: app + event.text }); + } } } @@ -455,7 +490,7 @@ export async function runDevMonitor(options: DevMonitorOptions): Promise { } } - for (const path of hangs.fresh()) { + for (const path of [...hangs.fresh(), ...genesisHangs.fresh()]) { if (!announced.has(basename(path))) { batcher.add({ kind: "hang", 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..27e692fc91 --- /dev/null +++ b/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift @@ -0,0 +1,101 @@ +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 line = lock.withLock { storm.start(label, at: CFAbsoluteTimeGetCurrent()) } + if let line { PerfLog.mark(line) } + return { + let line = lock.withLock { storm.finish(at: CFAbsoluteTimeGetCurrent()) } + if let line { PerfLog.mark(line) } + } + } + + /// 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 == "--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 { + words.append(argument) + } + } + return words.joined(separator: " ") + } +} + +/// The burst rule, apart from the clock and the log: `burstStarts` starts within `window` seconds, or `burstRunning` +/// children at once. A burst is reported when it starts, every `reportEvery` seconds while it lasts, and when it ends. +public struct SpawnStorm { + public static let burstStarts = 24 + public static let burstRunning = 12 + 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 lastReport = -Double.infinity + private var counts: [String: Int] = [:] + private var total = 0 + + public init() {} + + public mutating func start(_ label: String, at now: Double) -> String? { + running += 1 + starts.append((now, label)) + prune(now) + if let since { + total += 1 + counts[label, default: 0] += 1 + guard now - lastReport >= Self.reportEvery else { return nil } + lastReport = now + return "spawn.storm ongoing \(Int(now - since)) s: \(total) child processes started, \(running) running; \(top)" + } + guard starts.count >= Self.burstStarts || running >= Self.burstRunning else { return nil } + since = now + lastReport = now + total = starts.count + counts = starts.reduce(into: [:]) { $0[$1.label, default: 0] += 1 } + return "spawn.storm \(starts.count) child processes started in \(Int(Self.window)) s, \(running) running; \(top)" + } + + public mutating func finish(at now: Double) -> String? { + running = max(0, running - 1) + prune(now) + 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(now - 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..38f6cb10fa 100644 --- a/src/macos/GenesisKit/Sources/GenesisKitBase/Tools/ProcessCapture.swift +++ b/src/macos/GenesisKit/Sources/GenesisKitBase/Tools/ProcessCapture.swift @@ -48,6 +48,8 @@ extension Process { let exited = DispatchSemaphore(value: 0) terminationHandler = { _ in exited.signal() } try run() + let ended = SpawnMeter.started(executable: executableURL, arguments: arguments ?? []) + defer { ended() } 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..2441fc89a3 100644 --- a/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift +++ b/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift @@ -96,3 +96,44 @@ 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() + var lines: [String] = [] + for index in 0..<(SpawnStorm.burstStarts - 1) { + XCTAssertNil(storm.start("GenesisTools agents blame", at: Double(index) * 0.1), "under the burst size: quiet") + _ = storm.finish(at: Double(index) * 0.1 + 0.05) + } + if let line = storm.start("git status", at: 2.4) { lines.append(line) } + XCTAssertEqual(lines.count, 1) + XCTAssertTrue(lines[0].hasPrefix("spawn.storm 24 child processes started in 10 s"), lines[0]) + XCTAssertTrue(lines[0].contains("GenesisTools agents blame ×23, git status ×1"), lines[0]) + + XCTAssertNil(storm.start("git status", at: 3), "no second line within 30 s") + XCTAssertTrue(storm.start("git status", at: 33)?.hasPrefix("spawn.storm ongoing 30 s") == true) + // The first finish once the window holds few starts and few children run ends it. + let over = storm.finish(at: 40) + XCTAssertTrue(over?.hasPrefix("spawn.storm over after 37 s: 26 child processes started") == true, over ?? "nil") + XCTAssertNil(storm.finish(at: 41)) + XCTAssertNil(storm.start("git status", at: 61), "a quiet start after the burst ended") + } + + func testManyChildrenRunningAtOnceAreABurstToo() { + var storm = SpawnStorm() + var line: String? + for index in 0.. Date: Sat, 24 Oct 2026 19:46:30 +0200 Subject: [PATCH 2/6] fix(GenesisKit): spawn.storm fires at 40 starts in 10 s or 16 running, so the hub opening a pull request (24 starts, 5 running) is not a storm, and git's -c option stays out of the label --- .claude/skills/ux/references/findings.md | 34 +++++++++++++++++++ .../GenesisKitBase/Perf/SpawnMeter.swift | 8 +++-- .../Diff/AgentBlameModelTests.swift | 19 ++++++----- 3 files changed, 50 insertions(+), 11 deletions(-) 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/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift b/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift index 27e692fc91..e9bd3e66f8 100644 --- a/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift +++ b/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift @@ -29,7 +29,7 @@ public enum SpawnMeter { skipValue = false continue } - if argument == "-C" || argument == "--git-dir" { + if argument == "-C" || argument == "-c" || argument == "--git-dir" { skipValue = true continue } @@ -46,9 +46,11 @@ public enum SpawnMeter { /// The burst rule, apart from the clock and the log: `burstStarts` starts within `window` seconds, or `burstRunning` /// children at once. A burst is reported when it starts, every `reportEvery` seconds while it lasts, and when it ends. +/// 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 = 24 - public static let burstRunning = 12 + public static let burstStarts = 40 + public static let burstRunning = 16 public static let window: TimeInterval = 10 public static let reportEvery: TimeInterval = 30 diff --git a/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift b/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift index 2441fc89a3..48997b61c7 100644 --- a/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift +++ b/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift @@ -106,16 +106,19 @@ final class SpawnStormTests: XCTestCase { XCTAssertNil(storm.start("GenesisTools agents blame", at: Double(index) * 0.1), "under the burst size: quiet") _ = storm.finish(at: Double(index) * 0.1 + 0.05) } - if let line = storm.start("git status", at: 2.4) { lines.append(line) } + let last = Double(SpawnStorm.burstStarts - 1) * 0.1 + if let line = storm.start("git status", at: last) { lines.append(line) } XCTAssertEqual(lines.count, 1) - XCTAssertTrue(lines[0].hasPrefix("spawn.storm 24 child processes started in 10 s"), lines[0]) - XCTAssertTrue(lines[0].contains("GenesisTools agents blame ×23, git status ×1"), lines[0]) + let burst = SpawnStorm.burstStarts + XCTAssertTrue(lines[0].hasPrefix("spawn.storm \(burst) child processes started in 10 s"), lines[0]) + XCTAssertTrue(lines[0].contains("GenesisTools agents blame ×\(burst - 1), git status ×1"), lines[0]) - XCTAssertNil(storm.start("git status", at: 3), "no second line within 30 s") - XCTAssertTrue(storm.start("git status", at: 33)?.hasPrefix("spawn.storm ongoing 30 s") == true) + XCTAssertNil(storm.start("git status", at: 4.5), "no second line within 30 s") + XCTAssertTrue(storm.start("git status", at: 34)?.hasPrefix("spawn.storm ongoing 30 s") == true) // The first finish once the window holds few starts and few children run ends it. let over = storm.finish(at: 40) - XCTAssertTrue(over?.hasPrefix("spawn.storm over after 37 s: 26 child processes started") == true, over ?? "nil") + XCTAssertTrue(over?.hasPrefix("spawn.storm over after \(Int(40 - last)) s: \(SpawnStorm.burstStarts + 2) child processes started") == true, + over ?? "nil") XCTAssertNil(storm.finish(at: 41)) XCTAssertNil(storm.start("git status", at: 61), "a quiet start after the burst ended") } @@ -124,12 +127,12 @@ final class SpawnStormTests: XCTestCase { var storm = SpawnStorm() var line: String? for index in 0.. Date: Sat, 24 Oct 2026 20:32:10 +0200 Subject: [PATCH 3/6] fix(GenesisKit): a spawn.storm label leaves out commit ids and revisions, so git cat-file counts as git cat-file --- .../Sources/GenesisKitBase/Perf/SpawnMeter.swift | 8 +++++++- .../Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift | 3 +++ 2 files changed, 10 insertions(+), 1 deletion(-) diff --git a/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift b/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift index e9bd3e66f8..db019e6875 100644 --- a/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift +++ b/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift @@ -36,12 +36,18 @@ public enum SpawnMeter { 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 { + } 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" && base.count < argument.count + } } /// The burst rule, apart from the clock and the log: `burstStarts` starts within `window` seconds, or `burstRunning` diff --git a/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift b/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift index 48997b61c7..0cd8c9e7ea 100644 --- a/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift +++ b/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift @@ -138,5 +138,8 @@ final class SpawnStormTests: XCTestCase { arguments: ["/Users/x/.genesis-tools/bin/gt-agents", "/repo/src/agents/index.ts", "blame", "--repo", "/vault", "--files", "a/b.md", "--json"]), "GenesisTools agents blame") + XCTAssertEqual(SpawnMeter.label(executable: URL(fileURLWithPath: "/usr/bin/git"), + arguments: ["-c", "core.quotepath=off", "cat-file", "-t", "96c986d3c53f34fde9beb70d8f3e3c987edcfe3f^{commit}"]), + "git cat-file", "a commit id would split one command's count") } } From 6a079d21ca859fa932a81d8663fff3af5e38cded Mon Sep 17 00:00:00 2001 From: Martin Date: Sat, 24 Oct 2026 20:36:18 +0200 Subject: [PATCH 4/6] fix(GenesisKit): a spawn.storm ends at the first start or finish that finds it quiet and is timed to its last start, so a 10 s burst no longer reads "over after 209 s" --- .../GenesisKitBase/Perf/SpawnMeter.swift | 37 +++++++++----- .../Diff/AgentBlameModelTests.swift | 50 +++++++++++-------- 2 files changed, 53 insertions(+), 34 deletions(-) diff --git a/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift b/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift index db019e6875..458010ed84 100644 --- a/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift +++ b/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift @@ -11,11 +11,11 @@ public enum SpawnMeter { /// 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 line = lock.withLock { storm.start(label, at: CFAbsoluteTimeGetCurrent()) } - if let line { PerfLog.mark(line) } + let lines = lock.withLock { storm.start(label, at: CFAbsoluteTimeGetCurrent()) } + lines.forEach { PerfLog.mark($0) } return { - let line = lock.withLock { storm.finish(at: CFAbsoluteTimeGetCurrent()) } - if let line { PerfLog.mark(line) } + let lines = lock.withLock { storm.finish(at: CFAbsoluteTimeGetCurrent()) } + lines.forEach { PerfLog.mark($0) } } } @@ -51,7 +51,8 @@ public enum SpawnMeter { } /// The burst rule, apart from the clock and the log: `burstStarts` starts within `window` seconds, or `burstRunning` -/// children at once. A burst is reported when it starts, every `reportEvery` seconds while it lasts, and when it ends. +/// children at once. A burst is reported when it starts, every `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 { @@ -63,38 +64,48 @@ public struct SpawnStorm { 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? { + public mutating func start(_ label: String, at now: Double) -> [String] { + prune(now) + var lines = endIfQuiet().map { [$0] } ?? [] running += 1 starts.append((now, label)) - prune(now) if let since { total += 1 counts[label, default: 0] += 1 - guard now - lastReport >= Self.reportEvery else { return nil } + lastStart = now + guard now - lastReport >= Self.reportEvery else { return lines } lastReport = now - return "spawn.storm ongoing \(Int(now - since)) s: \(total) child processes started, \(running) running; \(top)" + lines.append("spawn.storm ongoing \(Int(now - since)) s: \(total) child processes started, \(running) running; \(top)") + return lines } - guard starts.count >= Self.burstStarts || running >= Self.burstRunning else { return nil } + 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 } - return "spawn.storm \(starts.count) child processes started in \(Int(Self.window)) s, \(running) running; \(top)" + 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? { + public mutating func finish(at now: Double) -> [String] { running = max(0, running - 1) prune(now) + return endIfQuiet().map { [$0] } ?? [] + } + + 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(now - since)) s: \(total) child processes started; \(top)" + return "spawn.storm over after \(Int(lastStart - since)) s: \(total) child processes started; \(top)" } private mutating func prune(_ now: Double) { diff --git a/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift b/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift index 0cd8c9e7ea..7cbc3e6d56 100644 --- a/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift +++ b/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift @@ -101,33 +101,41 @@ final class AgentBlameModelTests: XCTestCase { final class SpawnStormTests: XCTestCase { func testABurstIsReportedWhenItStartsWhileItLastsAndWhenItEnds() { var storm = SpawnStorm() - var lines: [String] = [] - for index in 0..<(SpawnStorm.burstStarts - 1) { - XCTAssertNil(storm.start("GenesisTools agents blame", at: Double(index) * 0.1), "under the burst size: quiet") - _ = storm.finish(at: Double(index) * 0.1 + 0.05) - } - let last = Double(SpawnStorm.burstStarts - 1) * 0.1 - if let line = storm.start("git status", at: last) { lines.append(line) } - XCTAssertEqual(lines.count, 1) let burst = SpawnStorm.burstStarts - XCTAssertTrue(lines[0].hasPrefix("spawn.storm \(burst) child processes started in 10 s"), lines[0]) - XCTAssertTrue(lines[0].contains("GenesisTools agents blame ×\(burst - 1), git status ×1"), lines[0]) + 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) - XCTAssertNil(storm.start("git status", at: 4.5), "no second line within 30 s") - XCTAssertTrue(storm.start("git status", at: 34)?.hasPrefix("spawn.storm ongoing 30 s") == true) - // The first finish once the window holds few starts and few children run ends it. - let over = storm.finish(at: 40) - XCTAssertTrue(over?.hasPrefix("spawn.storm over after \(Int(40 - last)) s: \(SpawnStorm.burstStarts + 2) child processes started") == true, - over ?? "nil") - XCTAssertNil(storm.finish(at: 41)) - XCTAssertNil(storm.start("git status", at: 61), "a quiet start after the burst ended") + // 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 testManyChildrenRunningAtOnceAreABurstToo() { var storm = SpawnStorm() - var line: String? - for index in 0.. Date: Mon, 26 Oct 2026 01:38:30 +0100 Subject: [PATCH 5/6] fix(GenesisKit, GenesisHub, hub): #593 followup - preserve storm and hang identity --- src/hub/lib/dev-monitor.test.ts | 118 +++++++++++++++++- src/hub/lib/dev-monitor.ts | 18 +-- .../GenesisKitBase/Perf/SpawnMeter.swift | 2 +- .../Diff/AgentBlameModelTests.swift | 11 ++ 4 files changed, 136 insertions(+), 13 deletions(-) diff --git a/src/hub/lib/dev-monitor.test.ts b/src/hub/lib/dev-monitor.test.ts index 358a27d6ff..6adb715556 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,15 +53,16 @@ describe("classifyPerfLine", () => { ).toBe("hang"); }); - test("a burst of child processes is an event; its ongoing and over lines collapse into one", () => { + 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 }); - expect(classifyPerfLine("[19:26:32.100] mark spawn.storm ongoing 30 s: 400 child processes started")?.key).toBe( - "storm" - ); + 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", () => { @@ -284,3 +285,110 @@ 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] [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: 300 child processes started", + "Genesis: 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 3cc0536f78..3acfbc88c2 100644 --- a/src/hub/lib/dev-monitor.ts +++ b/src/hub/lib/dev-monitor.ts @@ -166,7 +166,7 @@ export function classifyPerfLine( kind: "storm", time, text: short(body), - key: /^spawn\.storm (ongoing|over)/.test(body) ? "storm" : undefined, + key: /^spawn\.storm ongoing\b/.test(body) ? `${hangsDir}:storm:ongoing` : undefined, }; } @@ -352,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. */ @@ -394,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[] = []; @@ -424,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})` }; }); } @@ -445,7 +449,7 @@ 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); @@ -471,7 +475,7 @@ export async function runDevMonitor(options: DevMonitorOptions): Promise { const event = classifyPerfLine(line, options, hangsDir); if (event) { if (event.file) { - announced.add(basename(event.file)); + announced.add(event.file); } batcher.add({ ...event, text: app + event.text }); @@ -491,7 +495,7 @@ export async function runDevMonitor(options: DevMonitorOptions): Promise { } for (const path of [...hangs.fresh(), ...genesisHangs.fresh()]) { - if (!announced.has(basename(path))) { + if (!announced.has(path)) { batcher.add({ kind: "hang", time: "", diff --git a/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift b/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift index 458010ed84..ff41a3a2a3 100644 --- a/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift +++ b/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift @@ -46,7 +46,7 @@ public enum SpawnMeter { /// 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" && base.count < argument.count + return base.count >= 7 && base.allSatisfy(\.isHexDigit) || base == "HEAD" } } diff --git a/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift b/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift index 7cbc3e6d56..af1ac924ab 100644 --- a/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift +++ b/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift @@ -138,6 +138,17 @@ final class SpawnStormTests: XCTestCase { XCTAssertTrue(lines.last?.contains("\(SpawnStorm.burstRunning) running") == true, lines.last ?? "nil") } + func testLabelsGroupHeadAndCommitRevisionsTogether() { + for revision in ["HEAD", "HEAD~2", "HEAD^{commit}", "96c986d3", "96c986d3^{commit}"] { + XCTAssertEqual(SpawnMeter.label(executable: URL(fileURLWithPath: "/usr/bin/git"), + arguments: ["cat-file", "-t", revision]), + "git cat-file", revision) + } + XCTAssertEqual(SpawnMeter.label(executable: URL(fileURLWithPath: "/usr/bin/git"), + arguments: ["remote", "HEADquarters"]), + "git remote HEADquarters", "ordinary names beginning with HEAD remain labels") + } + func testLabelsNameTheCommandNotItsPaths() { XCTAssertEqual(SpawnMeter.label(executable: URL(fileURLWithPath: "/usr/bin/git"), arguments: ["-C", "/Users/x/vault", "-c", "core.quotepath=off", "status", "-z"]), From 421c572d9ba401174dbf1debe2fd2c13c6f58b0c Mon Sep 17 00:00:00 2001 From: Martin Date: Mon, 26 Oct 2026 03:49:31 +0100 Subject: [PATCH 6/6] fix(GenesisKit, GenesisHub, hub): #593 followup - a spawn storm reports its end without more starts, a captured child that ends early or fails to launch keeps the meter balanced, and helper perf lines stay apart from their parent's --- src/hub/lib/dev-monitor.test.ts | 25 +++++++++++++++-- src/hub/lib/dev-monitor.ts | 12 ++++----- .../GenesisKitBase/Perf/SpawnMeter.swift | 18 ++++++++----- .../GenesisKitBase/Tools/ProcessCapture.swift | 23 +++++++++++++--- .../Diff/AgentBlameModelTests.swift | 19 +++++++++++++ .../GenesisKitTests/ToolsBridgeTests.swift | 27 +++++++++++++++++++ 6 files changed, 106 insertions(+), 18 deletions(-) diff --git a/src/hub/lib/dev-monitor.test.ts b/src/hub/lib/dev-monitor.test.ts index 6adb715556..5865c65bc7 100644 --- a/src/hub/lib/dev-monitor.test.ts +++ b/src/hub/lib/dev-monitor.test.ts @@ -74,12 +74,31 @@ describe("classifyPerfLine", () => { 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" @@ -304,6 +323,7 @@ test("both perf tails retain their storm updates and endings in a batch", async 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", "", @@ -328,8 +348,9 @@ test("both perf tails retain their storm updates and endings in a batch", async "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: 300 child processes started", - "Genesis: spawn.storm over after 30 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 { diff --git a/src/hub/lib/dev-monitor.ts b/src/hub/lib/dev-monitor.ts index 3acfbc88c2..2e0e260562 100644 --- a/src/hub/lib/dev-monitor.ts +++ b/src/hub/lib/dev-monitor.ts @@ -150,11 +150,10 @@ export function classifyPerfLine( hangsDir = genesisToolsDir("logs", "hangs") ): DevEvent | null { const time = line.match(timePattern)?.[1] ?? ""; - const body = line - .replace(timePattern, "") - .replace(/^\[[a-z-]+\]\s+/, "") - .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) }; @@ -162,11 +161,12 @@ export function classifyPerfLine( // 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) ? `${hangsDir}:storm:ongoing` : undefined, + key: /^spawn\.storm ongoing\b/.test(body) ? `${source}:storm:ongoing` : undefined, }; } diff --git a/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift b/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift index ff41a3a2a3..994d9c6855 100644 --- a/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift +++ b/src/macos/GenesisKit/Sources/GenesisKitBase/Perf/SpawnMeter.swift @@ -51,7 +51,8 @@ public enum SpawnMeter { } /// The burst rule, apart from the clock and the log: `burstStarts` starts within `window` seconds, or `burstRunning` -/// children at once. A burst is reported when it starts, every `reportEvery` seconds while it lasts, and when it ends: +/// 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. @@ -76,13 +77,11 @@ public struct SpawnStorm { var lines = endIfQuiet().map { [$0] } ?? [] running += 1 starts.append((now, label)) - if let since { + if since != nil { total += 1 counts[label, default: 0] += 1 lastStart = now - guard now - lastReport >= Self.reportEvery else { return lines } - lastReport = now - lines.append("spawn.storm ongoing \(Int(now - since)) s: \(total) child processes started, \(running) running; \(top)") + if let ongoing = reportIfDue(at: now) { lines.append(ongoing) } return lines } guard starts.count >= Self.burstStarts || running >= Self.burstRunning else { return lines } @@ -98,7 +97,14 @@ public struct SpawnStorm { public mutating func finish(at now: Double) -> [String] { running = max(0, running - 1) prune(now) - return endIfQuiet().map { [$0] } ?? [] + 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? { diff --git a/src/macos/GenesisKit/Sources/GenesisKitBase/Tools/ProcessCapture.swift b/src/macos/GenesisKit/Sources/GenesisKitBase/Tools/ProcessCapture.swift index 38f6cb10fa..a9f19ca2f5 100644 --- a/src/macos/GenesisKit/Sources/GenesisKitBase/Tools/ProcessCapture.swift +++ b/src/macos/GenesisKit/Sources/GenesisKitBase/Tools/ProcessCapture.swift @@ -40,16 +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 = SpawnMeter.started(executable: executableURL, arguments: arguments ?? []) - defer { ended() } + 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/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift b/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift index af1ac924ab..d7f04f421d 100644 --- a/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift +++ b/src/macos/GenesisKit/Tests/GenesisKitTests/Diff/AgentBlameModelTests.swift @@ -131,6 +131,25 @@ final class SpawnStormTests: XCTestCase { XCTAssertEqual(storm.finish(at: 300.1), [], "the quiet child after it starts no new burst") } + func testFinishesReportAnOngoingConcurrencyStormWithoutMoreStarts() { + var storm = SpawnStorm() + for _ in 0..