Skip to content

Commit 75e126e

Browse files
steipetesteipete
committed
perf: improve gateway startup diagnostics
1 parent 13d3777 commit 75e126e

7 files changed

Lines changed: 144 additions & 44 deletions

File tree

‎scripts/bench-gateway-startup.ts‎

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -480,6 +480,10 @@ function collectStartupTrace(line: string, startupTrace: Record<string, number>)
480480
}
481481
}
482482

483+
function hasGatewayReadyLog(line: string): boolean {
484+
return /\[gateway\] (?:http server listening|ready \()/.test(line);
485+
}
486+
483487
function parseStartupTraceMetrics(raw: string): Array<{ key: string; value: number }> {
484488
const metrics: Array<{ key: string; value: number }> = [];
485489
for (const part of raw.trim().split(/\s+/u)) {
@@ -576,7 +580,7 @@ async function runGatewaySample(options: {
576580
output.splice(0, output.length - 20);
577581
}
578582
for (const line of text.split(/\r?\n/u)) {
579-
if (line.includes("ready (") && readyLogMs == null) {
583+
if (hasGatewayReadyLog(line) && readyLogMs == null) {
580584
readyLogMs = performance.now() - startAt;
581585
}
582586
collectStartupTrace(line, startupTrace);

‎scripts/check-gateway-watch-regression.mjs‎

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -352,10 +352,14 @@ function readProcessTreeCpuMs(rootPid) {
352352
return totalCpuMs;
353353
}
354354

355+
export function hasGatewayReadyLog(text) {
356+
return /\[gateway\] (?:http server listening|ready \()/.test(text);
357+
}
358+
355359
async function waitForGatewayReady(readText, timeoutMs) {
356360
const deadline = Date.now() + timeoutMs;
357361
while (Date.now() < deadline) {
358-
if (/\[gateway\] ready \(/.test(readText())) {
362+
if (hasGatewayReadyLog(readText())) {
359363
return true;
360364
}
361365
await sleep(100);

‎src/cli/run-main.ts‎

Lines changed: 75 additions & 36 deletions
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,7 @@ import process from "node:process";
44
import { fileURLToPath } from "node:url";
55
import { resolveStateDir } from "../config/paths.js";
66
import type { OpenClawConfig } from "../config/types.openclaw.js";
7-
import { normalizeEnv } from "../infra/env.js";
7+
import { isTruthyEnvValue, normalizeEnv } from "../infra/env.js";
88
import { isMainModule } from "../infra/is-main.js";
99
import { ensureOpenClawCliOnPath } from "../infra/path-env.js";
1010
import { assertSupportedRuntime } from "../infra/runtime-guard.js";
@@ -37,6 +37,41 @@ export {
3737
shouldUseRootHelpFastPath,
3838
} from "./run-main-policy.js";
3939

40+
type Awaitable<T> = T | Promise<T>;
41+
42+
function createGatewayCliMainStartupTrace(argv: string[]) {
43+
const enabled =
44+
isTruthyEnvValue(process.env.OPENCLAW_GATEWAY_STARTUP_TRACE) &&
45+
argv.slice(2).includes("gateway");
46+
const started = performance.now();
47+
let last = started;
48+
const emit = (name: string, durationMs: number, totalMs: number) => {
49+
if (!enabled) {
50+
return;
51+
}
52+
process.stderr.write(
53+
`[gateway] startup trace: cli.main.${name} ${durationMs.toFixed(1)}ms total=${totalMs.toFixed(1)}ms\n`,
54+
);
55+
};
56+
return {
57+
mark(name: string) {
58+
const now = performance.now();
59+
emit(name, now - last, now - started);
60+
last = now;
61+
},
62+
async measure<T>(name: string, run: () => Awaitable<T>): Promise<T> {
63+
const before = performance.now();
64+
try {
65+
return await run();
66+
} finally {
67+
const now = performance.now();
68+
emit(name, now - before, now - started);
69+
last = now;
70+
}
71+
},
72+
};
73+
}
74+
4075
async function closeCliMemoryManagers(): Promise<void> {
4176
const { hasMemoryRuntime } = await import("../plugins/memory-state.js");
4277
if (!hasMemoryRuntime()) {
@@ -98,6 +133,7 @@ async function ensureCliEnvProxyDispatcher(): Promise<void> {
98133

99134
export async function runCli(argv: string[] = process.argv) {
100135
const originalArgv = normalizeWindowsArgv(argv);
136+
const startupTrace = createGatewayCliMainStartupTrace(originalArgv);
101137
const parsedContainer = parseCliContainerArgs(originalArgv);
102138
if (!parsedContainer.ok) {
103139
throw new Error(parsedContainer.error);
@@ -123,10 +159,13 @@ export async function runCli(argv: string[] = process.argv) {
123159
return;
124160
}
125161
let normalizedArgv = parsedProfile.argv;
162+
startupTrace.mark("argv");
126163

127164
if (shouldLoadCliDotEnv()) {
128-
const { loadCliDotEnv } = await import("./dotenv.js");
129-
loadCliDotEnv({ quiet: true });
165+
await startupTrace.measure("dotenv", async () => {
166+
const { loadCliDotEnv } = await import("./dotenv.js");
167+
loadCliDotEnv({ quiet: true });
168+
});
130169
}
131170
normalizeEnv();
132171
if (shouldEnsureCliPath(normalizedArgv)) {
@@ -206,19 +245,18 @@ export async function runCli(argv: string[] = process.argv) {
206245
const [
207246
{ initializeDebugProxyCapture, finalizeDebugProxyCapture },
208247
{ maybeWarnAboutDebugProxyCoverage },
209-
] = await Promise.all([
210-
import("../proxy-capture/runtime.js"),
211-
import("../proxy-capture/coverage.js"),
212-
]);
248+
] = await startupTrace.measure("proxy-imports", () =>
249+
Promise.all([import("../proxy-capture/runtime.js"), import("../proxy-capture/coverage.js")]),
250+
);
213251
initializeDebugProxyCapture("cli");
214252
process.once("exit", () => {
215253
finalizeDebugProxyCapture();
216254
});
217-
await ensureCliEnvProxyDispatcher();
255+
await startupTrace.measure("proxy-dispatcher", () => ensureCliEnvProxyDispatcher());
218256
maybeWarnAboutDebugProxyCoverage();
219257

220-
const { tryRouteCli } = await import("./route.js");
221-
if (await tryRouteCli(normalizedArgv)) {
258+
const { tryRouteCli } = await startupTrace.measure("route-import", () => import("./route.js"));
259+
if (await startupTrace.measure("route", () => tryRouteCli(normalizedArgv))) {
222260
return;
223261
}
224262

@@ -253,14 +291,16 @@ export async function runCli(argv: string[] = process.argv) {
253291
isUncaughtExceptionHandled,
254292
},
255293
{ restoreTerminalState },
256-
] = await Promise.all([
257-
import("./program.js"),
258-
import("../infra/errors.js"),
259-
import("../infra/fatal-error-hooks.js"),
260-
import("../infra/unhandled-rejections.js"),
261-
import("../terminal/restore.js"),
262-
]);
263-
const program = buildProgram();
294+
] = await startupTrace.measure("core-imports", () =>
295+
Promise.all([
296+
import("./program.js"),
297+
import("../infra/errors.js"),
298+
import("../infra/fatal-error-hooks.js"),
299+
import("../infra/unhandled-rejections.js"),
300+
import("../terminal/restore.js"),
301+
]),
302+
);
303+
const program = await startupTrace.measure("build-program", () => buildProgram());
264304

265305
// Global error handlers to prevent silent crashes from unhandled rejections/exceptions.
266306
// These log the error and exit gracefully instead of crashing without trace.
@@ -291,14 +331,16 @@ export async function runCli(argv: string[] = process.argv) {
291331
// are correct even with lazy command registration.
292332
const { primary } = invocation;
293333
if (primary && shouldRegisterPrimaryCommandOnly(parseArgv)) {
294-
const { getProgramContext } = await import("./program/program-context.js");
295-
const ctx = getProgramContext(program);
296-
if (ctx) {
297-
const { registerCoreCliByName } = await import("./program/command-registry.js");
298-
await registerCoreCliByName(program, ctx, primary, parseArgv);
299-
}
300-
const { registerSubCliByName } = await import("./program/register.subclis.js");
301-
await registerSubCliByName(program, primary);
334+
await startupTrace.measure("register-primary", async () => {
335+
const { getProgramContext } = await import("./program/program-context.js");
336+
const ctx = getProgramContext(program);
337+
if (ctx) {
338+
const { registerCoreCliByName } = await import("./program/command-registry.js");
339+
await registerCoreCliByName(program, ctx, primary, parseArgv);
340+
}
341+
const { registerSubCliByName } = await import("./program/register.subclis.js");
342+
await registerSubCliByName(program, primary);
343+
});
302344
}
303345

304346
const hasBuiltinPrimary =
@@ -312,17 +354,14 @@ export async function runCli(argv: string[] = process.argv) {
312354
hasBuiltinPrimary,
313355
});
314356
if (!shouldSkipPluginRegistration) {
315-
// Register plugin CLI commands before parsing
316-
const { registerPluginCliCommandsFromValidatedConfig } = await import("../plugins/cli.js");
317-
const config = await registerPluginCliCommandsFromValidatedConfig(
318-
program,
319-
undefined,
320-
undefined,
321-
{
357+
const config = await startupTrace.measure("register-plugin-commands", async () => {
358+
const { registerPluginCliCommandsFromValidatedConfig } =
359+
await import("../plugins/cli.js");
360+
return await registerPluginCliCommandsFromValidatedConfig(program, undefined, undefined, {
322361
mode: "lazy",
323362
primary,
324-
},
325-
);
363+
});
364+
});
326365
if (config) {
327366
if (
328367
primary &&
@@ -349,7 +388,7 @@ export async function runCli(argv: string[] = process.argv) {
349388
stopStartupProgress();
350389

351390
try {
352-
await program.parseAsync(parseArgv);
391+
await startupTrace.measure("parse", () => program.parseAsync(parseArgv));
353392
} catch (error) {
354393
if (!isCommanderParseExit(error)) {
355394
throw error;

‎src/entry.ts‎

Lines changed: 42 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -13,7 +13,7 @@ import {
1313
} from "./entry.compile-cache.js";
1414
import { buildCliRespawnPlan } from "./entry.respawn.js";
1515
import { tryHandleRootVersionFastPath } from "./entry.version-fast-path.js";
16-
import { normalizeEnv } from "./infra/env.js";
16+
import { isTruthyEnvValue, normalizeEnv } from "./infra/env.js";
1717
import { isMainModule } from "./infra/is-main.js";
1818
import { ensureOpenClawExecMarkerOnProcess } from "./infra/openclaw-exec-env.js";
1919
import { installProcessWarningFilter } from "./infra/warning-filter.js";
@@ -34,6 +34,41 @@ function shouldForceReadOnlyAuthStore(argv: string[]): boolean {
3434
return false;
3535
}
3636

37+
function createGatewayEntryStartupTrace(argv: string[]) {
38+
const enabled =
39+
isTruthyEnvValue(process.env.OPENCLAW_GATEWAY_STARTUP_TRACE) &&
40+
argv.slice(2).includes("gateway");
41+
const started = performance.now();
42+
let last = started;
43+
const emit = (name: string, durationMs: number, totalMs: number) => {
44+
if (!enabled) {
45+
return;
46+
}
47+
process.stderr.write(
48+
`[gateway] startup trace: entry.${name} ${durationMs.toFixed(1)}ms total=${totalMs.toFixed(1)}ms\n`,
49+
);
50+
};
51+
return {
52+
mark(name: string) {
53+
const now = performance.now();
54+
emit(name, now - last, now - started);
55+
last = now;
56+
},
57+
async measure<T>(name: string, run: () => Promise<T>): Promise<T> {
58+
const before = performance.now();
59+
try {
60+
return await run();
61+
} finally {
62+
const now = performance.now();
63+
emit(name, now - before, now - started);
64+
last = now;
65+
}
66+
},
67+
};
68+
}
69+
70+
const gatewayEntryStartupTrace = createGatewayEntryStartupTrace(process.argv);
71+
3772
// Guard: only run entry-point logic when this file is the main module.
3873
// The bundler may import entry.js as a shared dependency when dist/index.js
3974
// is the actual entry point; without this guard the top-level code below
@@ -60,6 +95,7 @@ if (
6095
enableOpenClawCompileCache({
6196
installRoot,
6297
});
98+
gatewayEntryStartupTrace.mark("bootstrap");
6399

64100
if (shouldForceReadOnlyAuthStore(process.argv)) {
65101
process.env.OPENCLAW_AUTH_STORE_READONLY = "1";
@@ -130,6 +166,7 @@ if (
130166
// Keep Commander and ad-hoc argv checks consistent.
131167
process.argv = parsed.argv;
132168
}
169+
gatewayEntryStartupTrace.mark("argv");
133170

134171
if (!tryHandleRootVersionFastPath(process.argv)) {
135172
await runMainOrRootHelp(process.argv);
@@ -185,7 +222,10 @@ async function runMainOrRootHelp(argv: string[]): Promise<void> {
185222
return;
186223
}
187224
try {
188-
const { runCli } = await import("./cli/run-main.js");
225+
const { runCli } = await gatewayEntryStartupTrace.measure(
226+
"run-main-import",
227+
() => import("./cli/run-main.js"),
228+
);
189229
await runCli(argv);
190230
} catch (error) {
191231
console.error(

‎src/gateway/server-close.ts‎

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,6 @@ import { disposeRegisteredAgentHarnesses } from "../agents/harness/registry.js";
44
import { disposeAllSessionMcpRuntimes } from "../agents/pi-bundle-mcp-tools.js";
55
import type { CanvasHostHandler, CanvasHostServer } from "../canvas-host/server.js";
66
import { type ChannelId, listChannelPlugins } from "../channels/plugins/index.js";
7-
import { stopGmailWatcher } from "../hooks/gmail-watcher.js";
87
import { createInternalHookEvent, triggerInternalHook } from "../hooks/internal-hooks.js";
98
import type { HeartbeatRunner } from "../infra/heartbeat-runner.js";
109
import { createSubsystemLogger } from "../logging/subsystem.js";
@@ -100,6 +99,11 @@ async function disposeAllBundleLspRuntimesOnDemand(): Promise<void> {
10099
await disposeAllBundleLspRuntimes();
101100
}
102101

102+
async function stopGmailWatcherOnDemand(): Promise<void> {
103+
const { stopGmailWatcher } = await import("../hooks/gmail-watcher.js");
104+
await stopGmailWatcher();
105+
}
106+
103107
export async function runGatewayClosePrelude(params: {
104108
stopDiagnostics?: () => void;
105109
clearSkillsRefreshTimer?: () => void;
@@ -242,7 +246,7 @@ export function createGatewayCloseHandler(params: {
242246
if (params.pluginServices) {
243247
await params.pluginServices.stop().catch(() => {});
244248
}
245-
await stopGmailWatcher();
249+
await stopGmailWatcherOnDemand();
246250
params.cron.stop();
247251
params.heartbeatRunner.stop();
248252
try {

‎src/gateway/server-reload-handlers.ts‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -5,8 +5,6 @@ import { getTotalPendingReplies } from "../auto-reply/reply/dispatcher-registry.
55
import type { CliDeps } from "../cli/deps.types.js";
66
import { isRestartEnabled } from "../config/commands.flags.js";
77
import type { OpenClawConfig } from "../config/types.openclaw.js";
8-
import { startGmailWatcherWithLogs } from "../hooks/gmail-watcher-lifecycle.js";
9-
import { stopGmailWatcher } from "../hooks/gmail-watcher.js";
108
import { isTruthyEnvValue } from "../infra/env.js";
119
import type { HeartbeatRunner } from "../infra/heartbeat-runner.js";
1210
import { resetDirectoryCache } from "../infra/outbound/target-resolver.js";
@@ -269,6 +267,10 @@ export function createGatewayReloadHandlers(params: GatewayReloadHandlerParams)
269267
}
270268

271269
if (plan.restartGmailWatcher) {
270+
const [{ stopGmailWatcher }, { startGmailWatcherWithLogs }] = await Promise.all([
271+
import("../hooks/gmail-watcher.js"),
272+
import("../hooks/gmail-watcher-lifecycle.js"),
273+
]);
272274
await stopGmailWatcher().catch((err) => {
273275
params.logHooks.warn(`gmail watcher stop failed during reload: ${String(err)}`);
274276
});

‎test/scripts/check-gateway-watch-regression.test.ts‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
import { describe, expect, it } from "vitest";
22
import {
3+
hasGatewayReadyLog,
34
isIgnoredDistRuntimeWatchPath,
45
shouldRefreshBuildStampForRestoredArtifacts,
56
} from "../../scripts/check-gateway-watch-regression.mjs";
@@ -23,6 +24,12 @@ describe("check-gateway-watch-regression", () => {
2324
).toBe(false);
2425
});
2526

27+
it("recognizes current and legacy gateway ready logs", () => {
28+
expect(hasGatewayReadyLog("[gateway] http server listening (0 plugins, 0.8s)")).toBe(true);
29+
expect(hasGatewayReadyLog("[gateway] ready (0 plugins, 0.8s)")).toBe(true);
30+
expect(hasGatewayReadyLog("[gateway] starting HTTP server...")).toBe(false);
31+
});
32+
2633
it("refreshes restored build stamps only for skip-build config mtime drift", () => {
2734
expect(
2835
shouldRefreshBuildStampForRestoredArtifacts({

0 commit comments

Comments
 (0)