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-05-06 16:30:57 +00:00 · 2026-04-21 22:06:13 +10:00
parent 06ff594a3e
commit 4407df6c03
5 changed files with 265 additions and 71 deletions
--- 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<number>(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);
--- 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=<total>` 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<TPlugin = ChannelPlugin>({
        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 } : {}),
--- 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<T>(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<unknown> {
  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) {
--- a/src/plugins/plugin-load-profile.ts
+++ 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=<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);
+}
--- 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),
+    );
  };
 }