diff --git a/packages/core/src/filesystem/search.ts b/packages/core/src/filesystem/search.ts index a2b21d32cd..4152214341 100644 --- a/packages/core/src/filesystem/search.ts +++ b/packages/core/src/filesystem/search.ts @@ -20,6 +20,8 @@ export interface Interface { export class Service extends Context.Service()("@opencode/v2/FileSystem/Search") {} +const FffScanObservationMs = 60_000 + export const ripgrepLayer = Layer.effect( Service, Effect.gen(function* () { @@ -123,6 +125,7 @@ export const fffLayer = Layer.effect( Service, Effect.gen(function* () { const location = yield* Location.Service + const startedAt = performance.now() const result = yield* Effect.try({ try: () => Fff.create({ @@ -134,6 +137,7 @@ export const fffLayer = Layer.effect( catch: (cause) => cause, }).pipe( Effect.catch((error) => Effect.logWarning("failed to initialize fff", { error }).pipe(Effect.as(undefined))), + Effect.withSpan("FileSystemSearch.fff.create"), ) if (!result?.ok) { if (result) yield* Effect.logWarning("failed to initialize fff", { error: result.error }) @@ -144,6 +148,28 @@ export const fffLayer = Layer.effect( }) } yield* Effect.addFinalizer(() => Effect.sync(() => result.value.destroy()).pipe(Effect.ignore)) + yield* Effect.logInfo("fff initialized", { + durationMs: Math.round(performance.now() - startedAt), + scanning: result.value.isScanning(), + }) + yield* Effect.tryPromise({ + try: () => result.value.waitForScan(FffScanObservationMs), + catch: (cause) => cause, + }).pipe( + Effect.flatMap((scan) => { + const data = { durationMs: Math.round(performance.now() - startedAt) } + if (!scan.ok) return Effect.logWarning("fff initial scan failed", data) + if (!scan.value) return Effect.logWarning("fff initial scan still running", data) + return Effect.logInfo("fff initial scan completed", data) + }), + Effect.catch(() => + Effect.logWarning("failed to observe fff initial scan", { + durationMs: Math.round(performance.now() - startedAt), + }), + ), + Effect.withSpan("FileSystemSearch.fff.scan"), + Effect.forkScoped, + ) return Service.of({ glob: (input) => Effect.sync(() => { diff --git a/packages/core/src/location-services.ts b/packages/core/src/location-services.ts index 47e3f6dd2f..2cefbccdbe 100644 --- a/packages/core/src/location-services.ts +++ b/packages/core/src/location-services.ts @@ -45,6 +45,7 @@ import { ReadToolFileSystem } from "./tool/read-filesystem" import { ToolRegistry } from "./tool/registry" import { ToolOutputStore } from "./tool-output-store" import { Vcs } from "./vcs" +import { makeEventLoopDelayMonitor } from "./observability/event-loop-delay" export { LocationServiceMap } from "./location-service-map" @@ -114,25 +115,37 @@ export function buildLocationServiceMap( Effect.map( LayerMap.make( (ref: Location.Ref) => { - const startedAt = performance.now() const allReplacements = replacements.concat([[Location.node, Location.boundNode(ref)]]) // Apply replacements during hoist, not afterward: replacements can // introduce new tagged dependencies (Location.boundNode depends on // Project), and the hoist walk is the only pass that can still slice // those back out. const location = LayerNode.hoist(locationServices, Node.tags.values.global, allReplacements) - - return LayerNode.compile(location.node).pipe( + const compiled = LayerNode.compile(location.node).pipe( Layer.fresh, - Layer.tap(() => - Effect.logInfo("location services booted", { - directory: ref.directory, - workspaceID: ref.workspaceID, - durationMs: Math.round(performance.now() - startedAt), - }), - ), Layer.provide(LayerNode.compile(location.hoisted)), ) + return Layer.fromBuild((memoMap, scope) => + Effect.acquireUseRelease( + Effect.sync(() => ({ + startedAt: performance.now(), + eventLoopDelay: makeEventLoopDelayMonitor(), + })), + (diagnostics) => + Layer.buildWithMemoMap(compiled, memoMap, scope).pipe( + Effect.tap(() => + Effect.logInfo("location services booted", { + directory: ref.directory, + workspaceID: ref.workspaceID, + durationMs: Math.round(performance.now() - diagnostics.startedAt), + eventLoopDelayMaxMs: Math.round(diagnostics.eventLoopDelay.maxMs()), + }), + ), + Effect.withSpan("LocationServices.acquire"), + ), + (diagnostics) => Effect.sync(() => diagnostics.eventLoopDelay.stop()), + ), + ) }, { idleTimeToLive: "60 minutes" }, ), diff --git a/packages/core/src/observability/event-loop-delay.ts b/packages/core/src/observability/event-loop-delay.ts new file mode 100644 index 0000000000..9db6198ade --- /dev/null +++ b/packages/core/src/observability/event-loop-delay.ts @@ -0,0 +1,27 @@ +const ResolutionMs = 20 + +export function makeEventLoopDelayMonitor() { + const state = { + expectedAt: performance.now() + ResolutionMs, + maxMs: 0, + stoppedAt: undefined as number | undefined, + } + const timer = setInterval(() => { + const now = performance.now() + state.maxMs = Math.max(state.maxMs, now - state.expectedAt) + state.expectedAt = now + ResolutionMs + }, ResolutionMs) + timer.unref() + + const maxMs = () => Math.max(0, state.maxMs, (state.stoppedAt ?? performance.now()) - state.expectedAt) + return { + maxMs, + stop: () => { + if (state.stoppedAt === undefined) { + state.stoppedAt = performance.now() + clearInterval(timer) + } + return maxMs() + }, + } +} diff --git a/packages/core/src/project/copy.ts b/packages/core/src/project/copy.ts index 9183e26eb9..b0927483a2 100644 --- a/packages/core/src/project/copy.ts +++ b/packages/core/src/project/copy.ts @@ -1,6 +1,6 @@ export * as ProjectCopy from "./copy" -import { Context, Effect, Layer, Schema } from "effect" +import { Context, Duration, Effect, Layer, Schema } from "effect" import path from "path" import { AbsolutePath } from "../schema" import { FSUtil } from "../fs-util" @@ -15,6 +15,7 @@ import { Database } from "../database/database" import { Location } from "../location" import { Event } from "@opencode-ai/schema/project-directories" import { ProjectCopy } from "@opencode-ai/schema/project-copy" +import { makeEventLoopDelayMonitor } from "../observability/event-loop-delay" export const StrategyID = ProjectCopy.StrategyID export type StrategyID = typeof StrategyID.Type @@ -214,60 +215,102 @@ const layer = Layer.effect( }) const refresh = Effect.fn("ProjectCopy.refresh")(function* (input: RefreshInput) { - const stored = yield* directories.list(input.projectID) - const checked = yield* Effect.forEach( - stored, - (item) => fs.isDir(item.directory).pipe(Effect.map((exists) => ({ ...item, exists }))), - { concurrency: "unbounded" }, - ) - const sourceDirectories = checked - .filter((item) => item.strategy === undefined && item.exists) - .map((item) => item.directory) - const discovered = yield* Effect.forEach( - sourceDirectories, - (sourceDirectory) => - Effect.forEach(strategies(), (strategy) => - strategy.list(sourceDirectory).pipe( - Effect.catchTag("ProjectCopy.DirectoryUnavailableError", () => Effect.succeed([])), - Effect.map((items) => - items.map((item) => ({ - directory: item.directory, - strategy: item.type === "copy" ? strategy.id : undefined, - })), + return yield* Effect.acquireUseRelease( + Effect.sync(makeEventLoopDelayMonitor), + (eventLoopDelay) => + Effect.gen(function* () { + const startedAt = performance.now() + const loaded = yield* timed("ProjectCopy.refresh.load", directories.list(input.projectID)) + const checked = yield* timed( + "ProjectCopy.refresh.check", + Effect.forEach( + loaded.value, + (item) => fs.isDir(item.directory).pipe(Effect.map((exists) => ({ ...item, exists }))), + { concurrency: "unbounded" }, ), - ), - ), - { concurrency: "unbounded" }, - ).pipe( - Effect.map((sets) => new Map(sets.flat(2).map((item) => [item.directory, item] as const)).values().toArray()), - ) - const removed = checked.filter((item) => !item.exists).map((item) => item.directory) - const result = yield* db - .transaction((tx) => - Effect.all({ - updated: Effect.forEach(discovered, (item) => - directories.create( - { - projectID: input.projectID, - directory: item.directory, - strategy: item.strategy, - behavior: "replace", - }, - tx, + ) + const sourceDirectories = checked.value + .filter((item) => item.strategy === undefined && item.exists) + .map((item) => item.directory) + const discovered = yield* timed( + "ProjectCopy.refresh.discover", + Effect.forEach( + sourceDirectories, + (sourceDirectory) => + Effect.forEach(strategies(), (strategy) => + strategy.list(sourceDirectory).pipe( + Effect.catchTag("ProjectCopy.DirectoryUnavailableError", () => Effect.succeed([])), + Effect.map((items) => + items.map((item) => ({ + directory: item.directory, + strategy: item.type === "copy" ? strategy.id : undefined, + })), + ), + ), + ), + { concurrency: "unbounded" }, + ).pipe( + Effect.map((sets) => + new Map(sets.flat(2).map((item) => [item.directory, item] as const)).values().toArray(), + ), ), - ), - removed: Effect.forEach(removed, (directory) => - directories.remove({ projectID: input.projectID, directory }, tx), - ), + ) + const removed = checked.value.filter((item) => !item.exists).map((item) => item.directory) + const committed = yield* timed( + "ProjectCopy.refresh.commit", + db + .transaction((tx) => + Effect.all({ + updated: Effect.forEach(discovered.value, (item) => + directories.create( + { + projectID: input.projectID, + directory: item.directory, + strategy: item.strategy, + behavior: "replace", + }, + tx, + ), + ), + removed: Effect.forEach(removed, (directory) => + directories.remove({ projectID: input.projectID, directory }, tx), + ), + }), + ) + .pipe(Effect.orDie), + ) + const changes = { + updated: discovered.value + .filter((_, index) => committed.value.updated[index]) + .map((item) => item.directory), + removed: removed.filter((_, index) => committed.value.removed[index]), + } + const published = yield* timed( + "ProjectCopy.refresh.publish", + changed(input.projectID, changes.updated.length > 0 || changes.removed.length > 0), + ) + yield* Effect.logInfo("project copy refresh diagnostics", { + projectID: input.projectID, + durationMs: Math.round(performance.now() - startedAt), + eventLoopDelayMaxMs: Math.round(eventLoopDelay.maxMs()), + stored: loaded.value.length, + sources: sourceDirectories.length, + strategies: strategies().length, + discovered: discovered.value.length, + updated: changes.updated.length, + removed: changes.removed.length, + stages: { + loadMs: loaded.durationMs, + checkMs: checked.durationMs, + discoverMs: discovered.durationMs, + commitMs: committed.durationMs, + publishMs: published.durationMs, + }, + }) + return changes }), - ) - .pipe(Effect.orDie) - const changes = { - updated: discovered.filter((_, index) => result.updated[index]).map((item) => item.directory), - removed: removed.filter((_, index) => result.removed[index]), - } - yield* changed(input.projectID, changes.updated.length > 0 || changes.removed.length > 0) - return changes + (eventLoopDelay) => Effect.sync(() => eventLoopDelay.stop()), + ) }) return Service.of({ @@ -290,3 +333,11 @@ export const refreshNode = makeLocationNode({ layer: Layer.effectDiscard(refreshAfterBoot), deps: [node, Location.node], }) + +function timed(name: string, effect: Effect.Effect) { + return effect.pipe( + Effect.timed, + Effect.map(([duration, value]) => ({ durationMs: Math.round(Duration.toMillis(duration)), value })), + Effect.withSpan(name), + ) +} diff --git a/packages/core/test/effect/observability.test.ts b/packages/core/test/effect/observability.test.ts index c075986364..0dcebba53f 100644 --- a/packages/core/test/effect/observability.test.ts +++ b/packages/core/test/effect/observability.test.ts @@ -6,10 +6,22 @@ import os from "os" import path from "path" import { fileLogger } from "../../src/observability/logging" import { resource } from "../../src/observability/otlp" +import { makeEventLoopDelayMonitor } from "../../src/observability/event-loop-delay" const otelResourceAttributes = process.env.OTEL_RESOURCE_ATTRIBUTES const opencodeClient = process.env.OPENCODE_CLIENT +test("measures an immediate event-loop block and stops sampling", async () => { + const monitor = makeEventLoopDelayMonitor() + const startedAt = performance.now() + while (performance.now() - startedAt < 60) {} + const maxMs = monitor.stop() + await Bun.sleep(40) + + expect(maxMs).toBeGreaterThanOrEqual(20) + expect(monitor.maxMs()).toBe(maxMs) +}) + afterEach(() => { if (otelResourceAttributes === undefined) delete process.env.OTEL_RESOURCE_ATTRIBUTES else process.env.OTEL_RESOURCE_ATTRIBUTES = otelResourceAttributes