diff --git a/packages/core/src/boot-phase.ts b/packages/core/src/boot-phase.ts new file mode 100644 index 000000000000..6804e5d8499d --- /dev/null +++ b/packages/core/src/boot-phase.ts @@ -0,0 +1,51 @@ +export * as BootPhase from "./boot-phase" + +import { Context, Effect, Layer } from "effect" + +/** + * Mutable per-boot phase durations in fractional milliseconds, keyed by phase + * name. Present only on fibers descending from a recorded location boot. + */ +export type Phases = Record + +const Current = Context.Reference("@opencode/BootPhase/Current", { + defaultValue: () => undefined, +}) + +/** + * Attributes the duration of `effect` to `name` when the current fiber belongs + * to a recorded location boot; otherwise runs `effect` untouched. Repeated + * calls accumulate, and a tracked call nested inside another (wellknown inside + * config discovery) counts toward both names. + * + * Durations are wall-clock, so concurrent boots time-slicing the JS thread + * inflate each other's phases; the breakdown attributes where a boot spent its + * wait, not exclusive CPU cost. + */ +export const track = (name: string, effect: Effect.Effect): Effect.Effect => + Effect.gen(function* () { + const phases = yield* Current + if (!phases) return yield* effect + const start = performance.now() + return yield* Effect.onExit(effect, () => + Effect.sync(() => { + phases[name] = (phases[name] ?? 0) + performance.now() - start + }), + ) + }) + +/** + * Runs `layer`'s build with `phases` receiving tracked phase durations. Forked + * fibers inherit the recorder, so late recordings after boot completes mutate + * an already-reported object and are harmless. + */ +export function record(layer: Layer.Layer, phases: Phases): Layer.Layer { + return Layer.fromBuild((memoMap, scope) => + Effect.provideService(Layer.buildWithMemoMap(layer, memoMap, scope), Current, phases), + ) +} + +/** Rounds recorded durations for logging. */ +export function summarize(phases: Phases): Record { + return Object.fromEntries(Object.entries(phases).map(([name, duration]) => [name, Math.round(duration)])) +} diff --git a/packages/core/src/config.ts b/packages/core/src/config.ts index 781e3f63b243..9dee3d30e6b9 100644 --- a/packages/core/src/config.ts +++ b/packages/core/src/config.ts @@ -8,6 +8,7 @@ import { Context, Effect, Layer, Option, PubSub, Ref, Schema, Semaphore, Stream import { Permission } from "@opencode-ai/schema/permission" import { Config as ConfigSchema } from "@opencode-ai/schema/config" import { Integration } from "@opencode-ai/schema/integration" +import { BootPhase } from "./boot-phase" import { Credential } from "./credential" import { Bus } from "./bus" import { Watcher } from "./filesystem/watcher" @@ -258,7 +259,13 @@ export const layer = (options?: Options) => Layer.effect( ) if (!credential || credential.value.type !== "key") return [] const variables = { [auth.env]: credential.value.key } - const configs = yield* wellknown.resolve(entry, variables).pipe(Effect.orDie) + const configs = yield* wellknown.resolve(entry, variables).pipe( + Effect.catch(() => + Effect.logWarning("failed to load wellknown config", { source: entry.origin }).pipe( + Effect.as([] as const), + ), + ), + ) return yield* Effect.forEach(configs, (config) => ConfigVariable.substitute({ type: "virtual", @@ -369,12 +376,12 @@ export const layer = (options?: Options) => Layer.effect( ...explicit, ...direct, ...supplementary.slice(1).flat(), - ...(yield* loadWellknown().pipe(Effect.orDie)), + ...(yield* BootPhase.track("wellknown", loadWellknown().pipe(Effect.orDie))), ...content, ] }) - const initial = yield* discover() + const initial = yield* BootPhase.track("config", discover()) let configs = initial const updates = yield* PubSub.unbounded() // Vendored trees inside config roots (a plugin's node_modules, a nested @@ -461,7 +468,7 @@ export const layer = (options?: Options) => Layer.effect( Effect.forever, Effect.forkScoped({ startImmediately: true }), ) - yield* reconcile(initial) + yield* BootPhase.track("watch", reconcile(initial)) return Service.of({ entries: Effect.fn("Config.entries")(function* () { diff --git a/packages/core/src/location-services.ts b/packages/core/src/location-services.ts index 547cdd0e4557..3c9f96ef65f8 100644 --- a/packages/core/src/location-services.ts +++ b/packages/core/src/location-services.ts @@ -1,6 +1,7 @@ import { Effect, Layer, LayerMap } from "effect" import { Agent } from "./agent" import { AISDK } from "./aisdk" +import { BootPhase } from "./boot-phase" import { Catalog } from "./catalog" import { Command } from "./command" import { Config } from "./config" @@ -118,6 +119,7 @@ export function buildLocationServiceMap( LayerMap.make( (ref: Location.Ref) => { const startedAt = performance.now() + const phases: BootPhase.Phases = {} 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 @@ -125,16 +127,22 @@ export function buildLocationServiceMap( // those back out. const location = LayerNode.hoist(locationServices, Node.tags.values.global, allReplacements) - return 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), - }), + return BootPhase.record( + 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), + // Unattributed remainder is node construction and, under + // concurrent boots, time-slicing against other builds. + phaseMs: BootPhase.summarize(phases), + }), + ), + Layer.provide(LayerNode.compile(location.hoisted)), ), - Layer.provide(LayerNode.compile(location.hoisted)), + phases, ) }, { idleTimeToLive: "60 minutes" }, diff --git a/packages/core/src/location.ts b/packages/core/src/location.ts index ac27cb6ca9e4..61224b4846b6 100644 --- a/packages/core/src/location.ts +++ b/packages/core/src/location.ts @@ -1,5 +1,6 @@ import { Context, Effect, Layer } from "effect" import { Info, Ref, response } from "@opencode-ai/schema/location" +import { BootPhase } from "./boot-phase" import { Project } from "./project" import { LayerNode } from "@opencode-ai/util/effect/layer-node" import { makeLocationNode, tags } from "@opencode-ai/util/effect/app-node" @@ -21,7 +22,7 @@ const layer = (ref: Ref) => Service, Effect.gen(function* () { const project = yield* Project.Service - const resolved = yield* project.resolve(ref.directory) + const resolved = yield* BootPhase.track("project", project.resolve(ref.directory)) return Service.of({ directory: ref.directory, workspaceID: ref.workspaceID, diff --git a/packages/core/src/wellknown.ts b/packages/core/src/wellknown.ts index db5862a94886..4120690b0ce3 100644 --- a/packages/core/src/wellknown.ts +++ b/packages/core/src/wellknown.ts @@ -57,11 +57,17 @@ export const Event = { Updated: Bus.ephemeral({ type: "wellknown.updated", schema: {} }), } +// Wellknown fetches sit on the cold location build path, which is on the HTTP +// response path; an unresponsive origin must degrade into a tolerated error +// instead of stalling every request for that location. +const fetchTimeout = "10 seconds" + export const inspect = Effect.fn("WellKnown.inspect")(function* (origin: string) { const url = `${origin.replace(/\/+$/, "")}/.well-known/opencode` const http = HttpClient.filterStatusOk(yield* HttpClient.HttpClient) return yield* http.execute(HttpClientRequest.get(url).pipe(HttpClientRequest.acceptJson)).pipe( Effect.flatMap(HttpClientResponse.schemaBodyJson(Manifest)), + Effect.timeout(fetchTimeout), Effect.mapError((cause) => new Error(`Failed to load wellknown manifest from ${url}`, { cause })), ) }) @@ -89,6 +95,7 @@ const resolveEntry = Effect.fnUntraced(function* (entry: Entry, variables: Reado .execute(HttpClientRequest.get(url).pipe(HttpClientRequest.acceptJson, HttpClientRequest.setHeaders(headers))) .pipe( Effect.flatMap(HttpClientResponse.schemaBodyJson(Config)), + Effect.timeout(fetchTimeout), Effect.mapError((cause) => new Error(`Failed to load wellknown remote config from ${url}`, { cause })), ) if (Schema.is(Config)(remote.config)) return [...configs, remote.config] diff --git a/packages/core/test/config/config.test.ts b/packages/core/test/config/config.test.ts index 1b4373cf2e49..45440a16caf5 100644 --- a/packages/core/test/config/config.test.ts +++ b/packages/core/test/config/config.test.ts @@ -307,7 +307,7 @@ describe("Config", () => { }), ) - it.live("loads authenticated wellknown config at highest priority", () => + it.live("tolerates unavailable authenticated wellknown config and reloads it later", () => Effect.acquireUseRelease( Effect.promise(() => tmpdir()), (tmp) => @@ -322,6 +322,7 @@ describe("Config", () => { }) const integrationID = Integration.ID.make("https://example.com") + let available = false let key = "secret" const credentialNode = makeGlobalNode({ service: Credential.Service, @@ -362,7 +363,10 @@ describe("Config", () => { refresh: () => Effect.succeed(false), add: () => Effect.die("unused Wellknown.add"), remove: () => Effect.die("unused Wellknown.remove"), - resolve: (_entry, variables) => Effect.succeed([{ shell: variables.TOKEN }]), + resolve: (_entry, variables) => + available + ? Effect.succeed([{ shell: variables.TOKEN }]) + : Effect.fail(new Error("expired credential")), }), ), deps: [], @@ -371,11 +375,16 @@ describe("Config", () => { return yield* Effect.gen(function* () { const config = yield* Config.Service const bus = yield* Bus.Service - expect(Config.latest(yield* config.entries(), "shell")).toBe("secret") + const initial = yield* config.entries() + expect(Config.latest(initial, "shell")).toBe("project") + expect( + initial.flatMap((entry) => (entry.type === "document" && entry.info.shell ? [entry.info.shell] : [])), + ).toEqual(["global", "project"]) const updated = yield* bus .subscribe(ConfigSchema.Event.Updated) .pipe(Stream.take(1), Stream.runCollect, Effect.forkScoped) yield* Effect.yieldNow + available = true key = "next" yield* bus.publish(Integration.Event.ConnectionUpdated, { integrationID }) expect(yield* Fiber.join(updated)).toHaveLength(1) diff --git a/packages/core/test/location-layer.test.ts b/packages/core/test/location-layer.test.ts index bf897a6b1a61..34ee6cba3714 100644 --- a/packages/core/test/location-layer.test.ts +++ b/packages/core/test/location-layer.test.ts @@ -3,7 +3,7 @@ import path from "path" import { describe, expect } from "bun:test" import { Config } from "@opencode-ai/schema/config" import { Money } from "@opencode-ai/schema/money" -import { DateTime, Deferred, Effect, Equal, Fiber, Hash, RcMap, Schema, Stream } from "effect" +import { DateTime, Deferred, Effect, Equal, Fiber, Hash, Logger, RcMap, Schema, Stream } from "effect" import { Plugin as EffectPlugin } from "@opencode-ai/plugin/effect" import { Agent } from "@opencode-ai/core/agent" import { Catalog } from "@opencode-ai/core/catalog" @@ -111,6 +111,39 @@ describe("LocationServiceMap", () => { ), ) + it.live("attributes boot phases in the booted log", () => { + const booted: Record[] = [] + const logger = Logger.map(Logger.formatStructured, (entry) => { + if (!Array.isArray(entry.message) || entry.message[0] !== "location services booted") return + const details = entry.message[1] + if (typeof details === "object" && details !== null) booted.push(details as Record) + }) + return Effect.acquireRelease( + Effect.promise(() => tmpdir()), + (dir) => Effect.promise(() => dir[Symbol.asyncDispose]()), + ).pipe( + Effect.flatMap((dir) => + Effect.gen(function* () { + const locations = yield* LocationServiceMap.Service + yield* locations + .contextEffect(Location.Ref.make({ directory: AbsolutePath.make(dir.path) })) + .pipe(Effect.scoped) + + expect(booted).toHaveLength(1) + const entry = booted[0]! + expect(typeof entry.durationMs).toBe("number") + const phaseMs = entry.phaseMs as Record + expect(Object.keys(phaseMs).toSorted()).toEqual(["config", "project", "watch", "wellknown"]) + for (const duration of Object.values(phaseMs)) { + expect(duration).toBeGreaterThanOrEqual(0) + expect(duration).toBeLessThanOrEqual(entry.durationMs as number) + } + }), + ), + Effect.provide(Logger.layer([logger])), + ) + }) + itWithSdk.live("reruns activation for SDK plugins registered during startup", () => Effect.acquireRelease( Effect.promise(() => tmpdir()),