Skip to content

Commit 4407df6

Browse files
amknightamknight
authored
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
1 parent 06ff594 commit 4407df6

5 files changed

Lines changed: 265 additions & 71 deletions

File tree

‎src/plugin-sdk/channel-entry-contract.test.ts‎

Lines changed: 47 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -133,6 +133,53 @@ describe("loadBundledEntryExportSync", () => {
133133
});
134134
});
135135

136+
it("emits zero jiti sub-step timings on the Win32 nodeRequire fast-path", async () => {
137+
// The Win32 fast-path goes through `nodeRequire` directly and never
138+
// touches jiti. The plugin-load-profile line must reflect that with
139+
// `getJitiMs=0.0 jitiCallMs=0.0` rather than negative or full-elapsed
140+
// values that would mis-attribute nodeRequire time to jiti sub-steps.
141+
const platformSpy = vi.spyOn(process, "platform", "get").mockReturnValue("win32");
142+
vi.stubEnv("OPENCLAW_PLUGIN_LOAD_PROFILE", "1");
143+
const errorSpy = vi.spyOn(console, "error").mockImplementation(() => undefined);
144+
145+
try {
146+
const channelEntryContract = await importFreshModule<
147+
typeof import("./channel-entry-contract.js")
148+
>(import.meta.url, "./channel-entry-contract.js?scope=win32-profile-fast-path");
149+
150+
const tempRoot = fs.mkdtempSync(path.join(os.tmpdir(), "openclaw-channel-entry-contract-"));
151+
tempDirs.push(tempRoot);
152+
153+
const pluginRoot = path.join(tempRoot, "dist", "extensions", "telegram");
154+
fs.mkdirSync(pluginRoot, { recursive: true });
155+
156+
const importerPath = path.join(pluginRoot, "index.js");
157+
const sidecarPath = path.join(pluginRoot, "fast-path-sidecar.js");
158+
fs.writeFileSync(importerPath, "export default {};\n", "utf8");
159+
// CommonJS so `nodeRequire` succeeds without falling back to jiti.
160+
fs.writeFileSync(sidecarPath, "module.exports = { sentinel: 7 };\n", "utf8");
161+
162+
expect(
163+
channelEntryContract.loadBundledEntryExportSync<number>(pathToFileURL(importerPath).href, {
164+
specifier: "./fast-path-sidecar.js",
165+
exportName: "sentinel",
166+
}),
167+
).toBe(7);
168+
169+
const profileLine = errorSpy.mock.calls
170+
.map((args) => String(args[0] ?? ""))
171+
.find((line) => line.startsWith("[plugin-load-profile] phase=bundled-entry-module-load"));
172+
expect(profileLine, "expected a bundled-entry-module-load profile line").toBeDefined();
173+
expect(profileLine).toContain("getJitiMs=0.0");
174+
expect(profileLine).toContain("jitiCallMs=0.0");
175+
expect(profileLine).not.toMatch(/getJitiMs=-/);
176+
expect(profileLine).not.toMatch(/jitiCallMs=-/);
177+
} finally {
178+
errorSpy.mockRestore();
179+
platformSpy.mockRestore();
180+
}
181+
});
182+
136183
it("can disable source-tree fallback for dist bundled entry checks", () => {
137184
const tempRoot = fs.mkdtempSync(path.join(os.tmpdir(), "openclaw-channel-entry-contract-"));
138185
tempDirs.push(tempRoot);

‎src/plugin-sdk/channel-entry-contract.ts‎

Lines changed: 47 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,11 @@ import {
1212
getCachedPluginJitiLoader,
1313
type PluginJitiLoaderCache,
1414
} from "../plugins/jiti-loader-cache.js";
15+
import {
16+
createProfiler,
17+
formatPluginLoadProfileLine,
18+
shouldProfilePluginLoader,
19+
} from "../plugins/plugin-load-profile.js";
1520
import type { PluginRuntime } from "../plugins/runtime/types.js";
1621
import { resolveLoaderPackageRoot } from "../plugins/sdk-alias.js";
1722
import type { AnyAgentTool, OpenClawPluginApi, PluginCommandContext } from "../plugins/types.js";
@@ -318,6 +323,9 @@ function loadBundledEntryModuleSync(importMetaUrl: string, specifier: string): u
318323
return cached;
319324
}
320325
let loaded: unknown;
326+
const profile = shouldProfilePluginLoader();
327+
const loadStartMs = profile ? performance.now() : 0;
328+
let getJitiEndMs = 0;
321329
if (
322330
process.platform === "win32" &&
323331
modulePath.includes(`${path.sep}dist${path.sep}`) &&
@@ -326,10 +334,39 @@ function loadBundledEntryModuleSync(importMetaUrl: string, specifier: string): u
326334
try {
327335
loaded = nodeRequire(modulePath);
328336
} catch {
329-
loaded = getJiti(modulePath)(modulePath);
337+
const jiti = getJiti(modulePath);
338+
getJitiEndMs = profile ? performance.now() : 0;
339+
loaded = jiti(modulePath);
330340
}
331341
} else {
332-
loaded = getJiti(modulePath)(modulePath);
342+
const jiti = getJiti(modulePath);
343+
getJitiEndMs = profile ? performance.now() : 0;
344+
loaded = jiti(modulePath);
345+
}
346+
if (profile) {
347+
const endMs = performance.now();
348+
// Use shared formatter — but split timing fields ourselves so we can
349+
// attribute time spent in `getJiti(...)` factory creation vs the actual
350+
// graph-walking `__j(modulePath)` call. Both are emitted as extras
351+
// alongside the canonical `elapsedMs=<total>` field.
352+
console.error(
353+
formatPluginLoadProfileLine({
354+
phase: "bundled-entry-module-load",
355+
pluginId: "(bundled-entry)",
356+
source: modulePath,
357+
elapsedMs: endMs - loadStartMs,
358+
// When the Win32 fast-path resolves the module via `nodeRequire`,
359+
// `getJitiEndMs` stays `0` because the `catch` block (the only place
360+
// it gets stamped) never runs. Reporting `getJitiMs` /
361+
// `jitiCallMs` as `0` for that path keeps the breakdown honest:
362+
// `elapsedMs=` already captures the nodeRequire time, and we don't
363+
// want to mis-attribute it to jiti sub-steps.
364+
extras: [
365+
["getJitiMs", getJitiEndMs ? getJitiEndMs - loadStartMs : 0],
366+
["jitiCallMs", getJitiEndMs ? endMs - getJitiEndMs : 0],
367+
],
368+
}),
369+
);
333370
}
334371
loadedModuleExports.set(modulePath, loaded);
335372
return loaded;
@@ -410,13 +447,17 @@ export function defineBundledChannelEntry<TPlugin = ChannelPlugin>({
410447
registerCliMetadata?.(api);
411448
return;
412449
}
413-
setChannelRuntime?.(api.runtime);
414-
api.registerChannel({ plugin: loadChannelPlugin() as ChannelPlugin });
450+
const profile = createProfiler({ pluginId: id, source: importMetaUrl });
451+
profile("bundled-register:setChannelRuntime", () => setChannelRuntime?.(api.runtime));
452+
const channelPlugin = profile("bundled-register:loadChannelPlugin", loadChannelPlugin);
453+
profile("bundled-register:registerChannel", () =>
454+
api.registerChannel({ plugin: channelPlugin as ChannelPlugin }),
455+
);
415456
if (api.registrationMode !== "full") {
416457
return;
417458
}
418-
registerCliMetadata?.(api);
419-
registerFull?.(api);
459+
profile("bundled-register:registerCliMetadata", () => registerCliMetadata?.(api));
460+
profile("bundled-register:registerFull", () => registerFull?.(api));
420461
},
421462
loadChannelPlugin,
422463
...(loadChannelSecrets ? { loadChannelSecrets } : {}),

‎src/plugins/loader.ts‎

Lines changed: 29 additions & 50 deletions
Original file line numberDiff line numberDiff line change
@@ -76,6 +76,7 @@ import {
7676
} from "./memory-state.js";
7777
import { unwrapDefaultModuleExport } from "./module-export.js";
7878
import { isPathInside, safeStatSync } from "./path-safety.js";
79+
import { withProfile } from "./plugin-load-profile.js";
7980
import {
8081
createPluginIdScopeSet,
8182
hasExplicitPluginIdScope,
@@ -244,30 +245,6 @@ export function clearPluginLoaderCache(): void {
244245

245246
const defaultLogger = () => createSubsystemLogger("plugins");
246247

247-
function shouldProfilePluginLoader(): boolean {
248-
return process.env.OPENCLAW_PLUGIN_LOAD_PROFILE === "1";
249-
}
250-
251-
function profilePluginLoaderSync<T>(params: {
252-
phase: string;
253-
pluginId?: string;
254-
source: string;
255-
run: () => T;
256-
}): T {
257-
if (!shouldProfilePluginLoader()) {
258-
return params.run();
259-
}
260-
const startMs = performance.now();
261-
try {
262-
return params.run();
263-
} finally {
264-
const elapsedMs = performance.now() - startMs;
265-
console.error(
266-
`[plugin-load-profile] phase=${params.phase} plugin=${params.pluginId ?? "(core)"} elapsedMs=${elapsedMs.toFixed(1)} source=${params.source}`,
267-
);
268-
}
269-
}
270-
271248
function isPromiseLike(value: unknown): value is PromiseLike<unknown> {
272249
return (
273250
(typeof value === "object" || typeof value === "function") &&
@@ -1503,14 +1480,14 @@ export function loadOpenClawPlugins(options: PluginLoadOptions = {}): PluginRegi
15031480
throw new Error("Unable to resolve plugin runtime module");
15041481
}
15051482
const safeRuntimePath = toSafeImportPath(runtimeModulePath);
1506-
const runtimeModule = profilePluginLoaderSync({
1507-
phase: "runtime-module",
1508-
source: runtimeModulePath,
1509-
run: () =>
1483+
const runtimeModule = withProfile(
1484+
{ source: runtimeModulePath },
1485+
"runtime-module",
1486+
() =>
15101487
getJiti(runtimeModulePath)(safeRuntimePath) as {
15111488
createPluginRuntime?: (options?: CreatePluginRuntimeOptions) => PluginRuntime;
15121489
},
1513-
});
1490+
);
15141491
if (typeof runtimeModule.createPluginRuntime !== "function") {
15151492
throw new Error("Plugin runtime module missing createPluginRuntime export");
15161493
}
@@ -1961,12 +1938,11 @@ export function loadOpenClawPlugins(options: PluginLoadOptions = {}): PluginRegi
19611938
// Track the plugin as imported once module evaluation begins. Top-level
19621939
// code may have already executed even if evaluation later throws.
19631940
recordImportedPluginId(record.id);
1964-
mod = profilePluginLoaderSync({
1965-
phase: registrationMode,
1966-
pluginId: record.id,
1967-
source: safeSource,
1968-
run: () => getJiti(safeSource)(safeImportSource) as OpenClawPluginModule,
1969-
});
1941+
mod = withProfile(
1942+
{ pluginId: record.id, source: safeSource },
1943+
registrationMode,
1944+
() => getJiti(safeSource)(safeImportSource) as OpenClawPluginModule,
1945+
);
19701946
} catch (err) {
19711947
recordPluginError({
19721948
logger,
@@ -2039,13 +2015,11 @@ export function loadOpenClawPlugins(options: PluginLoadOptions = {}): PluginRegi
20392015
const safeRuntimeImportSource = toSafeImportPath(safeRuntimeSource);
20402016
let runtimeMod: OpenClawPluginModule | null = null;
20412017
try {
2042-
runtimeMod = profilePluginLoaderSync({
2043-
phase: "load-setup-runtime-entry",
2044-
pluginId: record.id,
2045-
source: safeRuntimeSource,
2046-
run: () =>
2047-
getJiti(safeRuntimeSource)(safeRuntimeImportSource) as OpenClawPluginModule,
2048-
});
2018+
runtimeMod = withProfile(
2019+
{ pluginId: record.id, source: safeRuntimeSource },
2020+
"load-setup-runtime-entry",
2021+
() => getJiti(safeRuntimeSource)(safeRuntimeImportSource) as OpenClawPluginModule,
2022+
);
20492023
} catch (err) {
20502024
recordPluginError({
20512025
logger,
@@ -2262,7 +2236,11 @@ export function loadOpenClawPlugins(options: PluginLoadOptions = {}): PluginRegi
22622236
const previousMemoryRuntime = getMemoryRuntime();
22632237

22642238
try {
2265-
runPluginRegisterSync(register, api);
2239+
withProfile(
2240+
{ pluginId: record.id, source: record.source },
2241+
`${registrationMode}:register`,
2242+
() => runPluginRegisterSync(register, api),
2243+
);
22662244
// Snapshot loads should not replace process-global runtime prompt state.
22672245
if (!shouldActivate) {
22682246
restoreRegisteredAgentHarnesses(previousAgentHarnesses);
@@ -2587,12 +2565,11 @@ export async function loadOpenClawPluginCliRegistry(
25872565

25882566
let mod: OpenClawPluginModule | null = null;
25892567
try {
2590-
mod = profilePluginLoaderSync({
2591-
phase: "cli-metadata",
2592-
pluginId: record.id,
2593-
source: safeSource,
2594-
run: () => getJiti(safeSource)(safeImportSource) as OpenClawPluginModule,
2595-
});
2568+
mod = withProfile(
2569+
{ pluginId: record.id, source: safeSource },
2570+
"cli-metadata",
2571+
() => getJiti(safeSource)(safeImportSource) as OpenClawPluginModule,
2572+
);
25962573
} catch (err) {
25972574
recordPluginError({
25982575
logger,
@@ -2683,7 +2660,9 @@ export async function loadOpenClawPluginCliRegistry(
26832660

26842661
const registrySnapshot = snapshotPluginRegistry(registry);
26852662
try {
2686-
runPluginRegisterSync(register, api);
2663+
withProfile({ pluginId: record.id, source: record.source }, "cli-metadata:register", () =>
2664+
runPluginRegisterSync(register, api),
2665+
);
26872666
registry.plugins.push(record);
26882667
seenIds.set(pluginId, candidate.origin);
26892668
} catch (err) {

0 commit comments

Comments
 (0)