test(core): verify event loop monitor cleanup

packages/core/src/filesystem/search.ts

@@ -20,6 +20,8 @@ export interface Interface {
 
 export class Service extends Context.Service<Service, Interface>()("@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(() => {

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" },
       ),

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()
+    },
+  }
+}

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<A, E, R>(name: string, effect: Effect.Effect<A, E, R>) {
+  return effect.pipe(
+    Effect.timed,
+    Effect.map(([duration, value]) => ({ durationMs: Math.round(Duration.toMillis(duration)), value })),
+    Effect.withSpan(name),
+  )
+}

packages/core/test/effect/observability.test.ts

@@ -6,10 +6,24 @@ 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()
+  const stoppedAt = performance.now()
+  while (performance.now() - stoppedAt < 60) {}
+  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