Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
56 changes: 56 additions & 0 deletions apps/host-daemon/src/event-loop-stall-monitor.test.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,56 @@
import { afterEach, describe, expect, it, vi } from "vitest";

const perfHooksMock = vi.hoisted(() => ({
histogram: {
disable: vi.fn(),
enable: vi.fn(),
max: 600_000_000_000,
mean: 1_000_000,
percentile: vi.fn(() => 1_000_000),
reset: vi.fn(),
},
}));

vi.mock("node:perf_hooks", () => ({
monitorEventLoopDelay: vi.fn(() => perfHooksMock.histogram),
}));

import { startEventLoopStallMonitor } from "./event-loop-stall-monitor.js";

describe("host event-loop stall monitor", () => {
afterEach(() => {
vi.useRealTimers();
vi.clearAllMocks();
});

it("suppresses histogram delays accumulated while the system was suspended", () => {
vi.useFakeTimers();
let now = 0;
const logger = { warn: vi.fn() };
const monitor = startEventLoopStallMonitor({ logger, now: () => now });

now = 300_000;
vi.advanceTimersByTime(5_000);

expect(logger.warn).not.toHaveBeenCalled();
expect(perfHooksMock.histogram.reset).toHaveBeenCalledOnce();
monitor.stop();
});

it("still reports a sub-minute event-loop stall", () => {
vi.useFakeTimers();
perfHooksMock.histogram.max = 600_000_000;
let now = 0;
const logger = { warn: vi.fn() };
const monitor = startEventLoopStallMonitor({ logger, now: () => now });

now = 5_000;
vi.advanceTimersByTime(5_000);

expect(logger.warn).toHaveBeenCalledWith(
expect.objectContaining({ maxDelayMs: 600 }),
"Host daemon event loop stalled",
);
monitor.stop();
});
});
13 changes: 12 additions & 1 deletion apps/host-daemon/src/event-loop-stall-monitor.ts
Original file line number Diff line number Diff line change
@@ -1,8 +1,11 @@
import { monitorEventLoopDelay } from "node:perf_hooks";
import type { HostDaemonLogger } from "./logger.js";
import { isLikelySystemSuspensionDelay } from "./system-suspension.js";

interface EventLoopStallMonitorOptions {
logger: Pick<HostDaemonLogger, "warn">;
/** Injectable monotonic-enough wall clock for tests. */
now?: () => number;
}

