fix: trace plugin tool factory timings (#75823)

* fix: trace plugin tool factory timings

* docs: document plugin tool timing traces

* fix: keep plugin tools mcp stdout clean

* test: type plugin tools mcp mock

* test: complete plugin tools mcp mock

* test: preserve console helpers in mcp test

* chore: refresh generated protocol models

apps/macos/Sources/OpenClawProtocol/GatewayModels.swift

@@ -2343,6 +2343,7 @@ public struct WizardStep: Codable, Sendable {
     public let type: AnyCodable
     public let title: String?
     public let message: String?
+    public let format: AnyCodable?
     public let options: [[String: AnyCodable]]?
     public let initialvalue: AnyCodable?
     public let placeholder: String?
@@ -2354,6 +2355,7 @@ public struct WizardStep: Codable, Sendable {
         type: AnyCodable,
         title: String?,
         message: String?,
+        format: AnyCodable?,
         options: [[String: AnyCodable]]?,
         initialvalue: AnyCodable?,
         placeholder: String?,
@@ -2364,6 +2366,7 @@ public struct WizardStep: Codable, Sendable {
         self.type = type
         self.title = title
         self.message = message
+        self.format = format
         self.options = options
         self.initialvalue = initialvalue
         self.placeholder = placeholder
@@ -2376,6 +2379,7 @@ public struct WizardStep: Codable, Sendable {
         case type
         case title
         case message
+        case format
         case options
         case initialvalue = "initialValue"
         case placeholder
@@ -2802,6 +2806,24 @@ public struct ChannelsStartParams: Codable, Sendable {
     }
 }
 
+public struct ChannelsStopParams: Codable, Sendable {
+    public let channel: String
+    public let accountid: String?
+
+    public init(
+        channel: String,
+        accountid: String?)
+    {
+        self.channel = channel
+        self.accountid = accountid
+    }
+
+    private enum CodingKeys: String, CodingKey {
+        case channel
+        case accountid = "accountId"
+    }
+}
+
 public struct ChannelsLogoutParams: Codable, Sendable {
     public let channel: String
     public let accountid: String?

apps/shared/OpenClawKit/Sources/OpenClawProtocol/GatewayModels.swift

@@ -2343,6 +2343,7 @@ public struct WizardStep: Codable, Sendable {
     public let type: AnyCodable
     public let title: String?
     public let message: String?
+    public let format: AnyCodable?
     public let options: [[String: AnyCodable]]?
     public let initialvalue: AnyCodable?
     public let placeholder: String?
@@ -2354,6 +2355,7 @@ public struct WizardStep: Codable, Sendable {
         type: AnyCodable,
         title: String?,
         message: String?,
+        format: AnyCodable?,
         options: [[String: AnyCodable]]?,
         initialvalue: AnyCodable?,
         placeholder: String?,
@@ -2364,6 +2366,7 @@ public struct WizardStep: Codable, Sendable {
         self.type = type
         self.title = title
         self.message = message
+        self.format = format
         self.options = options
         self.initialvalue = initialvalue
         self.placeholder = placeholder
@@ -2376,6 +2379,7 @@ public struct WizardStep: Codable, Sendable {
         case type
         case title
         case message
+        case format
         case options
         case initialvalue = "initialValue"
         case placeholder
@@ -2802,6 +2806,24 @@ public struct ChannelsStartParams: Codable, Sendable {
     }
 }
 
+public struct ChannelsStopParams: Codable, Sendable {
+    public let channel: String
+    public let accountid: String?
+
+    public init(
+        channel: String,
+        accountid: String?)
+    {
+        self.channel = channel
+        self.accountid = accountid
+    }
+
+    private enum CodingKeys: String, CodingKey {
+        case channel
+        case accountid = "accountId"
+    }
+}
+
 public struct ChannelsLogoutParams: Codable, Sendable {
     public let channel: String
     public let accountid: String?

docs/gateway/logging.md

@@ -41,6 +41,9 @@ openclaw logs --follow
   raise the file log level.
 - To capture verbose-only details in file logs, set `logging.level` to `debug` or
   `trace`.
+- Trace logging also includes diagnostic timing summaries for selected hot paths,
+  such as plugin tool factory preparation. See
+  [/tools/plugin#slow-plugin-tool-setup](/tools/plugin#slow-plugin-tool-setup).
 
 ## Console capture
 

docs/tools/plugin.md

@@ -334,6 +334,37 @@ do not run in live chat traffic, check these first:
   Gateway session/status surfaces and, when debugging provider payloads, start
   the Gateway with `--raw-stream --raw-stream-path <path>`.
 
+### Slow plugin tool setup
+
+If agent turns appear to stall while preparing tools, enable trace logging and
+check for plugin tool factory timing lines:
+
+```bash
+openclaw config set logging.level trace
+openclaw logs --follow
+```
+
+Look for:
+
+```text
+[trace:plugin-tools] factory timings ...
+```
+
+The summary lists total factory time and the slowest plugin tool factories,
+including plugin id, declared tool names, result shape, and whether the tool is
+optional. Slow lines are promoted to warnings when a single factory takes at
+least 1s or total plugin tool factory prep takes at least 5s.
+
+If one plugin dominates the timing, inspect its runtime registrations:
+
+```bash
+openclaw plugins inspect <plugin-id> --runtime --json
+```
+
+Then update, reinstall, or disable that plugin. Plugin authors should move
+expensive dependency loading behind the tool execution path instead of doing it
+inside the tool factory.
+
 ### Duplicate channel or tool ownership
 
 Symptoms:

src/mcp/plugin-tools-serve.test.ts

@@ -8,18 +8,76 @@ import { createMockPluginRegistry } from "../plugins/hooks.test-helpers.js";
 import { createPluginToolsMcpHandlers } from "./plugin-tools-handlers.js";
 
 const callGatewayTool = vi.hoisted(() => vi.fn());
+const connectToolsMcpServerToStdioMock = vi.hoisted(() => vi.fn());
+const createToolsMcpServerMock = vi.hoisted(() => vi.fn(() => ({ close: vi.fn() })));
+const getRuntimeConfigMock = vi.hoisted(() => vi.fn(() => ({ plugins: { enabled: true } })));
+const resolvePluginToolsMock = vi.hoisted(() => vi.fn<() => AnyAgentTool[]>(() => []));
+const routeLogsToStderrMock = vi.hoisted(() => vi.fn());
 
 vi.mock("../agents/tools/gateway.js", () => ({
   callGatewayTool,
 }));
 
+vi.mock("../config/config.js", () => ({
+  getRuntimeConfig: getRuntimeConfigMock,
+}));
+
+vi.mock("../logging/console.js", async (importOriginal) => {
+  const actual = await importOriginal<typeof import("../logging/console.js")>();
+  return {
+    ...actual,
+    routeLogsToStderr: routeLogsToStderrMock,
+  };
+});
+
+vi.mock("../plugins/tools.js", async (importOriginal) => {
+  const actual = await importOriginal<typeof import("../plugins/tools.js")>();
+  return {
+    ...actual,
+    resolvePluginTools: resolvePluginToolsMock,
+  };
+});
+
+vi.mock("./tools-stdio-server.js", () => ({
+  connectToolsMcpServerToStdio: connectToolsMcpServerToStdioMock,
+  createToolsMcpServer: createToolsMcpServerMock,
+}));
+
 afterEach(() => {
   vi.restoreAllMocks();
   callGatewayTool.mockReset();
+  connectToolsMcpServerToStdioMock.mockReset();
+  createToolsMcpServerMock.mockClear();
+  getRuntimeConfigMock.mockClear();
+  resolvePluginToolsMock.mockReset();
+  resolvePluginToolsMock.mockReturnValue([]);
+  routeLogsToStderrMock.mockReset();
   resetGlobalHookRunner();
 });
 
 describe("plugin tools MCP server", () => {
+  it("routes logs to stderr before resolving tools for stdio", async () => {
+    const { servePluginToolsMcp } = await import("./plugin-tools-serve.js");
+    resolvePluginToolsMock.mockReturnValue([
+      {
+        name: "memory_recall",
+        label: "Recall memory",
+        description: "Recall stored memory",
+        parameters: { type: "object", properties: {} },
+        execute: vi.fn(),
+      },
+    ]);
+
+    await servePluginToolsMcp();
+
+    expect(routeLogsToStderrMock).toHaveBeenCalledTimes(1);
+    expect(resolvePluginToolsMock).toHaveBeenCalledTimes(1);
+    expect(routeLogsToStderrMock.mock.invocationCallOrder[0]).toBeLessThan(
+      resolvePluginToolsMock.mock.invocationCallOrder[0] ?? 0,
+    );
+    expect(connectToolsMcpServerToStdioMock).toHaveBeenCalledOnce();
+  });
+
   it("lists registered plugin tools and serializes non-array tool content", async () => {
     const execute = vi.fn().mockResolvedValue({
       content: "Stored.",

src/mcp/plugin-tools-serve.ts

@@ -12,6 +12,7 @@ import type { AnyAgentTool } from "../agents/tools/common.js";
 import { getRuntimeConfig } from "../config/config.js";
 import type { OpenClawConfig } from "../config/types.openclaw.js";
 import { formatErrorMessage } from "../infra/errors.js";
+import { routeLogsToStderr } from "../logging/console.js";
 import { resolvePluginTools } from "../plugins/tools.js";
 import { connectToolsMcpServerToStdio, createToolsMcpServer } from "./tools-stdio-server.js";
 
@@ -34,6 +35,10 @@ export function createPluginToolsMcpServer(
 }
 
 export async function servePluginToolsMcp(): Promise<void> {
+  // MCP stdio requires stdout to stay protocol-only, including during plugin
+  // tool discovery before the transport is connected.
+  routeLogsToStderr();
+
   const config = getRuntimeConfig();
   const tools = resolveTools(config);
   const server = createPluginToolsMcpServer({ config, tools });

src/plugins/tools.optional.test.ts

@@ -1,7 +1,10 @@
 import { afterEach, beforeAll, beforeEach, describe, expect, it, vi } from "vitest";
+import { resetLogger, setLoggerOverride } from "../logging/logger.js";
+import { loggingState } from "../logging/state.js";
 
 type MockRegistryToolEntry = {
   pluginId: string;
+  names?: string[];
   optional: boolean;
   source: string;
   factory: (ctx: unknown) => unknown;
@@ -93,6 +96,7 @@ function setMultiToolRegistry() {
 function createOptionalDemoEntry(): MockRegistryToolEntry {
   return {
     pluginId: "optional-demo",
+    names: ["optional_tool"],
     optional: true,
     source: "/tmp/optional-demo.js",
     factory: () => makeTool("optional_tool"),
@@ -110,6 +114,17 @@ function createMalformedTool(name: string) {
   };
 }
 
+function installConsoleMethodSpy(method: "log" | "warn") {
+  const spy = vi.fn();
+  loggingState.rawConsole = {
+    log: method === "log" ? spy : vi.fn(),
+    info: vi.fn(),
+    warn: method === "warn" ? spy : vi.fn(),
+    error: vi.fn(),
+  };
+  return spy;
+}
+
 function resolveWithConflictingCoreName(options?: { suppressNameConflicts?: boolean }) {
   return resolvePluginTools(
     createResolveToolsParams({
@@ -227,6 +242,10 @@ describe("resolvePluginTools optional tools", () => {
 
   afterEach(() => {
     resetPluginRuntimeStateForTest?.();
+    setLoggerOverride(null);
+    loggingState.rawConsole = null;
+    resetLogger();
+    vi.useRealTimers();
   });
 
   it("skips optional tools without explicit allowlist", () => {
@@ -342,6 +361,86 @@ describe("resolvePluginTools optional tools", () => {
     );
   });
 
+  it("warns with plugin factory timing details when a factory is slow", () => {
+    vi.useFakeTimers({ now: 0 });
+    const warnSpy = installConsoleMethodSpy("warn");
+    setLoggerOverride({ level: "silent", consoleLevel: "warn" });
+    setRegistry([
+      {
+        pluginId: "optional-demo",
+        names: ["optional_tool"],
+        optional: true,
+        source: "/tmp/optional-demo.js",
+        factory: () => {
+          vi.advanceTimersByTime(1200);
+          return makeTool("optional_tool");
+        },
+      },
+    ]);
+
+    const tools = resolveOptionalDemoTools(["optional_tool"]);
+
+    expectResolvedToolNames(tools, ["optional_tool"]);
+    expect(warnSpy).toHaveBeenCalledTimes(1);
+    const message = String(warnSpy.mock.calls[0]?.[0] ?? "");
+    expect(message).toContain("[trace:plugin-tools] factory timings");
+    expect(message).toContain("totalMs=1200");
+    expect(message).toContain("optional-demo:1200ms@1200ms");
+    expect(message).toContain("names=[optional_tool]");
+    expect(message).toContain("result=single");
+    expect(message).toContain("count=1");
+  });
+
+  it("emits trace factory timings below the warn threshold when trace logging is enabled", () => {
+    vi.useFakeTimers({ now: 0 });
+    const logSpy = installConsoleMethodSpy("log");
+    setLoggerOverride({ level: "silent", consoleLevel: "trace" });
+    setRegistry([
+      {
+        pluginId: "optional-demo",
+        names: ["optional_tool"],
+        optional: true,
+        source: "/tmp/optional-demo.js",
+        factory: () => {
+          vi.advanceTimersByTime(5);
+          return makeTool("optional_tool");
+        },
+      },
+    ]);
+
+    const tools = resolveOptionalDemoTools(["optional_tool"]);
+
+    expectResolvedToolNames(tools, ["optional_tool"]);
+    expect(logSpy).toHaveBeenCalledTimes(1);
+    const message = String(logSpy.mock.calls[0]?.[0] ?? "");
+    expect(message).toContain("[trace:plugin-tools] factory timings");
+    expect(message).toContain("totalMs=5");
+    expect(message).toContain("optional-demo:5ms@5ms");
+  });
+
+  it("does not log plugin factory timings for fast factories without trace logging", () => {
+    vi.useFakeTimers({ now: 0 });
+    const warnSpy = installConsoleMethodSpy("warn");
+    setLoggerOverride({ level: "silent", consoleLevel: "warn" });
+    setRegistry([
+      {
+        pluginId: "optional-demo",
+        names: ["optional_tool"],
+        optional: true,
+        source: "/tmp/optional-demo.js",
+        factory: () => {
+          vi.advanceTimersByTime(5);
+          return makeTool("optional_tool");
+        },
+      },
+    ]);
+
+    const tools = resolveOptionalDemoTools(["optional_tool"]);
+
+    expectResolvedToolNames(tools, ["optional_tool"]);
+    expect(warnSpy).not.toHaveBeenCalled();
+  });
+
   it("skips allowlisted optional malformed plugin tools", () => {
     const registry = setRegistry([
       {

src/plugins/tools.ts

@@ -1,5 +1,6 @@
 import { normalizeToolName } from "../agents/tool-policy.js";
 import type { AnyAgentTool } from "../agents/tools/common.js";
+import { createSubsystemLogger } from "../logging/subsystem.js";
 import { applyTestPluginDefaults, normalizePluginsConfig } from "./config-state.js";
 import { listEnabledInstalledPluginRecords } from "./installed-plugin-index.js";
 import { resolveRuntimePluginRegistry, type PluginLoadOptions } from "./loader.js";
@@ -16,6 +17,23 @@ export type PluginToolMeta = {
   optional: boolean;
 };
 
+type PluginToolFactoryTimingResult = "array" | "error" | "null" | "single";
+
+type PluginToolFactoryTiming = {
+  pluginId: string;
+  names: string[];
+  durationMs: number;
+  elapsedMs: number;
+  result: PluginToolFactoryTimingResult;
+  resultCount: number;
+  optional: boolean;
+};
+
+const log = createSubsystemLogger("plugins/tools");
+const PLUGIN_TOOL_FACTORY_WARN_TOTAL_MS = 5_000;
+const PLUGIN_TOOL_FACTORY_WARN_FACTORY_MS = 1_000;
+const PLUGIN_TOOL_FACTORY_SUMMARY_LIMIT = 20;
+
 const pluginToolMeta = new WeakMap<AnyAgentTool, PluginToolMeta>();
 
 export function setPluginToolMeta(tool: AnyAgentTool, meta: PluginToolMeta): void {
@@ -75,6 +93,72 @@ function readPluginToolName(tool: unknown): string {
   return typeof tool.name === "string" ? tool.name.trim() : "";
 }
 
+function toElapsedMs(value: number): number {
+  return Math.max(0, Math.round(value));
+}
+
+function describePluginToolFactoryResult(
+  resolved: AnyAgentTool | AnyAgentTool[] | null | undefined,
+  failed: boolean,
+): { result: PluginToolFactoryTimingResult; resultCount: number } {
+  if (failed) {
+    return { result: "error", resultCount: 0 };
+  }
+  if (!resolved) {
+    return { result: "null", resultCount: 0 };
+  }
+  if (Array.isArray(resolved)) {
+    return { result: "array", resultCount: resolved.length };
+  }
+  return { result: "single", resultCount: 1 };
+}
+
+function formatPluginToolFactoryTiming(timing: PluginToolFactoryTiming): string {
+  const names = timing.names.length > 0 ? timing.names.join("|") : "-";
+  return [
+    `${timing.pluginId}:${timing.durationMs}ms@${timing.elapsedMs}ms`,
+    `names=[${names}]`,
+    `result=${timing.result}`,
+    `count=${timing.resultCount}`,
+    `optional=${String(timing.optional)}`,
+  ].join(" ");
+}
+
+function formatPluginToolFactoryTimingSummary(params: {
+  totalMs: number;
+  timings: PluginToolFactoryTiming[];
+}): string {
+  const ranked = params.timings
+    .toSorted(
+      (left, right) =>
+        right.durationMs - left.durationMs || left.pluginId.localeCompare(right.pluginId),
+    )
+    .slice(0, PLUGIN_TOOL_FACTORY_SUMMARY_LIMIT);
+  const omitted = Math.max(0, params.timings.length - ranked.length);
+  const factories =
+    ranked.length > 0
+      ? ranked.map((timing) => formatPluginToolFactoryTiming(timing)).join(", ")
+      : "none";
+  return [
+    "[trace:plugin-tools] factory timings",
+    `totalMs=${params.totalMs}`,
+    `factoryCount=${params.timings.length}`,
+    `shown=${ranked.length}`,
+    `omitted=${omitted}`,
+    `factories=${factories}`,
+  ].join(" ");
+}
+
+function shouldWarnPluginToolFactoryTimings(params: {
+  totalMs: number;
+  timings: PluginToolFactoryTiming[];
+}): boolean {
+  return (
+    params.totalMs >= PLUGIN_TOOL_FACTORY_WARN_TOTAL_MS ||
+    params.timings.some((timing) => timing.durationMs >= PLUGIN_TOOL_FACTORY_WARN_FACTORY_MS)
+  );
+}
+
 function describeMalformedPluginTool(tool: unknown): string | undefined {
   if (!isRecord(tool)) {
     return "tool must be an object";
@@ -163,6 +247,8 @@ export function resolvePluginTools(params: {
   const existingNormalized = new Set(Array.from(existing, (tool) => normalizeToolName(tool)));
   const allowlist = normalizeAllowlist(params.toolAllowlist);
   const blockedPlugins = new Set<string>();
+  const factoryTimingStartedAt = Date.now();
+  const factoryTimings: PluginToolFactoryTiming[] = [];
 
   for (const entry of registry.tools) {
     if (blockedPlugins.has(entry.pluginId)) {
@@ -183,17 +269,35 @@ export function resolvePluginTools(params: {
       blockedPlugins.add(entry.pluginId);
       continue;
     }
+    const declaredNames = entry.names ?? [];
     let resolved: AnyAgentTool | AnyAgentTool[] | null | undefined = null;
+    let factoryFailed = false;
+    const factoryStartedAt = Date.now();
     try {
       resolved = entry.factory(params.context);
     } catch (err) {
+      factoryFailed = true;
       context.logger.error(`plugin tool failed (${entry.pluginId}): ${String(err)}`);
+    } finally {
+      const factoryEndedAt = Date.now();
+      const result = describePluginToolFactoryResult(resolved, factoryFailed);
+      factoryTimings.push({
+        pluginId: entry.pluginId,
+        names: declaredNames,
+        durationMs: toElapsedMs(factoryEndedAt - factoryStartedAt),
+        elapsedMs: toElapsedMs(factoryEndedAt - factoryTimingStartedAt),
+        result: result.result,
+        resultCount: result.resultCount,
+        optional: entry.optional,
+      });
+    }
+    if (factoryFailed) {
       continue;
     }
     if (!resolved) {
-      if (entry.names.length > 0) {
+      if (declaredNames.length > 0) {
         context.logger.debug?.(
-          `plugin tool factory returned null (${entry.pluginId}): [${entry.names.join(", ")}]`,
+          `plugin tool factory returned null (${entry.pluginId}): [${declaredNames.join(", ")}]`,
         );
       }
       continue;
@@ -251,5 +355,16 @@ export function resolvePluginTools(params: {
     }
   }
 
+  if (factoryTimings.length > 0) {
+    const totalMs =
+      factoryTimings.at(-1)?.elapsedMs ?? toElapsedMs(Date.now() - factoryTimingStartedAt);
+    const timingSummary = { totalMs, timings: factoryTimings };
+    if (shouldWarnPluginToolFactoryTimings(timingSummary)) {
+      log.warn(formatPluginToolFactoryTimingSummary(timingSummary));
+    } else if (log.isEnabled("trace")) {
+      log.trace(formatPluginToolFactoryTimingSummary(timingSummary));
+    }
+  }
+
   return tools;
 }