From 12612f66464f1c39ada3f7bf7763fd9a8765148d Mon Sep 17 00:00:00 2001 From: Mohamed Boudra Date: Thu, 23 Jul 2026 21:57:08 +0200 Subject: [PATCH] Make Git slowdowns visible in daemon metrics (#2366) * feat(server): expose daemon Git pressure metrics Separate limiter queue wait from Git execution time and report subscription ownership so accumulating work is visible in the existing runtime log. * fix(server): collect subscriptions in agent metrics Reuse the existing agent snapshot during runtime flushes so WebSocket shutdown does not require an additional AgentManager method call. * test(server): retry transient hub cleanup --- docs/terminal-performance.md | 5 + .../server/src/server/agent/agent-manager.ts | 2 + .../hub/test-utils/relationship-harness.ts | 11 +- packages/server/src/server/session.ts | 7 + .../workspace-git-observer-service.test.ts | 29 ++++ .../workspace-git-observer-service.ts | 15 ++ .../test-utils/workspace-git-service-stub.ts | 14 ++ .../server/src/server/websocket-server.ts | 43 ++++- .../src/server/websocket/runtime-metrics.ts | 2 + .../src/server/workspace-git-service.ts | 63 ++++++++ .../utils/git-command-runtime-metrics.test.ts | 74 +++++++++ .../src/utils/git-command-runtime-metrics.ts | 147 ++++++++++++++++++ packages/server/src/utils/run-git-command.ts | 46 ++++-- 13 files changed, 440 insertions(+), 18 deletions(-) create mode 100644 packages/server/src/utils/git-command-runtime-metrics.test.ts create mode 100644 packages/server/src/utils/git-command-runtime-metrics.ts diff --git a/docs/terminal-performance.md b/docs/terminal-performance.md index 287855aa6..15108e951 100644 --- a/docs/terminal-performance.md +++ b/docs/terminal-performance.md @@ -32,6 +32,11 @@ Terminal frames share the daemon main event loop with all agent traffic. The `ev - **Browser perf specs (user-perceived path):** gated behind `PASEO_TERMINAL_PERF_E2E=1` — `packages/app/e2e/terminal-performance.spec.ts` and `packages/app/e2e/terminal-keystroke-stress.spec.ts` (per-stage keydown→xterm-commit breakdown under mock-agent load). Healthy: keydown→commit p50 ~18ms under 600-key burst. - **Production:** grep `daemon.log` for `ws_runtime_metrics` and read `eventLoopDelay` + `bufferedAmount`. +- **Git pressure:** the same log line includes `git.commands` (limiter occupancy, queue age, + queue wait, execution time, failures, timeouts, and top operations), + `git.workspaceService` (daemon-global Git observer ownership), and per-session workspace Git + subscription totals under `runtime`. Queue wait and execution time are separate because the Git + command timeout begins only after a command acquires a limiter slot. ## Known remaining contention (follow-up candidates) diff --git a/packages/server/src/server/agent/agent-manager.ts b/packages/server/src/server/agent/agent-manager.ts index 3337ceca6..8ad7b77a5 100644 --- a/packages/server/src/server/agent/agent-manager.ts +++ b/packages/server/src/server/agent/agent-manager.ts @@ -385,6 +385,7 @@ export type ManagedAgent = export interface AgentMetricsSnapshot { total: number; + subscriptionCount: number; byLifecycle: Record; withActiveForegroundTurn: number; timelineStats: { @@ -726,6 +727,7 @@ export class AgentManager { return { total: this.agents.size, + subscriptionCount: this.subscribers.size, byLifecycle, withActiveForegroundTurn, timelineStats: { diff --git a/packages/server/src/server/hub/test-utils/relationship-harness.ts b/packages/server/src/server/hub/test-utils/relationship-harness.ts index 6603bff87..819fb8d85 100644 --- a/packages/server/src/server/hub/test-utils/relationship-harness.ts +++ b/packages/server/src/server/hub/test-utils/relationship-harness.ts @@ -1322,16 +1322,17 @@ export class HubRelationshipHarness { } private async removeRoot(): Promise { - let retryableCode: string | null = null; - if (platform() === "win32") retryableCode = "EBUSY"; - if (platform() === "darwin") retryableCode = "ENOTEMPTY"; - const attempts = retryableCode ? 10 : 1; + const retryableCodes = new Set(["EBUSY", "ENOTEMPTY"]); + const attempts = 10; for (let attempt = 1; attempt <= attempts; attempt++) { try { await rm(this.root, { recursive: true, force: true }); return; } catch (error) { - if ((error as NodeJS.ErrnoException).code !== retryableCode || attempt === attempts) { + if ( + !retryableCodes.has((error as NodeJS.ErrnoException).code ?? "") || + attempt === attempts + ) { throw error; } await new Promise((resolve) => setTimeout(resolve, 100 * attempt)); diff --git a/packages/server/src/server/session.ts b/packages/server/src/server/session.ts index 1c8de87a0..9f21c4833 100644 --- a/packages/server/src/server/session.ts +++ b/packages/server/src/server/session.ts @@ -313,6 +313,9 @@ export function resolveWaitForFinishError(options: { export interface SessionRuntimeMetrics { terminalDirectorySubscriptionCount: number; terminalSubscriptionCount: number; + workspaceGitWatchedDirectoryCount: number; + workspaceGitWorkspaceRecordCount: number; + workspaceGitSubscriptionCount: number; inflightRequests: number; peakInflightRequests: number; } @@ -1260,9 +1263,13 @@ export class Session { public getRuntimeMetrics(): SessionRuntimeMetrics { const terminalMetrics = this.terminalController.getMetrics(); + const workspaceGitMetrics = this.workspaceGitObserver.getMetrics(); return { terminalDirectorySubscriptionCount: terminalMetrics.directorySubscriptionCount, terminalSubscriptionCount: terminalMetrics.streamSubscriptionCount, + workspaceGitWatchedDirectoryCount: workspaceGitMetrics.watchedDirectoryCount, + workspaceGitWorkspaceRecordCount: workspaceGitMetrics.workspaceRecordCount, + workspaceGitSubscriptionCount: workspaceGitMetrics.subscriptionCount, inflightRequests: this.inflightRequests, peakInflightRequests: this.peakInflightRequests, }; diff --git a/packages/server/src/server/session/workspace-git-observer/workspace-git-observer-service.test.ts b/packages/server/src/server/session/workspace-git-observer/workspace-git-observer-service.test.ts index d82d71210..1eb08a702 100644 --- a/packages/server/src/server/session/workspace-git-observer/workspace-git-observer-service.test.ts +++ b/packages/server/src/server/session/workspace-git-observer/workspace-git-observer-service.test.ts @@ -207,6 +207,35 @@ describe("syncObservers", () => { h.emitSnapshot(WS1, "feature"); expect(h.branchChanges).toEqual([["ws2", null, "feature"]]); }); + + test("reports observer ownership as workspaces are added and removed", () => { + const h = buildHarness(); + h.service.syncObservers([ + makeDescriptor({ id: "ws1", workspaceDirectory: WS1 }), + makeDescriptor({ id: "ws2", workspaceDirectory: WS1 }), + makeDescriptor({ id: "ws3", workspaceDirectory: WS2 }), + ]); + + expect(h.service.getMetrics()).toEqual({ + watchedDirectoryCount: 2, + workspaceRecordCount: 3, + subscriptionCount: 2, + }); + + h.service.removeForWorkspaceId("ws1"); + expect(h.service.getMetrics()).toEqual({ + watchedDirectoryCount: 2, + workspaceRecordCount: 2, + subscriptionCount: 2, + }); + + h.service.dispose(); + expect(h.service.getMetrics()).toEqual({ + watchedDirectoryCount: 0, + workspaceRecordCount: 0, + subscriptionCount: 0, + }); + }); }); describe("git snapshot listener", () => { diff --git a/packages/server/src/server/session/workspace-git-observer/workspace-git-observer-service.ts b/packages/server/src/server/session/workspace-git-observer/workspace-git-observer-service.ts index a5729f2db..dfc87b312 100644 --- a/packages/server/src/server/session/workspace-git-observer/workspace-git-observer-service.ts +++ b/packages/server/src/server/session/workspace-git-observer/workspace-git-observer-service.ts @@ -19,6 +19,12 @@ interface WorkspaceGitWatchState { lastBranchName: string | null; } +export interface WorkspaceGitObserverMetrics { + watchedDirectoryCount: number; + workspaceRecordCount: number; + subscriptionCount: number; +} + /** * Observes a workspace's git state on disk (via WorkspaceGitService) and drives the * live update fan-out: branch-change notifications, workspace-card refreshes, and @@ -40,6 +46,7 @@ export interface WorkspaceGitObserverService { shouldSkipUpdate(workspaceId: string, workspace: WorkspaceDescriptorPayload | null): boolean; recordDescriptorState(workspaceId: string, workspace: WorkspaceDescriptorPayload | null): void; handleBranchSnapshot(cwd: string, branchName: string | null): void; + getMetrics(): WorkspaceGitObserverMetrics; removeForWorkspaceId(workspaceId: string): void; dispose(): void; } @@ -239,6 +246,14 @@ export function createWorkspaceGitObserverService(deps: { handleBranchSnapshot, + getMetrics() { + return { + watchedDirectoryCount: watchTargets.size, + workspaceRecordCount: workspaceStates.size, + subscriptionCount: subscriptions.size, + }; + }, + removeForWorkspaceId, dispose() { diff --git a/packages/server/src/server/test-utils/workspace-git-service-stub.ts b/packages/server/src/server/test-utils/workspace-git-service-stub.ts index 20f5d2ebb..5a28a5f49 100644 --- a/packages/server/src/server/test-utils/workspace-git-service-stub.ts +++ b/packages/server/src/server/test-utils/workspace-git-service-stub.ts @@ -71,6 +71,20 @@ export function createNoopWorkspaceGitService( scheduleRefreshForCwd: () => {}, onWorkspaceStateMayHaveChanged: () => {}, invalidateForge: () => {}, + getMetrics: () => ({ + workspaceTargetCount: 0, + workspaceListenerCount: 0, + repositoryTargetCount: 0, + repositoryWorkspaceLinkCount: 0, + workingTreeWatchTargetCount: 0, + workingTreeWatchListenerCount: 0, + workspaceObservationSetupInFlightCount: 0, + workingTreeWatchSetupInFlightCount: 0, + workspaceRefreshInFlightCount: 0, + workspaceRefreshQueuedCount: 0, + fetchInFlightCount: 0, + snapshotUpdatedListenerCount: 0, + }), dispose: () => {}, ...overrides, }; diff --git a/packages/server/src/server/websocket-server.ts b/packages/server/src/server/websocket-server.ts index 35929bb84..b7bc4b881 100644 --- a/packages/server/src/server/websocket-server.ts +++ b/packages/server/src/server/websocket-server.ts @@ -37,7 +37,13 @@ import type { HubRelationshipManagement } from "./hub/relationship-controller.js import type { HubExecutionAgents } from "./hub/daemon-executions.js"; import type { AgentProvider } from "./agent/agent-sdk-types.js"; import { ProviderSnapshotManager } from "./agent/provider-snapshot-manager.js"; -import type { WorkspaceGitRuntimeSnapshot, WorkspaceGitService } from "./workspace-git-service.js"; +import type { + WorkspaceGitRuntimeSnapshot, + WorkspaceGitService, + WorkspaceGitServiceMetrics, +} from "./workspace-git-service.js"; +import type { GitCommandRuntimeMetricsSnapshot } from "../utils/git-command-runtime-metrics.js"; +import { snapshotGitCommandRuntimeMetrics } from "../utils/run-git-command.js"; import type { WorkspaceAutoName } from "./workspace-auto-name.js"; import { deriveProjectSlug } from "./workspace-git-metadata.js"; import { PushTokenStore } from "./push/token-store.js"; @@ -119,9 +125,14 @@ interface WebSocketServerConfig { } type WebSocketRuntimeMetrics = SessionRuntimeMetrics & CheckoutDiffMetrics; +interface GitRuntimeMetrics { + commands: GitCommandRuntimeMetricsSnapshot; + workspaceService: WorkspaceGitServiceMetrics; +} type WebSocketRuntimeDiagnosticPayload = WebSocketRuntimeDiagnosticSnapshot< WebSocketRuntimeMetrics, - AgentMetricsSnapshot + AgentMetricsSnapshot, + GitRuntimeMetrics >; type WebSocketRuntimeMetricsLogPayload = Omit; @@ -211,6 +222,20 @@ function createFallbackWorkspaceGitService(): WorkspaceGitService { scheduleRefreshForCwd: () => {}, onWorkspaceStateMayHaveChanged: () => {}, invalidateForge: () => {}, + getMetrics: () => ({ + workspaceTargetCount: 0, + workspaceListenerCount: 0, + repositoryTargetCount: 0, + repositoryWorkspaceLinkCount: 0, + workingTreeWatchTargetCount: 0, + workingTreeWatchListenerCount: 0, + workspaceObservationSetupInFlightCount: 0, + workingTreeWatchSetupInFlightCount: 0, + workspaceRefreshInFlightCount: 0, + workspaceRefreshQueuedCount: 0, + fetchInFlightCount: 0, + snapshotUpdatedListenerCount: 0, + }), dispose: () => {}, }; } @@ -2044,6 +2069,9 @@ export class VoiceAssistantWebSocketServer { ); let terminalDirectorySubscriptionCount = 0; let terminalSubscriptionCount = 0; + let workspaceGitWatchedDirectoryCount = 0; + let workspaceGitWorkspaceRecordCount = 0; + let workspaceGitSubscriptionCount = 0; let inflightRequests = 0; let peakInflightRequests = 0; @@ -2051,6 +2079,9 @@ export class VoiceAssistantWebSocketServer { const sessionMetrics = connection.session.getRuntimeMetrics(); terminalDirectorySubscriptionCount += sessionMetrics.terminalDirectorySubscriptionCount; terminalSubscriptionCount += sessionMetrics.terminalSubscriptionCount; + workspaceGitWatchedDirectoryCount += sessionMetrics.workspaceGitWatchedDirectoryCount; + workspaceGitWorkspaceRecordCount += sessionMetrics.workspaceGitWorkspaceRecordCount; + workspaceGitSubscriptionCount += sessionMetrics.workspaceGitSubscriptionCount; inflightRequests += sessionMetrics.inflightRequests; peakInflightRequests = Math.max(peakInflightRequests, sessionMetrics.peakInflightRequests); connection.session.resetPeakInflight(); @@ -2060,6 +2091,9 @@ export class VoiceAssistantWebSocketServer { ...this.checkoutDiffManager.getMetrics(), terminalDirectorySubscriptionCount, terminalSubscriptionCount, + workspaceGitWatchedDirectoryCount, + workspaceGitWorkspaceRecordCount, + workspaceGitSubscriptionCount, inflightRequests, peakInflightRequests, }; @@ -2076,6 +2110,7 @@ export class VoiceAssistantWebSocketServer { ).length; const sessionMetrics = this.collectSessionRuntimeMetrics(); const agentSnapshot = this.agentManager.getMetricsSnapshot(); + const gitCommandMetrics = snapshotGitCommandRuntimeMetrics(); const loggedMetrics = { windowMs: runtimeMetrics.windowMs, final: Boolean(options?.final), @@ -2103,6 +2138,10 @@ export class VoiceAssistantWebSocketServer { runtime: sessionMetrics, latency: runtimeMetrics.latency, agents: agentSnapshot, + git: { + commands: gitCommandMetrics, + workspaceService: this.workspaceGitService.getMetrics(), + }, } satisfies WebSocketRuntimeMetricsLogPayload; this.lastRuntimeMetricsSnapshot = { diff --git a/packages/server/src/server/websocket/runtime-metrics.ts b/packages/server/src/server/websocket/runtime-metrics.ts index fbb31210f..8e7c5c6ff 100644 --- a/packages/server/src/server/websocket/runtime-metrics.ts +++ b/packages/server/src/server/websocket/runtime-metrics.ts @@ -46,6 +46,7 @@ export interface WebSocketRuntimeMetricsSnapshot { export interface WebSocketRuntimeDiagnosticSnapshot< TRuntime = unknown, TAgents = unknown, + TGit = unknown, > extends WebSocketRuntimeMetricsSnapshot { collectedAt: string; final: boolean; @@ -67,6 +68,7 @@ export interface WebSocketRuntimeDiagnosticSnapshot< memory: ProcessMemoryDiagnostics; runtime: TRuntime; agents: TAgents; + git: TGit; } type Clock = () => number; diff --git a/packages/server/src/server/workspace-git-service.ts b/packages/server/src/server/workspace-git-service.ts index 71209da34..7a2a108bb 100644 --- a/packages/server/src/server/workspace-git-service.ts +++ b/packages/server/src/server/workspace-git-service.ts @@ -173,9 +173,25 @@ export interface WorkspaceGitService { scheduleRefreshForCwd(cwd: string): void; onWorkspaceStateMayHaveChanged(cwd: string): void; invalidateForge(cwd: string): void; + getMetrics(): WorkspaceGitServiceMetrics; dispose(): void; } +export interface WorkspaceGitServiceMetrics { + workspaceTargetCount: number; + workspaceListenerCount: number; + repositoryTargetCount: number; + repositoryWorkspaceLinkCount: number; + workingTreeWatchTargetCount: number; + workingTreeWatchListenerCount: number; + workspaceObservationSetupInFlightCount: number; + workingTreeWatchSetupInFlightCount: number; + workspaceRefreshInFlightCount: number; + workspaceRefreshQueuedCount: number; + fetchInFlightCount: number; + snapshotUpdatedListenerCount: number; +} + export type WorkspaceGitListener = (snapshot: WorkspaceGitRuntimeSnapshot) => void; export type WorkspaceGitSnapshotUpdatedListener = (snapshot: WorkspaceGitRuntimeSnapshot) => void; @@ -454,6 +470,53 @@ export class WorkspaceGitServiceImpl implements WorkspaceGitService { }; } + getMetrics(): WorkspaceGitServiceMetrics { + let workspaceListenerCount = 0; + let repositoryWorkspaceLinkCount = 0; + let workingTreeWatchListenerCount = 0; + let workspaceRefreshInFlightCount = 0; + let workspaceRefreshQueuedCount = 0; + let workspaceObservationSetupInFlightCount = 0; + let fetchInFlightCount = 0; + + for (const target of this.workspaceTargets.values()) { + workspaceListenerCount += target.listeners.size; + if (target.observationSetupPromise) { + workspaceObservationSetupInFlightCount += 1; + } + if (target.refreshState.status === "in-flight") { + workspaceRefreshInFlightCount += 1; + if (target.refreshState.queued) { + workspaceRefreshQueuedCount += 1; + } + } + } + for (const target of this.repoTargets.values()) { + repositoryWorkspaceLinkCount += target.workspaceKeys.size; + if (target.fetchInFlight) { + fetchInFlightCount += 1; + } + } + for (const target of this.workingTreeWatchTargets.values()) { + workingTreeWatchListenerCount += target.listeners.size; + } + + return { + workspaceTargetCount: this.workspaceTargets.size, + workspaceListenerCount, + repositoryTargetCount: this.repoTargets.size, + repositoryWorkspaceLinkCount, + workingTreeWatchTargetCount: this.workingTreeWatchTargets.size, + workingTreeWatchListenerCount, + workspaceObservationSetupInFlightCount, + workingTreeWatchSetupInFlightCount: this.workingTreeWatchSetups.size, + workspaceRefreshInFlightCount, + workspaceRefreshQueuedCount, + fetchInFlightCount, + snapshotUpdatedListenerCount: this.snapshotUpdatedListeners.size, + }; + } + async getSnapshot( cwd: string, options?: WorkspaceGitSnapshotOptions, diff --git a/packages/server/src/utils/git-command-runtime-metrics.test.ts b/packages/server/src/utils/git-command-runtime-metrics.test.ts new file mode 100644 index 000000000..e5bcd75d2 --- /dev/null +++ b/packages/server/src/utils/git-command-runtime-metrics.test.ts @@ -0,0 +1,74 @@ +import { describe, expect, test } from "vitest"; +import { GitCommandRuntimeMetricsWindow } from "./git-command-runtime-metrics.js"; + +function createMetricsWindow(concurrencyLimit = 2) { + let now = 1_000; + return { + metrics: new GitCommandRuntimeMetricsWindow(concurrencyLimit, () => now), + advance(ms: number) { + now += ms; + }, + }; +} + +describe("GitCommandRuntimeMetricsWindow", () => { + test("separates queue wait from execution time", () => { + const { metrics, advance } = createMetricsWindow(); + const command = metrics.submit("status"); + advance(40); + metrics.start(command); + advance(15); + metrics.finish(command, { success: true, timedOut: false }); + + expect(metrics.snapshotAndReset()).toMatchObject({ + submitted: 1, + started: 1, + completed: 1, + failed: 0, + timedOut: 0, + queueWaitMs: { count: 1, p50Ms: 40, p95Ms: 40, maxMs: 40 }, + executionMs: { count: 1, p50Ms: 15, p95Ms: 15, maxMs: 15 }, + operationsTop: [["status", 1]], + }); + }); + + test("reports live queue pressure across window resets", () => { + const { metrics, advance } = createMetricsWindow(1); + const active = metrics.submit("fetch"); + metrics.start(active); + const pending = metrics.submit("rev-parse"); + metrics.observeLimiter(1, 1); + advance(25); + + expect(metrics.snapshotAndReset()).toMatchObject({ + concurrencyLimit: 1, + active: 1, + pending: 1, + peakActive: 1, + peakPending: 1, + oldestPendingMs: 25, + submitted: 2, + started: 1, + }); + + advance(10); + metrics.finish(active, { success: true, timedOut: false }); + metrics.start(pending); + metrics.observeLimiter(1, 0); + advance(5); + metrics.finish(pending, { success: false, timedOut: true }); + + expect(metrics.snapshotAndReset()).toMatchObject({ + active: 0, + pending: 0, + peakActive: 1, + peakPending: 1, + submitted: 0, + started: 1, + completed: 2, + failed: 1, + timedOut: 1, + queueWaitMs: { count: 1, p50Ms: 35, p95Ms: 35, maxMs: 35 }, + }); + }); +}); diff --git a/packages/server/src/utils/git-command-runtime-metrics.ts b/packages/server/src/utils/git-command-runtime-metrics.ts new file mode 100644 index 000000000..69ff54e35 --- /dev/null +++ b/packages/server/src/utils/git-command-runtime-metrics.ts @@ -0,0 +1,147 @@ +export interface GitCommandDurationStats { + count: number; + p50Ms: number; + p95Ms: number; + maxMs: number; +} + +export interface GitCommandRuntimeMetricsSnapshot { + concurrencyLimit: number; + active: number; + pending: number; + peakActive: number; + peakPending: number; + oldestPendingMs: number; + submitted: number; + started: number; + completed: number; + failed: number; + timedOut: number; + queueWaitMs: GitCommandDurationStats; + executionMs: GitCommandDurationStats; + operationsTop: Array<[string, number]>; +} + +interface GitCommandRuntimeMetric { + queuedAtMs: number; + startedAtMs: number | null; +} + +type Clock = () => number; + +export class GitCommandRuntimeMetricsWindow { + private readonly pendingCommands = new Set(); + private active = 0; + private peakActive = 0; + private peakPending = 0; + private submittedCount = 0; + private startedCount = 0; + private completedCount = 0; + private failedCount = 0; + private timedOutCount = 0; + private readonly queueWaitSamples: number[] = []; + private readonly executionSamples: number[] = []; + private readonly operationCounts = new Map(); + + constructor( + private readonly concurrencyLimit: number, + private readonly clock: Clock = Date.now, + ) {} + + submit(operation: string): GitCommandRuntimeMetric { + const metric = { queuedAtMs: this.clock(), startedAtMs: null }; + this.pendingCommands.add(metric); + this.submittedCount += 1; + this.operationCounts.set(operation, (this.operationCounts.get(operation) ?? 0) + 1); + return metric; + } + + observeLimiter(active: number, pending: number): void { + this.peakActive = Math.max(this.peakActive, active); + this.peakPending = Math.max(this.peakPending, pending); + } + + start(metric: GitCommandRuntimeMetric): void { + if (!this.pendingCommands.delete(metric)) { + return; + } + const now = this.clock(); + metric.startedAtMs = now; + this.active += 1; + this.startedCount += 1; + this.peakActive = Math.max(this.peakActive, this.active); + this.queueWaitSamples.push(Math.max(0, now - metric.queuedAtMs)); + } + + finish(metric: GitCommandRuntimeMetric, outcome: { success: boolean; timedOut: boolean }): void { + if (metric.startedAtMs === null) { + return; + } + const startedAtMs = metric.startedAtMs; + metric.startedAtMs = null; + this.active = Math.max(0, this.active - 1); + this.completedCount += 1; + if (!outcome.success) { + this.failedCount += 1; + } + if (outcome.timedOut) { + this.timedOutCount += 1; + } + this.executionSamples.push(Math.max(0, this.clock() - startedAtMs)); + } + + snapshotAndReset( + limiter = { active: this.active, pending: this.pendingCommands.size }, + ): GitCommandRuntimeMetricsSnapshot { + const now = this.clock(); + const oldestPendingAtMs = Math.min( + ...Array.from(this.pendingCommands, (metric) => metric.queuedAtMs), + ); + const snapshot: GitCommandRuntimeMetricsSnapshot = { + concurrencyLimit: this.concurrencyLimit, + active: limiter.active, + pending: limiter.pending, + peakActive: this.peakActive, + peakPending: this.peakPending, + oldestPendingMs: + limiter.pending > 0 && Number.isFinite(oldestPendingAtMs) + ? Math.max(0, now - oldestPendingAtMs) + : 0, + submitted: this.submittedCount, + started: this.startedCount, + completed: this.completedCount, + failed: this.failedCount, + timedOut: this.timedOutCount, + queueWaitMs: summarizeDurations(this.queueWaitSamples), + executionMs: summarizeDurations(this.executionSamples), + operationsTop: [...this.operationCounts.entries()] + .sort((left, right) => right[1] - left[1] || left[0].localeCompare(right[0])) + .slice(0, 12), + }; + + this.peakActive = limiter.active; + this.peakPending = limiter.pending; + this.submittedCount = 0; + this.startedCount = 0; + this.completedCount = 0; + this.failedCount = 0; + this.timedOutCount = 0; + this.queueWaitSamples.length = 0; + this.executionSamples.length = 0; + this.operationCounts.clear(); + return snapshot; + } +} + +function summarizeDurations(samples: number[]): GitCommandDurationStats { + if (samples.length === 0) { + return { count: 0, p50Ms: 0, p95Ms: 0, maxMs: 0 }; + } + const sorted = [...samples].sort((left, right) => left - right); + return { + count: sorted.length, + p50Ms: Math.round(sorted[Math.floor(sorted.length / 2)] ?? 0), + p95Ms: Math.round(sorted[Math.ceil(sorted.length * 0.95) - 1] ?? 0), + maxMs: Math.round(sorted[sorted.length - 1] ?? 0), + }; +} diff --git a/packages/server/src/utils/run-git-command.ts b/packages/server/src/utils/run-git-command.ts index d2b1fb9f5..254c98046 100644 --- a/packages/server/src/utils/run-git-command.ts +++ b/packages/server/src/utils/run-git-command.ts @@ -2,6 +2,10 @@ import { existsSync } from "node:fs"; import pLimit from "p-limit"; import type { Logger } from "pino"; import type { ProcessEnvRecord } from "../server/paseo-env.js"; +import { + GitCommandRuntimeMetricsWindow, + type GitCommandRuntimeMetricsSnapshot, +} from "./git-command-runtime-metrics.js"; import { spawnProcess } from "./spawn.js"; const DEFAULT_TIMEOUT_MS = 30_000; @@ -10,6 +14,7 @@ const DEFAULT_STDERR_LIMIT = 2048; const gitConcurrency = parseInt(process.env.PASEO_GIT_CONCURRENCY ?? "8", 10) || 8; const gitLimit = pLimit(gitConcurrency); +const gitRuntimeMetrics = new GitCommandRuntimeMetricsWindow(gitConcurrency); export interface GitCommandOptions { cwd: string; @@ -81,6 +86,13 @@ export function stopGitCommandMetrics(): GitCommandMetricsSnapshot { }; } +export function snapshotGitCommandRuntimeMetrics(): GitCommandRuntimeMetricsSnapshot { + return gitRuntimeMetrics.snapshotAndReset({ + active: gitLimit.activeCount, + pending: gitLimit.pendingCount, + }); +} + function beginGitCommandMetric(): GitCommandMetricsState | null { const state = gitCommandMetricsState; if (!state) { @@ -123,9 +135,11 @@ export function runGitCommand( args: string[], options: GitCommandOptions, ): Promise { - return gitLimit( + const runtimeMetric = gitRuntimeMetrics.submit(getGitOperation(args)); + const promise = gitLimit( () => new Promise((resolve, reject) => { + gitRuntimeMetrics.start(runtimeMetric); const timeout = options.timeout ?? DEFAULT_TIMEOUT_MS; const maxOutputBytes = options.maxOutputBytes ?? DEFAULT_MAX_OUTPUT_BYTES; const acceptExitCodes = options.acceptExitCodes ?? [0]; @@ -175,24 +189,28 @@ export function runGitCommand( callback(); }; - const finishMetricOnce = (metric: GitCommandMetric) => { + const finishMetricOnce = (metric: GitCommandMetric, timedOut = false) => { if (metricFinished) return; metricFinished = true; finishGitCommandMetric(metricsState, metric); + gitRuntimeMetrics.finish(runtimeMetric, { success: metric.success, timedOut }); }; const timer = setTimeout(() => { const error = new Error(`Git command timed out after ${timeout}ms: ${command}`); child.kill("SIGKILL"); - finishMetricOnce({ - args, - cwd: options.cwd, - startedAtMs: startedAt, - durationMs: Date.now() - startedAt, - exitCode: null, - signal: "SIGKILL", - success: false, - }); + finishMetricOnce( + { + args, + cwd: options.cwd, + startedAtMs: startedAt, + durationMs: Date.now() - startedAt, + exitCode: null, + signal: "SIGKILL", + success: false, + }, + true, + ); settle(() => reject(error)); }, timeout); @@ -318,8 +336,14 @@ export function runGitCommand( }); }), ); + gitRuntimeMetrics.observeLimiter(gitLimit.activeCount, gitLimit.pendingCount); + return promise; } function formatGitCommand(args: string[]): string { return ["git", ...args].join(" "); } + +function getGitOperation(args: string[]): string { + return args[0] === "-c" ? (args[2] ?? "unknown") : (args[0] ?? "unknown"); +}