interface EventLoopStallMonitor {
Expand All @@ -28,12 +31,20 @@ export function startEventLoopStallMonitor(
const thresholdMs = DEFAULT_EVENT_LOOP_STALL_LOG_THRESHOLD_MS;
const intervalMs = DEFAULT_EVENT_LOOP_STALL_MONITOR_INTERVAL_MS;
const resolutionMs = DEFAULT_EVENT_LOOP_STALL_MONITOR_RESOLUTION_MS;
const now = options.now ?? (() => Date.now());
const histogram = monitorEventLoopDelay({ resolution: resolutionMs });
histogram.enable();
let lastSampleAt = now();

const timer = setInterval(() => {
const sampledAt = now();
const sampleGapMs = sampledAt - lastSampleAt;
lastSampleAt = sampledAt;
const maxDelayMs = nanosecondsToMilliseconds(histogram.max);
if (maxDelayMs >= thresholdMs) {
if (
!isLikelySystemSuspensionDelay({ gapMs: sampleGapMs, intervalMs }) &&
maxDelayMs >= thresholdMs
) {
options.logger.warn(
{
intervalMs,
Expand Down
32 changes: 29 additions & 3 deletions apps/host-daemon/src/event-sink.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -144,11 +144,13 @@ describe("event sink", () => {
expect(postEvents).toHaveBeenCalledTimes(1);
});

it("warns once when the queue grows large while undelivered", () => {
it("warns once when a large queue remains undelivered", () => {
const logger = createLogger();
let now = 0;
const sink = createEventSink({
isSessionOpen: () => false,
logger,
now: () => now,
postEvents: acceptingPostEvents(),
});

Expand All @@ -157,12 +159,36 @@ describe("event sink", () => {
}
expect(logger.warn).not.toHaveBeenCalled();

// Crossing the depth threshold fires the tripwire once...
// A fresh event burst is throughput, not evidence of a stalled delivery.
sink.emit({ threadId: "thr_1", event: systemErrorEvent("thr_1") });
expect(logger.warn).not.toHaveBeenCalled();

// Remaining above the depth threshold for five seconds fires once.
now = 5_000;
sink.emit({ threadId: "thr_1", event: systemErrorEvent("thr_1") });
expect(logger.warn).toHaveBeenCalledTimes(1);
expect(logger.warn).toHaveBeenCalledWith(
expect.objectContaining({ queueDepth: 512 }),
expect.objectContaining({ queueAgeMs: 5_000, queueDepth: 513 }),
expect.any(String),
);
});

it("warns when even a small queue is stalled for thirty seconds", () => {
const logger = createLogger();
let now = 0;
const sink = createEventSink({
isSessionOpen: () => false,
logger,
now: () => now,
postEvents: acceptingPostEvents(),
});

sink.emit({ threadId: "thr_1", event: systemErrorEvent("thr_1") });
now = 30_000;
sink.emit({ threadId: "thr_1", event: systemErrorEvent("thr_1") });

expect(logger.warn).toHaveBeenCalledWith(
expect.objectContaining({ queueAgeMs: 30_000, queueDepth: 2 }),
expect.any(String),
);
});
Expand Down
13 changes: 9 additions & 4 deletions apps/host-daemon/src/event-sink.ts
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,7 @@ const DEFAULT_DEBOUNCE_MS = 100;
// growing. These only warn — they never drop, fault, or bound the queue. If
// they fire in practice, that is the signal to add real backpressure.
const QUEUE_DEPTH_WARN_THRESHOLD = 512;
const QUEUE_DEPTH_WARN_MIN_AGE_MS = 5_000;
const QUEUE_AGE_WARN_THRESHOLD_MS = 30_000;

export interface EventSinkInput {
Expand All @@ -30,6 +31,8 @@ export interface EventPostResult {
export interface CreateEventSinkOptions {
isSessionOpen: () => boolean;
logger: Pick<HostDaemonLogger, "debug" | "error" | "warn">;
/** Injectable wall clock for queue-age tests. */
now?: () => number;
postEvents: (events: HostDaemonEventEnvelope[]) => Promise<EventPostResult>;
}

Expand Down Expand Up @@ -116,6 +119,7 @@ function summarizeRejectedEvents(
}

export function createEventSink(options: CreateEventSinkOptions): EventSink {
const now = options.now ?? (() => Date.now());
const queue: HostDaemonEventEnvelope[] = [];
let flushTimer: ReturnType<typeof setTimeout> | null = null;
let flushPromise: Promise<void> | null = null;
Expand All @@ -130,10 +134,11 @@ export function createEventSink(options: CreateEventSinkOptions): EventSink {
return;
}
const queueDepth = queue.length;
const queueAgeMs = Date.now() - backedUpSinceMs;
const queueAgeMs = now() - backedUpSinceMs;
if (
queueDepth < QUEUE_DEPTH_WARN_THRESHOLD &&
queueAgeMs < QUEUE_AGE_WARN_THRESHOLD_MS
queueAgeMs < QUEUE_AGE_WARN_THRESHOLD_MS &&
(queueDepth < QUEUE_DEPTH_WARN_THRESHOLD ||
queueAgeMs < QUEUE_DEPTH_WARN_MIN_AGE_MS)
) {
return;
}
Expand Down Expand Up @@ -281,7 +286,7 @@ export function createEventSink(options: CreateEventSinkOptions): EventSink {
throw new EventSinkDisposedError();
}
if (backedUpSinceMs === null) {
backedUpSinceMs = Date.now();
backedUpSinceMs = now();
}
queue.push({
threadId: input.threadId,
Expand Down
27 changes: 27 additions & 0 deletions apps/host-daemon/src/server-connection.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -354,6 +354,33 @@ describe("ServerConnection", () => {
}
});

it("reports a system-suspension gap without calling it a heartbeat stall", async () => {
vi.useFakeTimers();
vi.setSystemTime(0);
const { connection, logger } = createConnectionFixture({
heartbeatIntervalMs: 5_000,
leaseTimeoutMs: 30_000,
});
try {
await connection.start();
await vi.advanceTimersByTimeAsync(5_000);

vi.setSystemTime(300_000);
await vi.advanceTimersByTimeAsync(5_000);

expect(logger.warn).not.toHaveBeenCalledWith(
expect.anything(),
"Host daemon heartbeat timer delayed",
);
expect(logger.info).toHaveBeenCalledWith(
expect.objectContaining({ gapMs: 300_000 }),
"Host daemon resumed after likely system suspension",
);
} finally {
await connection.shutdown();
}
});

it("queues output above high water and flushes it before lifecycle messages", async () => {
vi.useFakeTimers();
const { connection, webSocket } = createConnectionFixture();
Expand Down
19 changes: 18 additions & 1 deletion apps/host-daemon/src/server-connection.ts
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@ import {
type ReconnectingWebSocketLike,
type ServerConnectionOptions,
} from "./server-connection-support.js";
import { isLikelySystemSuspensionDelay } from "./system-suspension.js";
import { normalizeCaughtError, runtimeErrorLogFields } from "./error-utils.js";
import { ServerResponseError } from "./server-client.js";

Expand Down Expand Up @@ -756,7 +757,23 @@ export class ServerConnection {
if (lastTickAt !== null) {
const gapMs = now - lastTickAt;
const thresholdMs = session.leaseTimeoutMs / 2;
if (gapMs > thresholdMs) {
if (
isLikelySystemSuspensionDelay({
gapMs,
intervalMs: session.heartbeatIntervalMs,
})
) {
this.options.logger.info(
{
gapMs,
heartbeatIntervalMs: session.heartbeatIntervalMs,
leaseTimeoutMs: session.leaseTimeoutMs,
sessionId: session.sessionId,
websocketReadyState: this.websocket?.readyState ?? null,
},
"Host daemon resumed after likely system suspension",
);
} else if (gapMs > thresholdMs) {
this.options.logger.warn(
{
gapMs,
Expand Down
14 changes: 14 additions & 0 deletions apps/host-daemon/src/system-suspension.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,14 @@
const LIKELY_SYSTEM_SUSPENSION_MIN_DELAY_MS = 60_000;

/**
* Long timer gaps on a laptop are overwhelmingly process suspension during
* system sleep, not JavaScript monopolizing the event loop. Keep sub-minute
* delays visible as real stalls while preventing a wake from flooding the log
* with event-loop and heartbeat warnings for time the process did not run.
*/
export function isLikelySystemSuspensionDelay(args: {
gapMs: number;
intervalMs: number;
}): boolean {
return args.gapMs - args.intervalMs >= LIKELY_SYSTEM_SUSPENSION_MIN_DELAY_MS;
}
35 changes: 21 additions & 14 deletions apps/server/src/routes/threads/data.ts
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@ import { formatCustomAcpAgentProviderId } from "@bb/config/bb-app-managed-config
import {
getAppSettings,
getLatestThreadSequence,
getLatestStoredConversationOutlineSequence,
listQueuedThreadMessages,
} from "@bb/db";
import type { Hono } from "hono";
Expand Down Expand Up @@ -315,19 +316,15 @@ export function registerThreadDataRoutes(app: Hono, deps: AppDeps): void {
const slowTimelineBuildLogger = createSlowThreadTimelineBuildLogger({
logger: deps.logger,
});
// The conversation outline reprojects the entire thread, so memoize it per
// (thread, maxSeq): repeated polls at a stable revision are served from
// cache. Any appended event bumps maxSeq and forces a rebuild, so a thread
// streaming many deltas rebuilds per batch — acceptable because the client
// only fetches the outline when the minimap is mounted and refetches are
// driven by the (debounced) realtime invalidation, not per token. The key
// omits the provider/env inputs the timeline cache tracks because the outline
// emits only event-derived fields (id/role/preview/attachment counts); add
// them here if the outline ever surfaces a provider- or workspace-derived
// value. A small LRU bounds memory across many viewed threads.
// The conversation outline reprojects the entire thread, so memoize it by
// the newest event that can affect the outline. Command output, reasoning,
// and usage events still advance maxSeq in the response but do not invalidate
// the expensive projection. The key includes thread metadata that can affect
// grouping; add provider/env inputs if the outline ever surfaces them. A
// small LRU bounds memory across many viewed threads.
const conversationOutlineCache = new Map<
string,
ThreadConversationOutlineResponse
ThreadConversationOutlineResponse["items"]
>();
const CONVERSATION_OUTLINE_CACHE_MAX_ENTRIES = 128;

Expand Down Expand Up @@ -422,13 +419,23 @@ export function registerThreadDataRoutes(app: Hono, deps: AppDeps): void {
get(routes.conversationOutline, (context) => {
const thread = requirePublicThread(deps.db, context.req.param("id"));
const maxSeq = getLatestThreadSequence(deps.db, { threadId: thread.id });
const cacheKey = `${thread.id}:${maxSeq}`;
const outlineSequence = getLatestStoredConversationOutlineSequence(
deps.db,
{ threadId: thread.id },
);
const cacheKey = JSON.stringify([
thread.id,
outlineSequence,
thread.status,
thread.title,
thread.titleFallback,
]);
const cached = conversationOutlineCache.get(cacheKey);
if (cached !== undefined) {
// Re-insert to mark most-recently-used.
conversationOutlineCache.delete(cacheKey);
conversationOutlineCache.set(cacheKey, cached);
return context.json(cached);
return context.json({ items: cached, maxSeq });
}
const response = buildThreadConversationOutline(deps.db, thread, {
maxSeq,
Expand All @@ -437,7 +444,7 @@ export function registerThreadDataRoutes(app: Hono, deps: AppDeps): void {
thread.providerId,
),
});
conversationOutlineCache.set(cacheKey, response);
conversationOutlineCache.set(cacheKey, response.items);
while (
conversationOutlineCache.size > CONVERSATION_OUTLINE_CACHE_MAX_ENTRIES
) {
Expand Down
Loading
Loading