Files
openclaw/src/plugins/plugin-load-profile.ts
Alex Knight 4407df6c03 perf(plugin-sdk): per-phase + per-jiti-call probes for bundled channel entries (#69537)
* 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:<phase>` — 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<T>({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
2026-04-21 22:06:13 +10:00

136 lines
4.1 KiB
TypeScript

/**
* 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=<X> plugin=<Y> elapsedMs=<N> [extras…] source=<S>
*
* 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<readonly [string, number | string]>;
/** 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 = <T>(
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<T>(
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);
}