From 4407df6c03048cfba697a6e1b01d7325626893d8 Mon Sep 17 00:00:00 2001 From: Alex Knight Date: Tue, 21 Apr 2026 22:06:13 +1000 Subject: [PATCH] perf(plugin-sdk): per-phase + per-jiti-call probes for bundled channel entries (#69537) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * perf(plugin-sdk): per-phase + per-jiti-call probes for bundled channel entries Extends the existing OPENCLAW_PLUGIN_LOAD_PROFILE infrastructure (see src/plugins/loader.ts `profilePluginLoaderSync` and src/plugins/source-loader.ts) with two new probe sites inside src/plugin-sdk/channel-entry-contract.ts: 1. `bundled-register:` — wraps each phase of `defineBundledChannelEntry`'s register() callback (`setChannelRuntime`, `loadChannelPlugin`, `registerChannel`, `registerCliMetadata`, `registerFull`). Lets us pinpoint which phase of plugin registration is responsible for cold-start cost on a per-plugin basis. 2. `bundled-entry-module-load` — instruments `loadBundledEntryModuleSync` and reports `getJitiMs` (jiti loader factory) vs `jitiCallMs` (actual graph walk + transpile + ESM linking) separately. Lets us distinguish alias-map / loader setup overhead from import-graph traversal cost on a per-module basis. Both probes are gated on OPENCLAW_PLUGIN_LOAD_PROFILE=1 and have zero overhead when the env flag is unset (early return before any `performance.now()` call). Log format matches the existing `[plugin-load-profile]` line shape so existing log scrapers continue to work. The helper is a file-local mirror of `profilePluginLoaderSync` rather than a new SDK export — keeps the SDK boundary narrow per src/plugin-sdk/AGENTS.md and avoids cross-importing host internals. Used to validate PR #69317 (slack startup perf) — measurements showed slack `setChannelRuntime` dropping from 13183ms to 67ms after barrel narrowing, which would have been undiagnosable without these per-phase probes. * perf(plugins): per-plugin register() probe in plugin loader Adds a `phase=${registrationMode}:register` probe wrapping each call to `runPluginRegisterSync(register, api)` in src/plugins/loader.ts. Emits the established `[plugin-load-profile]` line shape via `profilePluginLoaderSync`, gated on OPENCLAW_PLUGIN_LOAD_PROFILE=1. Two call sites are wrapped: - The main load path (registrationMode is dynamic: "snapshot", "validate", "full") at the post-snapshot register block. Emits e.g. `phase=full:register plugin=slack elapsedMs=14102.1 source=...` - The cli-metadata-only path (registrationMode hardcoded to "cli-metadata") for fast `--metadata` boot flows. Together with the existing `phase=full` (entire load) and `phase=source-loader` probes plus the `bundled-register:*` and `bundled-entry-module-load` probes added in the previous commit, this gives a full breakdown: - `phase=full plugin=slack` — total cost from import through register return - `phase=full:register plugin=slack` — just the register() callback (NEW) - `phase=bundled-register:setChannelRuntime plugin=slack` — sub-phase - `phase=bundled-register:loadChannelPlugin plugin=slack` — sub-phase - `phase=bundled-entry-module-load plugin=(bundled-entry)` — per-module load Lets you `sort -k4 -n -r` the log output to find the slowest plugin's register() call across all bundled+third-party plugins, then drill in via the sub-phase probes for bundled entries. * perf(plugins): consolidate plugin-load-profile primitives in shared module Extracts the previously duplicated `shouldProfilePluginLoader` / `profilePluginLoaderSync` helpers into a new `src/plugins/plugin-load-profile.ts` module. Removes 3 file-local copies of the same env-flag check and 2 near-duplicate `try { run() } finally { console.error(...) }` wrappers. Files updated: - NEW src/plugins/plugin-load-profile.ts — sole owner of: shouldProfilePluginLoader() profilePluginLoaderSync({phase, pluginId?, source, run, extras?}) formatPluginLoadProfileLine({phase, pluginId?, source, elapsedMs, extras?}) - src/plugins/loader.ts — drop file-local copies, import shared helper (existing 4 + new 2 call sites unchanged in shape) - src/plugins/source-loader.ts — drop renamed local copy (`shouldProfilePluginSourceLoader`), use shared helper with `pluginId: "(direct)"` to preserve the existing `plugin=(direct)` field - src/plugin-sdk/channel-entry-contract.ts — drop file-local copies and inline `profileStep` closure; use shared `profilePluginLoaderSync` directly at all 5 `bundled-register:*` call sites; dual-timing `bundled-entry-module-load` probe uses `formatPluginLoadProfileLine` with ordered `extras` for `getJitiMs`/`jitiCallMs` Log line format is byte-for-byte identical to before (validated against 3 cases: standard, with pluginId, dual-timing). The `extras` API is intentionally an ordered tuple list (not a record) so that scrapers see deterministic field order between `elapsedMs=` and `source=`. Net: +155/-87 lines across 4 files, removing ~60 lines of duplication while exposing a stable, documented probe surface. Verified: - pnpm tsgo (core) — 0 errors - pnpm lint on all 4 files — 0 warnings, 0 errors - pnpm test src/plugins/loader.test.ts — 102/102 - pnpm test src/plugins/contracts/plugin-entry-guardrails.test.ts — 7/7 - pnpm test src/plugin-sdk/channel-entry-contract.test.ts — 4/4 - Standalone formatter smoke test — output matches existing format byte-for-byte * refactor(plugins): rename profilePluginLoaderSync to withProfile and bind scope at register sites * fix(plugin-sdk): zero jiti sub-step timings on Win32 nodeRequire fast-path --- src/plugin-sdk/channel-entry-contract.test.ts | 47 ++++++ src/plugin-sdk/channel-entry-contract.ts | 53 ++++++- src/plugins/loader.ts | 79 ++++------ src/plugins/plugin-load-profile.ts | 135 ++++++++++++++++++ src/plugins/source-loader.ts | 22 +-- 5 files changed, 265 insertions(+), 71 deletions(-) create mode 100644 src/plugins/plugin-load-profile.ts diff --git a/src/plugin-sdk/channel-entry-contract.test.ts b/src/plugin-sdk/channel-entry-contract.test.ts index 029a2cc7149..45b43fd797d 100644 --- a/src/plugin-sdk/channel-entry-contract.test.ts +++ b/src/plugin-sdk/channel-entry-contract.test.ts @@ -133,6 +133,53 @@ describe("loadBundledEntryExportSync", () => { }); }); + it("emits zero jiti sub-step timings on the Win32 nodeRequire fast-path", async () => { + // The Win32 fast-path goes through `nodeRequire` directly and never + // touches jiti. The plugin-load-profile line must reflect that with + // `getJitiMs=0.0 jitiCallMs=0.0` rather than negative or full-elapsed + // values that would mis-attribute nodeRequire time to jiti sub-steps. + const platformSpy = vi.spyOn(process, "platform", "get").mockReturnValue("win32"); + vi.stubEnv("OPENCLAW_PLUGIN_LOAD_PROFILE", "1"); + const errorSpy = vi.spyOn(console, "error").mockImplementation(() => undefined); + + try { + const channelEntryContract = await importFreshModule< + typeof import("./channel-entry-contract.js") + >(import.meta.url, "./channel-entry-contract.js?scope=win32-profile-fast-path"); + + const tempRoot = fs.mkdtempSync(path.join(os.tmpdir(), "openclaw-channel-entry-contract-")); + tempDirs.push(tempRoot); + + const pluginRoot = path.join(tempRoot, "dist", "extensions", "telegram"); + fs.mkdirSync(pluginRoot, { recursive: true }); + + const importerPath = path.join(pluginRoot, "index.js"); + const sidecarPath = path.join(pluginRoot, "fast-path-sidecar.js"); + fs.writeFileSync(importerPath, "export default {};\n", "utf8"); + // CommonJS so `nodeRequire` succeeds without falling back to jiti. + fs.writeFileSync(sidecarPath, "module.exports = { sentinel: 7 };\n", "utf8"); + + expect( + channelEntryContract.loadBundledEntryExportSync(pathToFileURL(importerPath).href, { + specifier: "./fast-path-sidecar.js", + exportName: "sentinel", + }), + ).toBe(7); + + const profileLine = errorSpy.mock.calls + .map((args) => String(args[0] ?? "")) + .find((line) => line.startsWith("[plugin-load-profile] phase=bundled-entry-module-load")); + expect(profileLine, "expected a bundled-entry-module-load profile line").toBeDefined(); + expect(profileLine).toContain("getJitiMs=0.0"); + expect(profileLine).toContain("jitiCallMs=0.0"); + expect(profileLine).not.toMatch(/getJitiMs=-/); + expect(profileLine).not.toMatch(/jitiCallMs=-/); + } finally { + errorSpy.mockRestore(); + platformSpy.mockRestore(); + } + }); + it("can disable source-tree fallback for dist bundled entry checks", () => { const tempRoot = fs.mkdtempSync(path.join(os.tmpdir(), "openclaw-channel-entry-contract-")); tempDirs.push(tempRoot); diff --git a/src/plugin-sdk/channel-entry-contract.ts b/src/plugin-sdk/channel-entry-contract.ts index e8b709ce3c9..a5da17065e4 100644 --- a/src/plugin-sdk/channel-entry-contract.ts +++ b/src/plugin-sdk/channel-entry-contract.ts @@ -12,6 +12,11 @@ import { getCachedPluginJitiLoader, type PluginJitiLoaderCache, } from "../plugins/jiti-loader-cache.js"; +import { + createProfiler, + formatPluginLoadProfileLine, + shouldProfilePluginLoader, +} from "../plugins/plugin-load-profile.js"; import type { PluginRuntime } from "../plugins/runtime/types.js"; import { resolveLoaderPackageRoot } from "../plugins/sdk-alias.js"; import type { AnyAgentTool, OpenClawPluginApi, PluginCommandContext } from "../plugins/types.js"; @@ -318,6 +323,9 @@ function loadBundledEntryModuleSync(importMetaUrl: string, specifier: string): u return cached; } let loaded: unknown; + const profile = shouldProfilePluginLoader(); + const loadStartMs = profile ? performance.now() : 0; + let getJitiEndMs = 0; if ( process.platform === "win32" && modulePath.includes(`${path.sep}dist${path.sep}`) && @@ -326,10 +334,39 @@ function loadBundledEntryModuleSync(importMetaUrl: string, specifier: string): u try { loaded = nodeRequire(modulePath); } catch { - loaded = getJiti(modulePath)(modulePath); + const jiti = getJiti(modulePath); + getJitiEndMs = profile ? performance.now() : 0; + loaded = jiti(modulePath); } } else { - loaded = getJiti(modulePath)(modulePath); + const jiti = getJiti(modulePath); + getJitiEndMs = profile ? performance.now() : 0; + loaded = jiti(modulePath); + } + if (profile) { + const endMs = performance.now(); + // Use shared formatter — but split timing fields ourselves so we can + // attribute time spent in `getJiti(...)` factory creation vs the actual + // graph-walking `__j(modulePath)` call. Both are emitted as extras + // alongside the canonical `elapsedMs=` field. + console.error( + formatPluginLoadProfileLine({ + phase: "bundled-entry-module-load", + pluginId: "(bundled-entry)", + source: modulePath, + elapsedMs: endMs - loadStartMs, + // When the Win32 fast-path resolves the module via `nodeRequire`, + // `getJitiEndMs` stays `0` because the `catch` block (the only place + // it gets stamped) never runs. Reporting `getJitiMs` / + // `jitiCallMs` as `0` for that path keeps the breakdown honest: + // `elapsedMs=` already captures the nodeRequire time, and we don't + // want to mis-attribute it to jiti sub-steps. + extras: [ + ["getJitiMs", getJitiEndMs ? getJitiEndMs - loadStartMs : 0], + ["jitiCallMs", getJitiEndMs ? endMs - getJitiEndMs : 0], + ], + }), + ); } loadedModuleExports.set(modulePath, loaded); return loaded; @@ -410,13 +447,17 @@ export function defineBundledChannelEntry({ registerCliMetadata?.(api); return; } - setChannelRuntime?.(api.runtime); - api.registerChannel({ plugin: loadChannelPlugin() as ChannelPlugin }); + const profile = createProfiler({ pluginId: id, source: importMetaUrl }); + profile("bundled-register:setChannelRuntime", () => setChannelRuntime?.(api.runtime)); + const channelPlugin = profile("bundled-register:loadChannelPlugin", loadChannelPlugin); + profile("bundled-register:registerChannel", () => + api.registerChannel({ plugin: channelPlugin as ChannelPlugin }), + ); if (api.registrationMode !== "full") { return; } - registerCliMetadata?.(api); - registerFull?.(api); + profile("bundled-register:registerCliMetadata", () => registerCliMetadata?.(api)); + profile("bundled-register:registerFull", () => registerFull?.(api)); }, loadChannelPlugin, ...(loadChannelSecrets ? { loadChannelSecrets } : {}), diff --git a/src/plugins/loader.ts b/src/plugins/loader.ts index 12288504cae..f3683a1e8c6 100644 --- a/src/plugins/loader.ts +++ b/src/plugins/loader.ts @@ -76,6 +76,7 @@ import { } from "./memory-state.js"; import { unwrapDefaultModuleExport } from "./module-export.js"; import { isPathInside, safeStatSync } from "./path-safety.js"; +import { withProfile } from "./plugin-load-profile.js"; import { createPluginIdScopeSet, hasExplicitPluginIdScope, @@ -244,30 +245,6 @@ export function clearPluginLoaderCache(): void { const defaultLogger = () => createSubsystemLogger("plugins"); -function shouldProfilePluginLoader(): boolean { - return process.env.OPENCLAW_PLUGIN_LOAD_PROFILE === "1"; -} - -function profilePluginLoaderSync(params: { - phase: string; - pluginId?: string; - source: string; - run: () => T; -}): T { - if (!shouldProfilePluginLoader()) { - return params.run(); - } - const startMs = performance.now(); - try { - return params.run(); - } finally { - const elapsedMs = performance.now() - startMs; - console.error( - `[plugin-load-profile] phase=${params.phase} plugin=${params.pluginId ?? "(core)"} elapsedMs=${elapsedMs.toFixed(1)} source=${params.source}`, - ); - } -} - function isPromiseLike(value: unknown): value is PromiseLike { return ( (typeof value === "object" || typeof value === "function") && @@ -1503,14 +1480,14 @@ export function loadOpenClawPlugins(options: PluginLoadOptions = {}): PluginRegi throw new Error("Unable to resolve plugin runtime module"); } const safeRuntimePath = toSafeImportPath(runtimeModulePath); - const runtimeModule = profilePluginLoaderSync({ - phase: "runtime-module", - source: runtimeModulePath, - run: () => + const runtimeModule = withProfile( + { source: runtimeModulePath }, + "runtime-module", + () => getJiti(runtimeModulePath)(safeRuntimePath) as { createPluginRuntime?: (options?: CreatePluginRuntimeOptions) => PluginRuntime; }, - }); + ); if (typeof runtimeModule.createPluginRuntime !== "function") { throw new Error("Plugin runtime module missing createPluginRuntime export"); } @@ -1961,12 +1938,11 @@ export function loadOpenClawPlugins(options: PluginLoadOptions = {}): PluginRegi // Track the plugin as imported once module evaluation begins. Top-level // code may have already executed even if evaluation later throws. recordImportedPluginId(record.id); - mod = profilePluginLoaderSync({ - phase: registrationMode, - pluginId: record.id, - source: safeSource, - run: () => getJiti(safeSource)(safeImportSource) as OpenClawPluginModule, - }); + mod = withProfile( + { pluginId: record.id, source: safeSource }, + registrationMode, + () => getJiti(safeSource)(safeImportSource) as OpenClawPluginModule, + ); } catch (err) { recordPluginError({ logger, @@ -2039,13 +2015,11 @@ export function loadOpenClawPlugins(options: PluginLoadOptions = {}): PluginRegi const safeRuntimeImportSource = toSafeImportPath(safeRuntimeSource); let runtimeMod: OpenClawPluginModule | null = null; try { - runtimeMod = profilePluginLoaderSync({ - phase: "load-setup-runtime-entry", - pluginId: record.id, - source: safeRuntimeSource, - run: () => - getJiti(safeRuntimeSource)(safeRuntimeImportSource) as OpenClawPluginModule, - }); + runtimeMod = withProfile( + { pluginId: record.id, source: safeRuntimeSource }, + "load-setup-runtime-entry", + () => getJiti(safeRuntimeSource)(safeRuntimeImportSource) as OpenClawPluginModule, + ); } catch (err) { recordPluginError({ logger, @@ -2262,7 +2236,11 @@ export function loadOpenClawPlugins(options: PluginLoadOptions = {}): PluginRegi const previousMemoryRuntime = getMemoryRuntime(); try { - runPluginRegisterSync(register, api); + withProfile( + { pluginId: record.id, source: record.source }, + `${registrationMode}:register`, + () => runPluginRegisterSync(register, api), + ); // Snapshot loads should not replace process-global runtime prompt state. if (!shouldActivate) { restoreRegisteredAgentHarnesses(previousAgentHarnesses); @@ -2587,12 +2565,11 @@ export async function loadOpenClawPluginCliRegistry( let mod: OpenClawPluginModule | null = null; try { - mod = profilePluginLoaderSync({ - phase: "cli-metadata", - pluginId: record.id, - source: safeSource, - run: () => getJiti(safeSource)(safeImportSource) as OpenClawPluginModule, - }); + mod = withProfile( + { pluginId: record.id, source: safeSource }, + "cli-metadata", + () => getJiti(safeSource)(safeImportSource) as OpenClawPluginModule, + ); } catch (err) { recordPluginError({ logger, @@ -2683,7 +2660,9 @@ export async function loadOpenClawPluginCliRegistry( const registrySnapshot = snapshotPluginRegistry(registry); try { - runPluginRegisterSync(register, api); + withProfile({ pluginId: record.id, source: record.source }, "cli-metadata:register", () => + runPluginRegisterSync(register, api), + ); registry.plugins.push(record); seenIds.set(pluginId, candidate.origin); } catch (err) { diff --git a/src/plugins/plugin-load-profile.ts b/src/plugins/plugin-load-profile.ts new file mode 100644 index 00000000000..6830dcd19a3 --- /dev/null +++ b/src/plugins/plugin-load-profile.ts @@ -0,0 +1,135 @@ +/** + * Shared probe primitives for plugin-load profiling. + * + * All plugin-load probes — across `src/plugins/loader.ts`, + * `src/plugins/source-loader.ts`, and `src/plugin-sdk/channel-entry-contract.ts` + * — emit a single line per measurement to stderr in the form: + * + * [plugin-load-profile] phase= plugin= elapsedMs= [extras…] source= + * + * The same `OPENCLAW_PLUGIN_LOAD_PROFILE=1` env flag activates all probes. + * + * Tooling that scrapes these lines (e.g. PERF-STARTUP-PLAN.md profiling + * methodology) depends on the field order being: + * + * 1. `phase=` + * 2. `plugin=` + * 3. `elapsedMs=` + * 4. any caller-supplied extras (in declaration order) + * 5. `source=` last + * + * Keep this contract stable — downstream parsers rely on it. + */ + +export function shouldProfilePluginLoader(): boolean { + return process.env.OPENCLAW_PLUGIN_LOAD_PROFILE === "1"; +} + +/** + * An ordered list of `[key, value]` pairs appended between `elapsedMs=` and + * `source=` on the emitted log line. Ordered tuples (not a record) so that + * scrapers see a deterministic field order regardless of object iteration + * quirks. + */ +export type PluginLoadProfileExtras = ReadonlyArray; + +/** Per-call scope: which plugin and which source path the probe is for. */ +export type PluginLoadProfileScope = { + pluginId?: string; + source: string; +}; + +/** + * A scope-bound profiler — call it with a `phase` + sync `run` to time and + * emit a `[plugin-load-profile]` line that already includes the bound + * `pluginId` and `source`. Build one with `createProfiler(scope)`. + */ +export type PluginLoadProfiler = ( + phase: string, + run: () => T, + extras?: PluginLoadProfileExtras, +) => T; + +/** + * Render a `[plugin-load-profile]` line. Exported so that callers needing + * custom timing splits (e.g. dual-timer probes in + * `channel-entry-contract.ts`) can build their own start/stop logic and + * still emit a line in the canonical format. + */ +export function formatPluginLoadProfileLine(params: { + phase: string; + pluginId?: string; + source: string; + elapsedMs: number; + extras?: PluginLoadProfileExtras; +}): string { + const extras = (params.extras ?? []) + .map(([k, v]) => `${k}=${typeof v === "number" ? v.toFixed(1) : v}`) + .join(" "); + const extrasFragment = extras ? ` ${extras}` : ""; + return ( + `[plugin-load-profile] phase=${params.phase} plugin=${params.pluginId ?? "(core)"}` + + ` elapsedMs=${params.elapsedMs.toFixed(1)}${extrasFragment} source=${params.source}` + ); +} + +/** + * Time a single synchronous step and emit a `[plugin-load-profile]` line. + * Use this when you only need to wrap one call: + * + * ```ts + * const mod = withProfile( + * { pluginId: id, source }, + * "phase-name", + * () => loadIt(), + * ); + * ``` + * + * For repeated calls that share the same `{ pluginId, source }` scope, + * prefer `createProfiler(scope)` and call the returned profiler. + * + * When the env flag is unset, this runs `run()` directly with no timing + * overhead. Errors propagate naturally; the log line is still emitted via + * `try { … } finally { … }`. + */ +export function withProfile( + scope: PluginLoadProfileScope, + phase: string, + run: () => T, + extras?: PluginLoadProfileExtras, +): T { + if (!shouldProfilePluginLoader()) { + return run(); + } + const startMs = performance.now(); + try { + return run(); + } finally { + const elapsedMs = performance.now() - startMs; + console.error( + formatPluginLoadProfileLine({ + phase, + pluginId: scope.pluginId, + source: scope.source, + elapsedMs, + extras, + }), + ); + } +} + +/** + * Build a scope-bound profiler. Useful when several consecutive steps share + * the same `{ pluginId, source }`: + * + * ```ts + * const profile = createProfiler({ pluginId: id, source: importMetaUrl }); + * profile("phase-a", () => stepA()); + * const v = profile("phase-b", () => stepB()); + * ``` + * + * Each call has the same semantics as `withProfile(scope, phase, run)`. + */ +export function createProfiler(scope: PluginLoadProfileScope): PluginLoadProfiler { + return (phase, run, extras) => withProfile(scope, phase, run, extras); +} diff --git a/src/plugins/source-loader.ts b/src/plugins/source-loader.ts index f781f1835ec..e375e7ffe85 100644 --- a/src/plugins/source-loader.ts +++ b/src/plugins/source-loader.ts @@ -1,12 +1,9 @@ import type { PluginJitiLoaderCache } from "./jiti-loader-cache.js"; import { getCachedPluginJitiLoader } from "./jiti-loader-cache.js"; +import { withProfile } from "./plugin-load-profile.js"; export type PluginSourceLoader = (modulePath: string) => unknown; -function shouldProfilePluginSourceLoader(): boolean { - return process.env.OPENCLAW_PLUGIN_LOAD_PROFILE === "1"; -} - export function createPluginSourceLoader(): PluginSourceLoader { const loaders: PluginJitiLoaderCache = new Map(); return (modulePath) => { @@ -16,16 +13,11 @@ export function createPluginSourceLoader(): PluginSourceLoader { importerUrl: import.meta.url, jitiFilename: import.meta.url, }); - if (!shouldProfilePluginSourceLoader()) { - return jiti(modulePath); - } - const startMs = performance.now(); - try { - return jiti(modulePath); - } finally { - console.error( - `[plugin-load-profile] phase=source-loader plugin=(direct) elapsedMs=${(performance.now() - startMs).toFixed(1)} source=${modulePath}`, - ); - } + // Direct source loads are not associated with a specific plugin id — + // preserve the existing `plugin=(direct)` field used by tooling that + // scrapes [plugin-load-profile] lines. + return withProfile({ pluginId: "(direct)", source: modulePath }, "source-loader", () => + jiti(modulePath), + ); }; }