From ae3720c623c17d5b6ae3266d8302acee1bf08d40 Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Thu, 23 Jul 2026 12:33:23 +0200 Subject: [PATCH 1/5] test(mcp): diagnose startup stalls Copilot-Session: b62093c2-7f1f-46d8-9f9a-be7e30a965ab --- .github/workflows/infra.yml | 2 + .github/workflows/tests_components.yml | 1 + .github/workflows/tests_extension.yml | 1 + .github/workflows/tests_mcp.yml | 34 ++++---- .github/workflows/tests_primary.yml | 6 ++ .../playwright-core/src/server/browser.ts | 5 ++ .../playwright-core/src/server/browserType.ts | 16 +++- .../src/tools/cli-client/DEPS.list | 5 ++ .../src/tools/cli-client/cli.ts | 9 +- .../src/tools/cli-client/program.ts | 6 ++ .../src/tools/cli-client/session.ts | 13 ++- .../src/tools/cli-client/startupTrace.ts | 33 ++++++++ .../src/tools/cli-daemon/program.ts | 14 +++- .../src/tools/dashboard/dashboardApp.ts | 26 +++++- packages/utils/startupTrace.ts | 32 +++++++ tests/mcp/cli-fixtures.ts | 83 +++++++++++++++++-- 16 files changed, 258 insertions(+), 28 deletions(-) create mode 100644 packages/playwright-core/src/tools/cli-client/startupTrace.ts create mode 100644 packages/utils/startupTrace.ts diff --git a/.github/workflows/infra.yml b/.github/workflows/infra.yml index fe5ef6cfbf7d6..f0510959486e9 100644 --- a/.github/workflows/infra.yml +++ b/.github/workflows/infra.yml @@ -13,6 +13,7 @@ on: jobs: doc-and-lint: name: "docs & lint" + if: github.event_name != 'pull_request' || github.head_ref != 'skn0tt-diagnose-mcp-startup-stalls' runs-on: ubuntu-24.04 steps: - uses: actions/checkout@v6 @@ -35,6 +36,7 @@ jobs: continue-on-error: true lint-snippets: name: "Lint snippets" + if: github.event_name != 'pull_request' || github.head_ref != 'skn0tt-diagnose-mcp-startup-stalls' runs-on: ubuntu-latest steps: - uses: actions/checkout@v6 diff --git a/.github/workflows/tests_components.yml b/.github/workflows/tests_components.yml index e525ea0de3bec..e1857a57312b7 100644 --- a/.github/workflows/tests_components.yml +++ b/.github/workflows/tests_components.yml @@ -25,6 +25,7 @@ env: jobs: test_components: name: ${{ matrix.os }} - Node.js ${{ matrix.node-version }} + if: github.event_name != 'pull_request' || github.head_ref != 'skn0tt-diagnose-mcp-startup-stalls' strategy: fail-fast: false matrix: diff --git a/.github/workflows/tests_extension.yml b/.github/workflows/tests_extension.yml index 38a413f319c95..86704bbd4b30c 100644 --- a/.github/workflows/tests_extension.yml +++ b/.github/workflows/tests_extension.yml @@ -35,6 +35,7 @@ env: jobs: test_extension: name: ${{ matrix.os }} + if: github.event_name != 'pull_request' || github.head_ref != 'skn0tt-diagnose-mcp-startup-stalls' strategy: fail-fast: false matrix: diff --git a/.github/workflows/tests_mcp.yml b/.github/workflows/tests_mcp.yml index 8a5d04390435b..0dd483bc982f1 100644 --- a/.github/workflows/tests_mcp.yml +++ b/.github/workflows/tests_mcp.yml @@ -1,4 +1,4 @@ -name: MCP +name: MCP startup diagnostic (temporary) on: push: @@ -30,24 +30,18 @@ env: jobs: test_mcp: - name: ${{ matrix.os }} - ${{ matrix.project }} + name: DIAGNOSTIC - ${{ matrix.os }} - ${{ matrix.project }} - sample ${{ matrix.sample }} # Used for authentication of flakiness upload environment: ${{ github.event_name == 'push' && 'allow-uploading-flakiness-results' || null }} strategy: fail-fast: false matrix: - os: [ubuntu-latest, macos-latest] - project: [chrome, chromium, firefox, webkit] - include: - - os: windows-latest - project: chrome - - os: windows-latest - project: chromium - - os: windows-latest - project: firefox - - os: windows-latest - project: webkit - - os: windows-latest + # Temporary startup-stall diagnostic: 10 fresh runners for each affected configuration. + os: [ubuntu-latest, windows-latest] + project: [chrome, msedge] + sample: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10] + exclude: + - os: ubuntu-latest project: msedge runs-on: ${{ matrix.os }} permissions: @@ -58,8 +52,16 @@ jobs: - uses: ./.github/actions/run-test with: node-version: "22" - command: npm run test-mcp -- --project=${{ matrix.project }} - bot-name: "mcp-${{ matrix.os }}-${{ matrix.project }}" + # Keep the full suite and serial execution so setup/order/cleanup effects remain intact. + command: npm run test-mcp -- --project=${{ matrix.project }} --workers=1 + bot-name: "mcp-startup-diagnostic-${{ matrix.os }}-${{ matrix.project }}-sample-${{ matrix.sample }}" flakiness-client-id: ${{ secrets.AZURE_FLAKINESS_DASHBOARD_CLIENT_ID }} flakiness-tenant-id: ${{ secrets.AZURE_FLAKINESS_DASHBOARD_TENANT_ID }} flakiness-subscription-id: ${{ secrets.AZURE_FLAKINESS_DASHBOARD_SUBSCRIPTION_ID }} + - name: Upload raw MCP startup timelines + if: always() + uses: actions/upload-artifact@v4 + with: + name: "mcp-startup-timelines-${{ matrix.os }}-${{ matrix.project }}-sample-${{ matrix.sample }}" + path: test-results/mcp-startup-timelines/*.jsonl + if-no-files-found: error diff --git a/.github/workflows/tests_primary.yml b/.github/workflows/tests_primary.yml index a4da6a0e7f061..bf0004e9e8720 100644 --- a/.github/workflows/tests_primary.yml +++ b/.github/workflows/tests_primary.yml @@ -32,6 +32,7 @@ env: jobs: test_linux: name: ${{ matrix.os }} (${{ matrix.browser }} - Node.js ${{ matrix.node-version }}) + if: github.event_name != 'pull_request' || github.head_ref != 'skn0tt-diagnose-mcp-startup-stalls' environment: ${{ github.event_name == 'push' && 'allow-uploading-flakiness-results' || null }} strategy: fail-fast: false @@ -67,6 +68,7 @@ jobs: test_test_runner: name: Test Runner + if: github.event_name != 'pull_request' || github.head_ref != 'skn0tt-diagnose-mcp-startup-stalls' environment: ${{ github.event_name == 'push' && 'allow-uploading-flakiness-results' || null }} strategy: fail-fast: false @@ -142,6 +144,7 @@ jobs: test_web_components: name: Web Components - ${{ matrix.package }} + if: github.event_name != 'pull_request' || github.head_ref != 'skn0tt-diagnose-mcp-startup-stalls' environment: ${{ github.event_name == 'push' && 'allow-uploading-flakiness-results' || null }} permissions: id-token: write # This is required for OIDC login (azure/login) to succeed @@ -165,6 +168,7 @@ jobs: test_vscode_extension: name: VSCode Extension + if: github.event_name != 'pull_request' || github.head_ref != 'skn0tt-diagnose-mcp-startup-stalls' runs-on: ubuntu-latest steps: - uses: actions/checkout@v6 @@ -201,6 +205,7 @@ jobs: test_package_installations: name: "Installation Test ${{ matrix.os }}" + if: github.event_name != 'pull_request' || github.head_ref != 'skn0tt-diagnose-mcp-startup-stalls' environment: ${{ github.event_name == 'push' && 'allow-uploading-flakiness-results' || null }} strategy: fail-fast: false @@ -237,6 +242,7 @@ jobs: test_clock_frozen_time_linux: name: time library - ${{ matrix.clock }} + if: github.event_name != 'pull_request' || github.head_ref != 'skn0tt-diagnose-mcp-startup-stalls' environment: ${{ github.event_name == 'push' && 'allow-uploading-flakiness-results' || null }} permissions: id-token: write # This is required for OIDC login (azure/login) to succeed diff --git a/packages/playwright-core/src/server/browser.ts b/packages/playwright-core/src/server/browser.ts index 56fff6415a054..cf8c4443edac3 100644 --- a/packages/playwright-core/src/server/browser.ts +++ b/packages/playwright-core/src/server/browser.ts @@ -18,6 +18,7 @@ import fs from 'fs'; import { makeSocketPath } from '@utils/fileUtils'; import { createGuid } from '@utils/crypto'; +import { startupTrace } from '@utils/startupTrace'; import { BrowserContext, validateBrowserContextOptions } from './browserContext'; import { Download } from './download'; import { SdkObject } from './instrumentation'; @@ -231,6 +232,7 @@ export class BrowserServer { endpoint = this._pipeSocketPath; } + startupTrace('browser.registry-publication.start', { browserPid: this._browser.options.browserProcess.process?.pid, title, endpoint }); const browserInfo: BrowserInfo = { guid: this._browser.guid, browserName: this._browser.options.browserType, @@ -243,10 +245,12 @@ export class BrowserServer { workspaceDir: options.workspaceDir, metadata: options.metadata, }); + startupTrace('browser.registry-publication.end', { browserPid: this._browser.options.browserProcess.process?.pid, title, endpoint }); return { endpoint }; } async stop() { + startupTrace('browser.server-teardown.start', { browserPid: this._browser.options.browserProcess.process?.pid }); if (!this._browser.options.userDataDir) await serverRegistry.delete(this._browser.guid); if (this._pipeSocketPath && process.platform !== 'win32') @@ -256,6 +260,7 @@ export class BrowserServer { this._pipeServer = undefined; this._wsServer = undefined; this._isStarted = false; + startupTrace('browser.server-teardown.end', { browserPid: this._browser.options.browserProcess.process?.pid }); } private async _socketPath() { diff --git a/packages/playwright-core/src/server/browserType.ts b/packages/playwright-core/src/server/browserType.ts index bed4f1d3e86a4..9b5c4e9af124b 100644 --- a/packages/playwright-core/src/server/browserType.ts +++ b/packages/playwright-core/src/server/browserType.ts @@ -25,6 +25,7 @@ import { debugMode } from '@utils/debug'; import { existsAsync } from '@utils/fileUtils'; import { envArrayToObject, launchProcess } from '@utils/processLauncher'; import { RecentLogsCollector } from '@utils/debugLogger'; +import { startupTrace } from '@utils/startupTrace'; import { normalizeProxySettings, validateBrowserContextOptions } from './browserContext'; import { helper } from './helper'; import { SdkObject } from './instrumentation'; @@ -73,6 +74,7 @@ export abstract class BrowserType extends SdkObject { } async launchPersistentContext(progress: Progress, userDataDir: string, options: channels.BrowserTypeLaunchPersistentContextOptions & { internalIgnoreHTTPSErrors?: boolean, socksProxyPort?: number }): Promise { + startupTrace('browser.launch-persistent-context.start', { browserName: this._name }); const launchOptions = this._validateLaunchOptions(options); // Note: Any initial TLS requests will fail since we rely on the Page/Frames initialize which sets ignoreHTTPSErrors. let clientCertificatesProxy: ClientCertificatesProxy | undefined; @@ -85,6 +87,7 @@ export abstract class BrowserType extends SdkObject { try { const browser = await this._innerLaunchWithRetries(progress, launchOptions, options, helper.debugProtocolLogger(), userDataDir).catch(e => { throw this._rewriteStartupLog(e); }); browser._defaultContext!._clientCertificatesProxy = clientCertificatesProxy; + startupTrace('browser.launch-persistent-context.end', { browserName: this._name }); return browser._defaultContext!; } catch (error) { await clientCertificatesProxy?.close().catch(() => {}); @@ -135,11 +138,16 @@ export abstract class BrowserType extends SdkObject { if (persistent) validateBrowserContextOptions(persistent, browserOptions); copyTestHooks(options, browserOptions); + startupTrace('browser.transport-connect.start', { browserName: this._name, browserPid: browserProcess.process?.pid, persistent: !!persistent }); const browser = await progress.race(this.connectToTransport(transport, browserOptions, browserLogsCollector)); + startupTrace('browser.transport-connect.end', { browserName: this._name, browserPid: browserProcess.process?.pid, persistent: !!persistent }); (browser as any)._userDataDirForTest = userDataDir; // We assume no control when using custom arguments, and do not prepare the default context in that case. - if (persistent && !options.ignoreAllDefaultArgs) + if (persistent && !options.ignoreAllDefaultArgs) { + startupTrace('browser.persistent-context-load.start', { browserName: this._name, browserPid: browserProcess.process?.pid }); await browser._defaultContext!.loadDefaultContext(progress); + startupTrace('browser.persistent-context-load.end', { browserName: this._name, browserPid: browserProcess.process?.pid }); + } return browser; } catch (error) { await progress.race(browserProcess.close().catch(() => {})); @@ -211,6 +219,7 @@ export abstract class BrowserType extends SdkObject { let transport: ConnectionTransport | undefined = undefined; let browserProcess: BrowserProcess | undefined = undefined; const exitPromise = new ManualPromise(); + startupTrace('browser.launch-process.start', { browserName: this._name, persistent: isPersistent }); const { launchedProcess, gracefullyClose, kill } = await progress.race(launchProcess({ command: prepared.executable, args: prepared.browserArguments, @@ -235,12 +244,14 @@ export abstract class BrowserType extends SdkObject { } }, onExit: (exitCode, signal) => { + startupTrace('browser.process.exit', { browserName: this._name, browserPid: browserProcess?.process?.pid, exitCode, signal }); // Unblock launch when browser prematurely exits. exitPromise.resolve(); if (browserProcess && browserProcess.onclose) browserProcess.onclose(exitCode, signal); }, })); + startupTrace('browser.process.spawned', { browserName: this._name, browserPid: launchedProcess.pid, persistent: isPersistent }); async function closeOrKill(timeout: number): Promise { let timer: NodeJS.Timeout; @@ -262,6 +273,7 @@ export abstract class BrowserType extends SdkObject { kill }; try { + startupTrace('browser.ready-state.start', { browserName: this._name, browserPid: launchedProcess.pid }); const { wsEndpoint } = await progress.race([ this.waitForReadyState(options, browserLogsCollector), exitPromise.then(() => ({ wsEndpoint: undefined })), @@ -271,12 +283,14 @@ export abstract class BrowserType extends SdkObject { const updatedLog = this.doRewriteStartupLog(log); throw new Error(`Failed to launch the browser process.\nBrowser logs:\n${updatedLog}`); } + startupTrace('browser.ready-state.end', { browserName: this._name, browserPid: launchedProcess.pid }); if (!this.supportsPipeTransport(options)) { transport = await WebSocketTransport.connect(progress, wsEndpoint!); } else { const stdio = launchedProcess.stdio as unknown as [NodeJS.ReadableStream, NodeJS.WritableStream, NodeJS.WritableStream, NodeJS.WritableStream, NodeJS.ReadableStream]; transport = new PipeTransport(stdio[3], stdio[4]); } + startupTrace('browser.transport.ready', { browserName: this._name, browserPid: launchedProcess.pid }); return { browserProcess, artifactsDir: prepared.artifactsDir, userDataDir: prepared.userDataDir, transport, wsEndpoint }; } catch (error) { await progress.race(closeOrKill(DEFAULT_PLAYWRIGHT_TIMEOUT).catch(() => {})); diff --git a/packages/playwright-core/src/tools/cli-client/DEPS.list b/packages/playwright-core/src/tools/cli-client/DEPS.list index 07864bbb60b55..d834f41c7a0b9 100644 --- a/packages/playwright-core/src/tools/cli-client/DEPS.list +++ b/packages/playwright-core/src/tools/cli-client/DEPS.list @@ -7,6 +7,7 @@ ./output.ts ./session.ts ./registry.ts +./startupTrace.ts [output.ts] "strict" @@ -22,6 +23,7 @@ ../../package.ts ../utils/socketConnection.ts ./registry.ts +./startupTrace.ts [socketConnection.ts] "strict" @@ -30,5 +32,8 @@ "strict" ../../package.ts +[startupTrace.ts] +"strict" + [minimist.ts] "strict" diff --git a/packages/playwright-core/src/tools/cli-client/cli.ts b/packages/playwright-core/src/tools/cli-client/cli.ts index 6db3e40ee050b..8865fd5d69fed 100644 --- a/packages/playwright-core/src/tools/cli-client/cli.ts +++ b/packages/playwright-core/src/tools/cli-client/cli.ts @@ -15,8 +15,15 @@ */ import { program } from './program'; +import { startupTrace } from './startupTrace'; -program().catch(e => { +startupTrace('cli-client.process.start', { argv: process.argv.slice(2) }); +process.on('exit', exitCode => startupTrace('cli-client.process.exit', { exitCode })); + +program().then(() => { + startupTrace('cli-client.command.ack'); +}).catch(e => { + startupTrace('cli-client.command.error', { error: e.message }); /* eslint-disable no-console */ console.error(e.message); /* eslint-disable no-restricted-properties */ diff --git a/packages/playwright-core/src/tools/cli-client/program.ts b/packages/playwright-core/src/tools/cli-client/program.ts index 6cf1a6b37e043..b44151bc06766 100644 --- a/packages/playwright-core/src/tools/cli-client/program.ts +++ b/packages/playwright-core/src/tools/cli-client/program.ts @@ -29,6 +29,7 @@ import { Session } from './session'; import { libPath } from '../../package'; import { serverRegistry } from '../../serverRegistry'; import { minimist } from './minimist'; +import { startupTrace } from './startupTrace'; import type { ListData, ListedBrowser, Output } from './output'; import type { ClientInfo, SessionFile } from './registry'; @@ -237,18 +238,22 @@ export async function program(options?: { embedderVersion?: string}) { return; } const foreground = args.port !== undefined; + startupTrace('cli-client.dashboard-spawn.start', { foreground, daemonArgs }); const child = spawn(process.execPath, daemonArgs, { detached: !foreground, stdio: foreground ? 'inherit' : ['pipe', 'pipe', 'ignore'], }); + startupTrace('cli-client.dashboard-spawned', { foreground, dashboardPid: child.pid }); if (foreground) { await new Promise(resolve => child.on('exit', () => resolve())); + startupTrace('cli-client.dashboard-foreground.exit', { dashboardPid: child.pid }); return; } const timer = setTimeout(() => child.stdin!.destroy(), 60_000); child.unref(); let daemonPid: number; try { + startupTrace('cli-client.dashboard-ready-ack.start', { dashboardPid: child.pid }); await new Promise((resolve, reject) => { let outLog = ''; child.stdout!.on('data', data => { @@ -261,6 +266,7 @@ export async function program(options?: { embedderVersion?: string}) { }); child.once('exit', (code, signal) => reject(new Error(`Dashboard daemon exited (code=${code}, signal=${signal}) before signaling READY${outLog ? '\n' + outLog : ''}`))); }); + startupTrace('cli-client.dashboard-ready-ack.end', { dashboardPid: child.pid, daemonPid: daemonPid! }); } finally { clearTimeout(timer); child.removeAllListeners('exit'); diff --git a/packages/playwright-core/src/tools/cli-client/session.ts b/packages/playwright-core/src/tools/cli-client/session.ts index bbcf54cf41d90..67b90bc355a58 100644 --- a/packages/playwright-core/src/tools/cli-client/session.ts +++ b/packages/playwright-core/src/tools/cli-client/session.ts @@ -22,6 +22,7 @@ import os from 'os'; import path from 'path'; import { libPath } from '../../package'; import { compareSemver, SocketConnection } from '../utils/socketConnection'; +import { startupTrace } from './startupTrace'; import { resolveSessionName } from './registry'; import type { SessionConfig, ClientInfo, SessionFile } from './registry'; @@ -49,7 +50,10 @@ export class Session { const { socket } = await this._connect(); if (!socket) throw new Error(`Browser '${this.name}' is not open. Run\n\n playwright-cli${this.name !== 'default' ? ` -s=${this.name}` : ''} open\n\nto start the browser session.`); - return await SocketConnectionClient.sendAndClose(socket, 'run', { args, cwd: process.cwd(), raw: options?.raw, json: options?.json }); + startupTrace('cli-client.daemon-command.start', { sessionName: this.name, command: args._?.[0] }); + const result = await SocketConnectionClient.sendAndClose(socket, 'run', { args, cwd: process.cwd(), raw: options?.raw, json: options?.json }); + startupTrace('cli-client.daemon-command.ack', { sessionName: this.name, command: args._?.[0] }); + return result; } async stop(): Promise<{ wasOpen: boolean }> { @@ -89,11 +93,14 @@ export class Session { } private async _connect(): Promise<{ socket?: net.Socket, error?: Error }> { + startupTrace('cli-client.daemon-connect.start', { sessionName: this.name, socketPath: this.config.socketPath }); return await new Promise(resolve => { const socket = net.createConnection(this.config.socketPath, () => { + startupTrace('cli-client.daemon-connect.end', { sessionName: this.name, socketPath: this.config.socketPath }); resolve({ socket }); }); socket.on('error', error => { + startupTrace('cli-client.daemon-connect.error', { sessionName: this.name, socketPath: this.config.socketPath, error: error.message }); if (os.platform() !== 'win32') void fs.promises.unlink(this.config.socketPath).catch(() => {}).then(() => resolve({ error })); else @@ -144,11 +151,13 @@ export class Session { else if (cliArgs.endpoint) args.push(`--endpoint=${cliArgs.endpoint}`); + startupTrace('cli-client.daemon-spawn.start', { sessionName, mode, args }); const child = spawn(process.execPath, args, { detached: true, stdio: ['ignore', 'pipe', err], cwd: process.cwd(), // Will be used as root. }); + startupTrace('cli-client.daemon-spawned', { sessionName, mode, daemonPid: child.pid }); let signalled = false; const sigintHandler = () => { @@ -165,6 +174,7 @@ export class Session { let outLog = ''; const rejectWithPid = (reject: (e: Error) => void, message: string) => reject(Object.assign(new Error(`Daemon pid=${child.pid}: ${message}`), { daemonPid: child.pid })); + startupTrace('cli-client.daemon-ready-ack.start', { sessionName, daemonPid: child.pid }); await new Promise((resolve, reject) => { child.stdout!.on('data', data => { outLog += data.toString(); @@ -178,6 +188,7 @@ export class Session { } }); }); + startupTrace('cli-client.daemon-ready-ack.end', { sessionName, daemonPid: child.pid }); process.off('SIGINT', sigintHandler); process.off('SIGTERM', sigtermHandler); diff --git a/packages/playwright-core/src/tools/cli-client/startupTrace.ts b/packages/playwright-core/src/tools/cli-client/startupTrace.ts new file mode 100644 index 0000000000000..fa31e6f9db91d --- /dev/null +++ b/packages/playwright-core/src/tools/cli-client/startupTrace.ts @@ -0,0 +1,33 @@ +/** + * Copyright (c) Microsoft Corporation. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +import fs from 'fs'; + +// CLI client entries are emitted as standalone files and cannot import @utils/startupTrace. +export function startupTrace(phase: string, data: Record = {}): void { + const traceFile = process.env.PWTEST_MCP_STARTUP_TRACE; + if (!traceFile) + return; + const entry = { + timestamp: new Date().toISOString(), + monotonicTime: Number(process.hrtime.bigint() / 1_000_000n), + pid: process.pid, + ppid: process.ppid, + phase, + ...data, + }; + fs.appendFileSync(traceFile, JSON.stringify(entry) + '\n'); +} diff --git a/packages/playwright-core/src/tools/cli-daemon/program.ts b/packages/playwright-core/src/tools/cli-daemon/program.ts index b57ce32118a45..7417edce95e94 100644 --- a/packages/playwright-core/src/tools/cli-daemon/program.ts +++ b/packages/playwright-core/src/tools/cli-daemon/program.ts @@ -22,6 +22,7 @@ import path from 'path'; import { getAsBooleanFromENV, guessClientName } from '@utils/env'; import { gracefullyProcessExitDoNotHang } from '@utils/processLauncher'; +import { startupTrace } from '@utils/startupTrace'; import { startCliDaemonServer } from './daemon'; import { setupExitWatchdog } from '../mcp/watchdog'; import { createBrowserWithInfo } from '../mcp/browserFactory'; @@ -47,6 +48,8 @@ export function decorateProgram(program: Command) { .option('--init-skills ', 'install skills for the given agent type ("claude" or "agents")') .action(async (sessionName: string, options: any) => { + startupTrace('cli-daemon.process.start', { sessionName, options }); + process.on('exit', exitCode => startupTrace('cli-daemon.process.exit', { sessionName, exitCode })); if (options.initWorkspace) { await initWorkspace(options.initSkills); return; @@ -61,16 +64,25 @@ export function decorateProgram(program: Command) { }; try { + startupTrace('cli-daemon.browser-create.start', { sessionName }); const { browser, browserInfo, canBind, ownership } = await createBrowserWithInfo(mcpConfig, mcpClientInfo, options); - if (canBind) + startupTrace('cli-daemon.browser-create.end', { sessionName, canBind, ownership }); + if (canBind) { + startupTrace('cli-daemon.browser-bind.start', { sessionName }); await browser.bind(sessionName, { workspaceDir: clientInfo.workspaceDir }); + startupTrace('cli-daemon.browser-bind.end', { sessionName }); + } const browserContext = mcpConfig.browser.isolated ? await browser.newContext(mcpConfig.browser.contextOptions) : browser.contexts()[0]; if (!browserContext) throw new Error('Error: unable to connect to a browser that does not have any contexts'); + startupTrace('cli-daemon.browser-context.ready', { sessionName }); const persistent = options.persistent || options.profile || mcpConfig.browser.userDataDir ? true : undefined; + startupTrace('cli-daemon.server.start', { sessionName }); const socketPath = await startCliDaemonServer(sessionName, browserContext, browserInfo, mcpConfig, clientInfo, mcpClientInfo, { persistent, exitOnClose: true, ownership }); + startupTrace('cli-daemon.server.ready', { sessionName, socketPath }); console.log(`Daemon listening on ${socketPath}\n`); } catch (error) { + startupTrace('cli-daemon.process.error', { sessionName, error: String(error) }); console.log(error); gracefullyProcessExitDoNotHang(1); } diff --git a/packages/playwright-core/src/tools/dashboard/dashboardApp.ts b/packages/playwright-core/src/tools/dashboard/dashboardApp.ts index 5faa603223775..503c896e68561 100644 --- a/packages/playwright-core/src/tools/dashboard/dashboardApp.ts +++ b/packages/playwright-core/src/tools/dashboard/dashboardApp.ts @@ -22,6 +22,7 @@ import http from 'http'; import { HttpServer } from '@utils/httpServer'; import { makeSocketPath } from '@utils/fileUtils'; import { gracefullyProcessExitDoNotHang } from '@utils/processLauncher'; +import { startupTrace } from '@utils/startupTrace'; import { ManualPromise } from '@isomorphic/manualPromise'; import { libPath } from '../../package'; import { playwright } from '../../inprocess'; @@ -48,6 +49,7 @@ type DashboardServer = { }; async function startDashboardServer(provider: SessionProvider, options: DashboardOptions): Promise { + startupTrace('dashboard.http-server.start', { host: options.host, port: options.port }); const dashboardDir = libPath('vite', 'dashboard'); const httpServer = new HttpServer(dashboardDir); @@ -85,6 +87,7 @@ async function startDashboardServer(provider: SessionProvider, options: Dashboar else attachDashboardStaticServer(httpServer, dashboardDir); await httpServer.start({ port: options.port, host: options.host }); + startupTrace('dashboard.http-server.ready', { url: httpServer.urlPrefix('human-readable') }); const reveal = (next: DashboardOptions): void => { void connectionLanded.then(() => { @@ -109,9 +112,11 @@ async function startDashboardServer(provider: SessionProvider, options: Dashboar }; const close = async () => { + startupTrace('dashboard.teardown.start'); for (const c of connections) c.close?.(); await httpServer.stop(); + startupTrace('dashboard.teardown.end'); }; return { url: httpServer.urlPrefix('human-readable'), reveal, triggerAnnotate, close }; } @@ -140,6 +145,7 @@ type AppState = { page?: api.Page; server: DashboardServer }; async function launchApp(appName: string, options?: { onClose?: () => void }) { const channel = findChromiumChannelBestEffort('javascript'); + startupTrace('dashboard.browser.launch-persistent-context.start', { channel }); const context = await playwright.chromium.launchPersistentContext('', { ignoreDefaultArgs: ['--enable-automation'], channel, @@ -152,8 +158,12 @@ async function launchApp(appName: string, options?: { onClose?: () => void }) { ], viewport: null, }); - if (process.env.PWTEST_DASHBOARD_APP_BIND_TITLE) + startupTrace('dashboard.browser.launch-persistent-context.end', { channel }); + if (process.env.PWTEST_DASHBOARD_APP_BIND_TITLE) { + startupTrace('dashboard.browser-bind.start', { title: process.env.PWTEST_DASHBOARD_APP_BIND_TITLE }); await context.browser()?.bind(process.env.PWTEST_DASHBOARD_APP_BIND_TITLE, { workspaceDir: process.cwd() }); + startupTrace('dashboard.browser-bind.end', { title: process.env.PWTEST_DASHBOARD_APP_BIND_TITLE }); + } const [page] = context.pages(); // Chromium on macOS opens a new tab when clicking on the dock icon. @@ -167,7 +177,10 @@ async function launchApp(appName: string, options?: { onClose?: () => void }) { }); } - page.on('close', () => options?.onClose?.()); + page.on('close', () => { + startupTrace('dashboard.browser-page.close'); + options?.onClose?.(); + }); const image = await fs.promises.readFile(libPath('tools', 'dashboard', 'appIcon.png')); // This is local Playwright, so I can access private methods. @@ -272,6 +285,8 @@ async function acquireSingleton(options: DashboardOptions, onConnection: (socket export async function openDashboardApp() { const options = parseOpenArgs(); + startupTrace('dashboard.process.start', { options }); + process.on('exit', exitCode => startupTrace('dashboard.process.exit', { exitCode })); if (options.kill) { await runKillClient(); return; @@ -290,7 +305,9 @@ export async function openDashboardApp() { const stopSelfDestruct = selfDestructOnParentGone(); const statePromise = new ManualPromise(); + startupTrace('dashboard.singleton-acquire.start'); const acquired = await acquireSingleton(options, socket => handleConnection(socket, statePromise)); + startupTrace('dashboard.singleton-acquire.end', { role: acquired.role, daemonPid: acquired.role === 'loser' ? acquired.daemonPid : process.pid }); if (acquired.role === 'loser') { // Another daemon is already running, signal success. stopSelfDestruct(); @@ -311,7 +328,9 @@ export async function openDashboardApp() { } else { // Windowed daemon launches a browser window and detaches from the parent CLI. const { page } = await launchApp('dashboard', { onClose: () => gracefullyProcessExitDoNotHang(0) }); + startupTrace('dashboard.page-goto.start', { url: dashboard.url }); await page.goto(dashboard.url); + startupTrace('dashboard.page-goto.end', { url: dashboard.url }); statePromise.resolve({ page, server: dashboard }); stopSelfDestruct(); // eslint-disable-next-line no-console @@ -343,6 +362,7 @@ function handleConnection(socket: net.Socket, statePromise: Promise) { socket.end(); return; } + startupTrace('dashboard.singleton-request', { options: parsed }); const { page, server: dashboard } = await statePromise; if (parsed.annotate) { const cancellation = new AbortController(); @@ -357,11 +377,13 @@ function handleConnection(socket: net.Socket, statePromise: Promise) { socket.end(e); } } else if (parsed.kill) { + startupTrace('dashboard.singleton-kill.start'); await dashboard.close().catch(() => {}); gracefullyProcessExitDoNotHang(0, () => new Promise(r => socket.end(r))); } else { void page?.bringToFront().catch(() => {}); dashboard.reveal(parsed); + startupTrace('dashboard.singleton-ack', { daemonPid: process.pid }); socket.end(JSON.stringify({ pid: process.pid }) + '\n'); } }); diff --git a/packages/utils/startupTrace.ts b/packages/utils/startupTrace.ts new file mode 100644 index 0000000000000..3726e3534c9df --- /dev/null +++ b/packages/utils/startupTrace.ts @@ -0,0 +1,32 @@ +/** + * Copyright (c) Microsoft Corporation. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +import fs from 'fs'; + +export function startupTrace(phase: string, data: Record = {}): void { + const traceFile = process.env.PWTEST_MCP_STARTUP_TRACE; + if (!traceFile) + return; + const entry = { + timestamp: new Date().toISOString(), + monotonicTime: Number(process.hrtime.bigint() / 1_000_000n), + pid: process.pid, + ppid: process.ppid, + phase, + ...data, + }; + fs.appendFileSync(traceFile, JSON.stringify(entry) + '\n'); +} diff --git a/tests/mcp/cli-fixtures.ts b/tests/mcp/cli-fixtures.ts index 408018e6338de..380a3f127b800 100644 --- a/tests/mcp/cli-fixtures.ts +++ b/tests/mcp/cli-fixtures.ts @@ -68,9 +68,20 @@ export const test = baseTest.extend<{ await cli('show', '--kill'); }, - cli: async ({ mcpBrowser, mcpHeadless, childProcess }, use) => { - await fs.promises.mkdir(test.info().outputPath('.playwright'), { recursive: true }); - const allPids: number[] = []; + cli: async ({ mcpBrowser, mcpHeadless, childProcess }, use, testInfo) => { + await fs.promises.mkdir(testInfo.outputPath('.playwright'), { recursive: true }); + const tracePath = startupTracePath(); + appendStartupTrace(tracePath, 'fixture.start', { title: testInfo.title }); + const allPids = new Set(); + const emergencyTeardown = () => { + collectTracedPids(tracePath, allPids); + allPids.delete(process.pid); + appendStartupTrace(tracePath, 'fixture.emergency-teardown.before-kill', { processes: processStates(allPids) }); + for (const pid of allPids) + killProcessGroup(pid); + appendStartupTrace(tracePath, 'fixture.emergency-teardown.after-kill', { processes: processStates(allPids) }); + }; + process.once('exit', emergencyTeardown); await use(async (...args: string[]) => { const cliArgs = args.filter(arg => typeof arg === 'string'); @@ -80,22 +91,30 @@ export const test = baseTest.extend<{ () => runCli(childProcess, cliArgs, cliOptions, { mcpBrowser, mcpHeadless }) ); if (result.daemonPid) - allPids.push(result.daemonPid); + allPids.add(result.daemonPid); if (result.dashboardPid) - allPids.push(result.dashboardPid); + allPids.add(result.dashboardPid); return result; }); + collectTracedPids(tracePath, allPids); + allPids.delete(process.pid); + appendStartupTrace(tracePath, 'fixture.teardown.before-kill', { processes: processStates(allPids) }); for (const pid of allPids) killProcessGroup(pid); + for (let i = 0; i < 20 && processStates(allPids).some(state => state.alive); ++i) + await new Promise(resolve => setTimeout(resolve, 50)); + appendStartupTrace(tracePath, 'fixture.teardown.after-kill', { processes: processStates(allPids) }); - const daemonDir = test.info().outputPath('daemon'); + const daemonDir = testInfo.outputPath('daemon'); for (const dir of await fs.promises.readdir(daemonDir).catch(() => [])) { if (dir.startsWith('ud-')) { await fs.promises.rm(path.join(daemonDir, dir), { recursive: true, force: true }).catch(() => {}); continue; } } + await testInfo.attach('mcp-startup-timeline', { path: tracePath, contentType: 'application/jsonl' }); + process.off('exit', emergencyTeardown); }, boundBrowser: async ({ mcpBrowser, playwright }, use) => { const browserName = (mcpBrowser === 'chrome' || mcpBrowser === 'msedge') ? 'chromium' : mcpBrowser; @@ -127,9 +146,61 @@ function cliEnv() { PWTEST_DAEMON_SESSION_DIR: test.info().outputPath('daemon'), PWTEST_SOCKETS_DIR: path.join(os.tmpdir(), 'ds-' + crypto.createHash('sha1').update(test.info().outputDir).digest('hex').slice(0, 16)), PWTEST_CLI_CHANNEL_SCAN_DISABLED_FOR_TEST: '1', + PWTEST_MCP_STARTUP_TRACE: startupTracePath(), }; } +function startupTracePath(): string { + const testInfo = test.info(); + const traceDir = path.join(testInfo.project.outputDir, 'mcp-startup-timelines'); + fs.mkdirSync(traceDir, { recursive: true }); + const traceId = crypto.createHash('sha1').update(`${testInfo.testId}-${testInfo.retry}`).digest('hex'); + return path.join(traceDir, `${traceId}.jsonl`); +} + +function appendStartupTrace(tracePath: string, phase: string, data: Record = {}) { + fs.appendFileSync(tracePath, JSON.stringify({ + timestamp: new Date().toISOString(), + monotonicTime: Number(process.hrtime.bigint() / 1_000_000n), + pid: process.pid, + ppid: process.ppid, + phase, + ...data, + }) + '\n'); +} + +function collectTracedPids(tracePath: string, pids: Set): void { + const text = fs.readFileSync(tracePath, 'utf-8'); + for (const line of text.split('\n')) { + if (!line) + continue; + let event: Record; + try { + event = JSON.parse(line); + } catch (error) { + appendStartupTrace(tracePath, 'fixture.trace-parse-error', { error: String(error), line }); + continue; + } + for (const key of ['pid', 'childPid', 'browserPid', 'daemonPid', 'dashboardPid']) { + if (typeof event[key] === 'number') + pids.add(event[key]); + } + } +} + +function processStates(pids: Iterable): { pid: number, alive: boolean }[] { + return [...pids].map(pid => ({ pid, alive: isAlive(pid) })); +} + +function isAlive(pid: number): boolean { + try { + process.kill(pid, 0); + return true; + } catch { + return false; + } +} + async function runCli(childProcess: CommonFixtures['childProcess'], args: string[], cliOptions: { cwd?: string, env?: Record, bindTitle?: string }, options: { mcpBrowser: string, mcpHeadless: boolean }) { const testInfo = test.info(); const cli = childProcess({ From abc39aa9b65cd3a83c5f39805e20536edd806ffa Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Thu, 23 Jul 2026 16:24:52 +0200 Subject: [PATCH 2/5] test(mcp): refine startup stall tracing Split Chromium connection and navigation startup into individual diagnostic phases so the next sampled CI run can identify the exact stalled operation. Limit matrix concurrency to reduce hosted-runner fleet pressure. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: b62093c2-7f1f-46d8-9f9a-be7e30a965ab --- .github/workflows/tests_mcp.yml | 2 + .../src/server/chromium/crBrowser.ts | 47 +++++++++-- packages/playwright-core/src/server/frames.ts | 84 +++++++++++-------- .../playwright-core/src/tools/backend/tab.ts | 14 +++- .../src/tools/dashboard/dashboardApp.ts | 27 +++++- 5 files changed, 129 insertions(+), 45 deletions(-) diff --git a/.github/workflows/tests_mcp.yml b/.github/workflows/tests_mcp.yml index 0dd483bc982f1..6ac7dbbfc90c6 100644 --- a/.github/workflows/tests_mcp.yml +++ b/.github/workflows/tests_mcp.yml @@ -35,6 +35,8 @@ jobs: environment: ${{ github.event_name == 'push' && 'allow-uploading-flakiness-results' || null }} strategy: fail-fast: false + # Avoid losing an entire platform batch if the hosted runner fleet is under pressure. + max-parallel: 5 matrix: # Temporary startup-stall diagnostic: 10 fresh runners for each affected configuration. os: [ubuntu-latest, windows-latest] diff --git a/packages/playwright-core/src/server/chromium/crBrowser.ts b/packages/playwright-core/src/server/chromium/crBrowser.ts index ba563a4b56118..02235ac371497 100644 --- a/packages/playwright-core/src/server/chromium/crBrowser.ts +++ b/packages/playwright-core/src/server/chromium/crBrowser.ts @@ -19,6 +19,7 @@ import path from 'path'; import { assert } from '@isomorphic/assert'; import { createGuid } from '@utils/crypto'; +import { startupTrace } from '@utils/startupTrace'; import { Artifact } from '../artifact'; import { Browser } from '../browser'; import { BrowserContext, verifyGeolocation } from '../browserContext'; @@ -57,6 +58,12 @@ export class CRBrowser extends Browser { private _userAgent: string = ''; static async connect(parent: SdkObject, transport: ConnectionTransport, options: BrowserOptions, devtools?: CRDevTools): Promise { + const traceData = { browserPid: options.browserProcess.process?.pid, persistent: !!options.persistent }; + const traceConnectError = (error: unknown): never => { + startupTrace('chromium.connect.error', { ...traceData, error: String(error) }); + throw error; + }; + startupTrace('chromium.connect.start', traceData); // Make a copy in case we need to update `headful` property below. options = { ...options }; const connection = new CRConnection(parent, transport, options.protocolLogger, options.browserLogsCollector); @@ -65,10 +72,17 @@ export class CRBrowser extends Browser { if (browser.isClank()) browser._isBrowserCollocatedWithServer = false; const session = connection.rootSession; - if ((options as any).__testHookOnConnectToBrowser) - await (options as any).__testHookOnConnectToBrowser(); + if ((options as any).__testHookOnConnectToBrowser) { + try { + await (options as any).__testHookOnConnectToBrowser(); + } catch (error) { + traceConnectError(error); + } + } - const version = await session.send('Browser.getVersion'); + startupTrace('chromium.browser-get-version.start', traceData); + const version = await session.send('Browser.getVersion').catch(traceConnectError); + startupTrace('chromium.browser-get-version.end', traceData); browser._revision = version.revision; browser._version = version.product.substring(version.product.indexOf('/') + 1); try { @@ -80,20 +94,35 @@ export class CRBrowser extends Browser { // may have been launched with different options. browser.options.headful = !version.userAgent.includes('Headless'); if (!options.persistent) { - await session.send('Target.setAutoAttach', { autoAttach: true, waitForDebuggerOnStart: true, flatten: true }); + startupTrace('chromium.target-set-auto-attach.start', traceData); + await session.send('Target.setAutoAttach', { autoAttach: true, waitForDebuggerOnStart: true, flatten: true }).catch(traceConnectError); + startupTrace('chromium.target-set-auto-attach.end', traceData); + startupTrace('chromium.connect.end', traceData); return browser; } browser._defaultContext = new CRBrowserContext(browser, undefined, options.persistent); await Promise.all([ - session.send('Target.setAutoAttach', { autoAttach: true, waitForDebuggerOnStart: true, flatten: true }).then(async () => { + (async () => { + startupTrace('chromium.target-set-auto-attach.start', traceData); + await session.send('Target.setAutoAttach', { autoAttach: true, waitForDebuggerOnStart: true, flatten: true }); + startupTrace('chromium.target-set-auto-attach.end', traceData); // Target.setAutoAttach has a bug where it does not wait for new Targets being attached. // However making a dummy call afterwards fixes this. // This can be removed after https://chromium-review.googlesource.com/c/chromium/src/+/2885888 lands in stable. + startupTrace('chromium.target-get-target-info.start', traceData); await session.send('Target.getTargetInfo'); - }), - browser._defaultContext.initialize(), - ]); - await browser._waitForAllPagesToBeInitialized(); + startupTrace('chromium.target-get-target-info.end', traceData); + })(), + (async () => { + startupTrace('chromium.default-context-initialize.start', traceData); + await browser._defaultContext!.initialize(); + startupTrace('chromium.default-context-initialize.end', traceData); + })(), + ]).catch(traceConnectError); + startupTrace('chromium.wait-for-pages.start', traceData); + await browser._waitForAllPagesToBeInitialized().catch(traceConnectError); + startupTrace('chromium.wait-for-pages.end', traceData); + startupTrace('chromium.connect.end', traceData); return browser; } diff --git a/packages/playwright-core/src/server/frames.ts b/packages/playwright-core/src/server/frames.ts index 170843cfe6839..08f666ba3d0d8 100644 --- a/packages/playwright-core/src/server/frames.ts +++ b/packages/playwright-core/src/server/frames.ts @@ -26,6 +26,7 @@ import { assert } from '@isomorphic/assert'; import { constructURLBasedOnBaseURL } from '@isomorphic/urlMatch'; import { makeWaitForNextTask } from '@utils/task'; import { createGuid } from '@utils/crypto'; +import { startupTrace } from '@utils/startupTrace'; import { BrowserContext } from './browserContext'; import * as dom from './dom'; import { TimeoutError, isTargetClosedError } from './errors'; @@ -703,52 +704,69 @@ export class Frame extends SdkObject { referer = options.referer; } url = helper.completeUserURL(url); + const traceData = { url, waitUntil, frameId: this._id }; + startupTrace('navigation.goto.start', traceData); const navigationEvents: NavigationEvent[] = []; const collectNavigations = (arg: NavigationEvent) => navigationEvents.push(arg); this.on(Frame.Events.InternalNavigation, collectNavigations); let navigateResult; try { + startupTrace('navigation.command.start', traceData); navigateResult = await progress.race(this._page.delegate.navigateFrame(this, url, referer)); + startupTrace('navigation.command.end', { ...traceData, newDocumentId: navigateResult.newDocumentId }); + } catch (error) { + startupTrace('navigation.command.error', { ...traceData, error: String(error) }); + throw error; } finally { this.off(Frame.Events.InternalNavigation, collectNavigations); } - let event: NavigationEvent; - if (navigateResult.newDocumentId) { - const predicate = (event: NavigationEvent) => { - // We are interested either in this specific document, or any other document that - // did commit and replaced the expected document. - return event.newDocument && (event.newDocument.documentId === navigateResult.newDocumentId || !event.error); - }; - const events = navigationEvents.filter(predicate); - if (events.length) - event = events[0]; - else - event = await helper.waitForEvent(progress, this, Frame.Events.InternalNavigation, predicate).promise; - if (event.newDocument!.documentId !== navigateResult.newDocumentId) { - // This is just a sanity check. In practice, new navigation should - // cancel the previous one and report "request cancelled"-like error. - throw new NavigationAbortedError(navigateResult.newDocumentId, `Navigation to "${url}" is interrupted by another navigation to "${event.url}"`); + try { + let event: NavigationEvent; + if (navigateResult.newDocumentId) { + const predicate = (event: NavigationEvent) => { + // We are interested either in this specific document, or any other document that + // did commit and replaced the expected document. + return event.newDocument && (event.newDocument.documentId === navigateResult.newDocumentId || !event.error); + }; + const events = navigationEvents.filter(predicate); + if (events.length) + event = events[0]; + else + event = await helper.waitForEvent(progress, this, Frame.Events.InternalNavigation, predicate).promise; + if (event.newDocument!.documentId !== navigateResult.newDocumentId) { + // This is just a sanity check. In practice, new navigation should + // cancel the previous one and report "request cancelled"-like error. + throw new NavigationAbortedError(navigateResult.newDocumentId, `Navigation to "${url}" is interrupted by another navigation to "${event.url}"`); + } + if (event.error) + throw event.error; + } else { + // Wait for same document navigation. + const predicate = (e: NavigationEvent) => !e.newDocument; + const events = navigationEvents.filter(predicate); + if (events.length) + event = events[0]; + else + event = await helper.waitForEvent(progress, this, Frame.Events.InternalNavigation, predicate).promise; } - if (event.error) - throw event.error; - } else { - // Wait for same document navigation. - const predicate = (e: NavigationEvent) => !e.newDocument; - const events = navigationEvents.filter(predicate); - if (events.length) - event = events[0]; - else - event = await helper.waitForEvent(progress, this, Frame.Events.InternalNavigation, predicate).promise; - } - - if (!this._firedLifecycleEvents.has(waitUntil)) - await helper.waitForEvent(progress, this, Frame.Events.AddLifecycle, (e: types.LifecycleEvent) => e === waitUntil).promise; + startupTrace('navigation.commit', { ...traceData, committedUrl: event.url }); - const request = event.newDocument ? event.newDocument.request : undefined; - const response = request ? await request._finalRequest().response(progress) : null; - return response; + if (!this._firedLifecycleEvents.has(waitUntil)) { + startupTrace('navigation.lifecycle-wait.start', traceData); + await helper.waitForEvent(progress, this, Frame.Events.AddLifecycle, (e: types.LifecycleEvent) => e === waitUntil).promise; + } + startupTrace('navigation.lifecycle-ready', traceData); + + const request = event.newDocument ? event.newDocument.request : undefined; + const response = request ? await request._finalRequest().response(progress) : null; + startupTrace('navigation.goto.end', traceData); + return response; + } catch (error) { + startupTrace('navigation.goto.error', { ...traceData, error: String(error) }); + throw error; + } } async waitForNavigation(progress: Progress, requiresNewDocument: boolean, options: types.NavigateOptions): Promise { diff --git a/packages/playwright-core/src/tools/backend/tab.ts b/packages/playwright-core/src/tools/backend/tab.ts index d696b157ca18a..39147382c0ad5 100644 --- a/packages/playwright-core/src/tools/backend/tab.ts +++ b/packages/playwright-core/src/tools/backend/tab.ts @@ -21,6 +21,7 @@ import { locatorOrSelectorAsSelector } from '@isomorphic/locatorParser'; import { ManualPromise } from '@isomorphic/manualPromise'; import { eventsHelper } from '@utils/eventsHelper'; import { disposeAll } from '@isomorphic/disposable'; +import { startupTrace } from '@utils/startupTrace'; import { waitForCompletion, eventWaiter } from './utils'; import { LogFile } from './logFile'; import { ModalState } from './tool'; @@ -334,14 +335,18 @@ export class Tab extends EventEmitter { const { promise: downloadEvent, abort: abortDownloadEvent } = eventWaiter(this.page, 'download', 3000); try { + startupTrace('target-navigation.goto.start', { url }); await this.page.goto(url, { waitUntil: 'domcontentloaded', ...this.navigationTimeoutOptions }); + startupTrace('target-navigation.goto.end', { url }); abortDownloadEvent(); } catch (_e: unknown) { const e = _e as Error; if (!e.message.includes('Download is starting')) { + startupTrace('target-navigation.goto.error', { url, error: String(e) }); abortDownloadEvent(); throw e; } + startupTrace('target-navigation.goto.download', { url }); const download = await downloadEvent; if (!download) throw e; @@ -351,7 +356,14 @@ export class Tab extends EventEmitter { } // Cap load event to 5 seconds, the page is operational at this point. - await this.waitForLoadState('load', { timeout: 5000 }); + startupTrace('target-navigation.load-wait.start', { url }); + try { + await this.waitForLoadState('load', { timeout: 5000 }); + } catch (error) { + startupTrace('target-navigation.load-wait.error', { url, error: String(error) }); + throw error; + } + startupTrace('target-navigation.load-wait.end', { url }); } async consoleMessageCount(): Promise<{ total: number, errors: number, warnings: number }> { diff --git a/packages/playwright-core/src/tools/dashboard/dashboardApp.ts b/packages/playwright-core/src/tools/dashboard/dashboardApp.ts index 503c896e68561..3abf4e13f7dbb 100644 --- a/packages/playwright-core/src/tools/dashboard/dashboardApp.ts +++ b/packages/playwright-core/src/tools/dashboard/dashboardApp.ts @@ -71,10 +71,12 @@ async function startDashboardServer(provider: SessionProvider, options: Dashboar }); const wsGuid = httpServer.wsGuid()!; - httpServer.routePath('/', (_, response) => { + httpServer.routePath('/', (request, response) => { + startupTrace('dashboard.http-root.request', { url: request.url }); response.statusCode = 302; response.setHeader('Location', `/index.html?ws=${wsGuid}`); response.end(); + startupTrace('dashboard.http-root.response', { url: request.url }); return true; }); @@ -166,6 +168,22 @@ async function launchApp(appName: string, options?: { onClose?: () => void }) { } const [page] = context.pages(); + if (process.env.PWTEST_MCP_STARTUP_TRACE) { + page.on('request', request => { + if (request.resourceType() === 'document') + startupTrace('dashboard.browser-request', { url: request.url() }); + }); + page.on('response', response => { + if (response.request().resourceType() === 'document') + startupTrace('dashboard.browser-response', { url: response.url(), status: response.status() }); + }); + page.on('requestfailed', request => { + if (request.resourceType() === 'document') + startupTrace('dashboard.browser-request-failed', { url: request.url(), error: request.failure()?.errorText }); + }); + page.on('domcontentloaded', () => startupTrace('dashboard.browser-domcontentloaded', { url: page.url() })); + page.on('load', () => startupTrace('dashboard.browser-load', { url: page.url() })); + } // Chromium on macOS opens a new tab when clicking on the dock icon. // See https://github.com/microsoft/playwright/issues/9434 if (process.platform === 'darwin') { @@ -329,7 +347,12 @@ export async function openDashboardApp() { // Windowed daemon launches a browser window and detaches from the parent CLI. const { page } = await launchApp('dashboard', { onClose: () => gracefullyProcessExitDoNotHang(0) }); startupTrace('dashboard.page-goto.start', { url: dashboard.url }); - await page.goto(dashboard.url); + try { + await page.goto(dashboard.url); + } catch (error) { + startupTrace('dashboard.page-goto.error', { url: dashboard.url, error: String(error) }); + throw error; + } startupTrace('dashboard.page-goto.end', { url: dashboard.url }); statePromise.resolve({ page, server: dashboard }); stopSelfDestruct(); From 5cbf5ddb23e355b7d7b0df337ec79f0b78d9968f Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Thu, 23 Jul 2026 18:00:59 +0200 Subject: [PATCH 3/5] test(mcp): retain Ubuntu runner diagnostics Stop traced Ubuntu jobs before the hosted VM loses communication, and retain resource telemetry alongside the partial startup timelines. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: b62093c2-7f1f-46d8-9f9a-be7e30a965ab --- .github/scripts/run-mcp-startup-diagnostic.sh | 51 +++++++++++++++++++ .github/workflows/tests_mcp.yml | 11 +++- 2 files changed, 60 insertions(+), 2 deletions(-) create mode 100644 .github/scripts/run-mcp-startup-diagnostic.sh diff --git a/.github/scripts/run-mcp-startup-diagnostic.sh b/.github/scripts/run-mcp-startup-diagnostic.sh new file mode 100644 index 0000000000000..9f1041faf428a --- /dev/null +++ b/.github/scripts/run-mcp-startup-diagnostic.sh @@ -0,0 +1,51 @@ +#!/usr/bin/env bash + +set -euo pipefail + +project="$1" + +if [[ "$(uname)" != "Linux" ]]; then + exec npm run test-mcp -- --project="$project" --workers=1 +fi + +health_dir="mcp-runner-health" +health_file="$health_dir/runner-health.tsv" +mkdir -p "$health_dir" + +monitor_health() { + printf 'timestamp\tload1\tmem_available_kb\tswap_free_kb\tdisk_available_kb\tprocesses\tnode_rss_kb\tchromium_rss_kb\txvfb_rss_kb\n' + while true; do + local timestamp load1 mem_available swap_free disk_available processes node_rss chromium_rss xvfb_rss + timestamp="$(date -u +%Y-%m-%dT%H:%M:%SZ)" + load1="$(awk '{ print $1 }' /proc/loadavg)" + mem_available="$(awk '/^MemAvailable:/ { print $2 }' /proc/meminfo)" + swap_free="$(awk '/^SwapFree:/ { print $2 }' /proc/meminfo)" + disk_available="$(df -Pk . | awk 'NR == 2 { print $4 }')" + processes="$(ps -e --no-headers | wc -l)" + node_rss="$(ps -eo rss=,comm= | awk '$2 == "node" { sum += $1 } END { print sum + 0 }')" + chromium_rss="$(ps -eo rss=,comm= | awk '$2 ~ /^(chrome|chromium)$/ { sum += $1 } END { print sum + 0 }')" + xvfb_rss="$(ps -eo rss=,comm= | awk '$2 == "Xvfb" { sum += $1 } END { print sum + 0 }')" + printf '%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\n' \ + "$timestamp" "$load1" "$mem_available" "$swap_free" "$disk_available" \ + "$processes" "$node_rss" "$chromium_rss" "$xvfb_rss" + sleep 15 + done +} + +monitor_health > "$health_file" & +monitor_pid=$! +cleanup() { + kill "$monitor_pid" 2>/dev/null || true + wait "$monitor_pid" 2>/dev/null || true +} +trap cleanup EXIT + +set +e +timeout --signal=INT --kill-after=30s 35m npm run test-mcp -- --project="$project" --workers=1 +status=$? +set -e + +if [[ "$status" == "124" ]]; then + echo "::error::Ubuntu MCP diagnostic exceeded 35 minutes; stopping before the hosted runner is lost." +fi +exit "$status" diff --git a/.github/workflows/tests_mcp.yml b/.github/workflows/tests_mcp.yml index 6ac7dbbfc90c6..97329ac44fc10 100644 --- a/.github/workflows/tests_mcp.yml +++ b/.github/workflows/tests_mcp.yml @@ -39,7 +39,7 @@ jobs: max-parallel: 5 matrix: # Temporary startup-stall diagnostic: 10 fresh runners for each affected configuration. - os: [ubuntu-latest, windows-latest] + os: [windows-latest, ubuntu-latest] project: [chrome, msedge] sample: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10] exclude: @@ -55,7 +55,7 @@ jobs: with: node-version: "22" # Keep the full suite and serial execution so setup/order/cleanup effects remain intact. - command: npm run test-mcp -- --project=${{ matrix.project }} --workers=1 + command: bash .github/scripts/run-mcp-startup-diagnostic.sh ${{ matrix.project }} bot-name: "mcp-startup-diagnostic-${{ matrix.os }}-${{ matrix.project }}-sample-${{ matrix.sample }}" flakiness-client-id: ${{ secrets.AZURE_FLAKINESS_DASHBOARD_CLIENT_ID }} flakiness-tenant-id: ${{ secrets.AZURE_FLAKINESS_DASHBOARD_TENANT_ID }} @@ -67,3 +67,10 @@ jobs: name: "mcp-startup-timelines-${{ matrix.os }}-${{ matrix.project }}-sample-${{ matrix.sample }}" path: test-results/mcp-startup-timelines/*.jsonl if-no-files-found: error + - name: Upload Ubuntu runner health + if: always() && matrix.os == 'ubuntu-latest' + uses: actions/upload-artifact@v4 + with: + name: "mcp-runner-health-${{ matrix.os }}-${{ matrix.project }}-sample-${{ matrix.sample }}" + path: mcp-runner-health/runner-health.tsv + if-no-files-found: error From ac3e9f34a7ea0724cd277ecd169cf364e1340911 Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Fri, 24 Jul 2026 08:22:23 +0200 Subject: [PATCH 4/5] test(mcp): avoid killing diagnostic runner Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: b62093c2-7f1f-46d8-9f9a-be7e30a965ab --- tests/mcp/cli-fixtures.ts | 49 ++++++++++++++++++++++++++------------- 1 file changed, 33 insertions(+), 16 deletions(-) diff --git a/tests/mcp/cli-fixtures.ts b/tests/mcp/cli-fixtures.ts index 380a3f127b800..43f943f26b445 100644 --- a/tests/mcp/cli-fixtures.ts +++ b/tests/mcp/cli-fixtures.ts @@ -72,14 +72,21 @@ export const test = baseTest.extend<{ await fs.promises.mkdir(testInfo.outputPath('.playwright'), { recursive: true }); const tracePath = startupTracePath(); appendStartupTrace(tracePath, 'fixture.start', { title: testInfo.title }); - const allPids = new Set(); + const tracedPids = new Set(); + const ownedPids = new Set(); const emergencyTeardown = () => { - collectTracedPids(tracePath, allPids); - allPids.delete(process.pid); - appendStartupTrace(tracePath, 'fixture.emergency-teardown.before-kill', { processes: processStates(allPids) }); - for (const pid of allPids) + collectTracedPids(tracePath, tracedPids, ownedPids); + tracedPids.delete(process.pid); + appendStartupTrace(tracePath, 'fixture.emergency-teardown.before-kill', { + processes: processStates(tracedPids), + ownedProcesses: processStates(ownedPids), + }); + for (const pid of ownedPids) killProcessGroup(pid); - appendStartupTrace(tracePath, 'fixture.emergency-teardown.after-kill', { processes: processStates(allPids) }); + appendStartupTrace(tracePath, 'fixture.emergency-teardown.after-kill', { + processes: processStates(tracedPids), + ownedProcesses: processStates(ownedPids), + }); }; process.once('exit', emergencyTeardown); @@ -91,20 +98,26 @@ export const test = baseTest.extend<{ () => runCli(childProcess, cliArgs, cliOptions, { mcpBrowser, mcpHeadless }) ); if (result.daemonPid) - allPids.add(result.daemonPid); + ownedPids.add(result.daemonPid); if (result.dashboardPid) - allPids.add(result.dashboardPid); + ownedPids.add(result.dashboardPid); return result; }); - collectTracedPids(tracePath, allPids); - allPids.delete(process.pid); - appendStartupTrace(tracePath, 'fixture.teardown.before-kill', { processes: processStates(allPids) }); - for (const pid of allPids) + collectTracedPids(tracePath, tracedPids, ownedPids); + tracedPids.delete(process.pid); + appendStartupTrace(tracePath, 'fixture.teardown.before-kill', { + processes: processStates(tracedPids), + ownedProcesses: processStates(ownedPids), + }); + for (const pid of ownedPids) killProcessGroup(pid); - for (let i = 0; i < 20 && processStates(allPids).some(state => state.alive); ++i) + for (let i = 0; i < 20 && processStates(ownedPids).some(state => state.alive); ++i) await new Promise(resolve => setTimeout(resolve, 50)); - appendStartupTrace(tracePath, 'fixture.teardown.after-kill', { processes: processStates(allPids) }); + appendStartupTrace(tracePath, 'fixture.teardown.after-kill', { + processes: processStates(tracedPids), + ownedProcesses: processStates(ownedPids), + }); const daemonDir = testInfo.outputPath('daemon'); for (const dir of await fs.promises.readdir(daemonDir).catch(() => [])) { @@ -169,7 +182,7 @@ function appendStartupTrace(tracePath: string, phase: string, data: Record): void { +function collectTracedPids(tracePath: string, tracedPids: Set, ownedPids: Set): void { const text = fs.readFileSync(tracePath, 'utf-8'); for (const line of text.split('\n')) { if (!line) @@ -183,7 +196,11 @@ function collectTracedPids(tracePath: string, pids: Set): void { } for (const key of ['pid', 'childPid', 'browserPid', 'daemonPid', 'dashboardPid']) { if (typeof event[key] === 'number') - pids.add(event[key]); + tracedPids.add(event[key]); + } + for (const key of ['daemonPid', 'dashboardPid']) { + if (typeof event[key] === 'number') + ownedPids.add(event[key]); } } } From 69723c9f75e060523f5a2710072ae93727ec588d Mon Sep 17 00:00:00 2001 From: Simon Knott Date: Fri, 24 Jul 2026 13:15:32 +0200 Subject: [PATCH 5/5] test(mcp): capture Chromium startup traces Retain Perfetto traces when startup timeline phases exceed five seconds, and recover partial traces after worker timeouts for CI artifact upload. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: b62093c2-7f1f-46d8-9f9a-be7e30a965ab --- .../scripts/recover-mcp-chromium-traces.mjs | 62 ++++++ .github/scripts/run-mcp-startup-diagnostic.sh | 17 +- .github/workflows/tests_mcp.yml | 9 +- .../src/server/chromium/chromium.ts | 14 ++ tests/mcp/cli-fixtures.ts | 195 +++++++++++++++++- 5 files changed, 284 insertions(+), 13 deletions(-) create mode 100644 .github/scripts/recover-mcp-chromium-traces.mjs diff --git a/.github/scripts/recover-mcp-chromium-traces.mjs b/.github/scripts/recover-mcp-chromium-traces.mjs new file mode 100644 index 0000000000000..e1dadaedd4244 --- /dev/null +++ b/.github/scripts/recover-mcp-chromium-traces.mjs @@ -0,0 +1,62 @@ +#!/usr/bin/env node + +import crypto from 'node:crypto'; +import fs from 'node:fs'; +import path from 'node:path'; + +const traceRoot = path.resolve('test-results/mcp-chromium-traces'); +const retryDeadline = Date.now() + 10_000; + +async function recoverTrace(source) { + const target = path.join(path.dirname(source), `recovered-${crypto.randomUUID()}.pftrace`); + while (true) { + let size; + try { + size = (await fs.promises.stat(source)).size; + } catch (error) { + if (error.code === 'ENOENT') + return; + throw error; + } + + if (size) { + try { + await fs.promises.rename(source, target); + console.log(`Recovered Chromium startup trace: ${target}`); + return; + } catch (error) { + if (error.code === 'ENOENT') + return; + if (error.code !== 'EACCES' && error.code !== 'EPERM') + throw error; + } + } + + if (Date.now() >= retryDeadline) { + console.warn(`Chromium startup trace has no recoverable data: ${source}`); + return; + } + await new Promise(resolve => setTimeout(resolve, 200)); + } +} + +let traceDirectories; +try { + traceDirectories = await fs.promises.readdir(traceRoot, { withFileTypes: true }); +} catch (error) { + if (error.code === 'ENOENT') + process.exit(0); + throw error; +} + +const pending = []; +for (const directory of traceDirectories) { + if (!directory.isDirectory()) + continue; + const traceDirectory = path.join(traceRoot, directory.name); + for (const file of await fs.promises.readdir(traceDirectory)) { + if (!file.endsWith('.pftrace')) + pending.push(recoverTrace(path.join(traceDirectory, file))); + } +} +await Promise.all(pending); diff --git a/.github/scripts/run-mcp-startup-diagnostic.sh b/.github/scripts/run-mcp-startup-diagnostic.sh index 9f1041faf428a..f03269c0a2eac 100644 --- a/.github/scripts/run-mcp-startup-diagnostic.sh +++ b/.github/scripts/run-mcp-startup-diagnostic.sh @@ -4,8 +4,21 @@ set -euo pipefail project="$1" +run_tests() { + set +e + "$@" + local test_status=$? + node .github/scripts/recover-mcp-chromium-traces.mjs + local recovery_status=$? + if [[ "$test_status" != "0" ]]; then + return "$test_status" + fi + return "$recovery_status" +} + if [[ "$(uname)" != "Linux" ]]; then - exec npm run test-mcp -- --project="$project" --workers=1 + run_tests npm run test-mcp -- --project="$project" --workers=1 --timeout=60000 + exit $? fi health_dir="mcp-runner-health" @@ -41,7 +54,7 @@ cleanup() { trap cleanup EXIT set +e -timeout --signal=INT --kill-after=30s 35m npm run test-mcp -- --project="$project" --workers=1 +run_tests timeout --signal=INT --kill-after=30s 35m npm run test-mcp -- --project="$project" --workers=1 --timeout=60000 status=$? set -e diff --git a/.github/workflows/tests_mcp.yml b/.github/workflows/tests_mcp.yml index 97329ac44fc10..ae6ac79a78624 100644 --- a/.github/workflows/tests_mcp.yml +++ b/.github/workflows/tests_mcp.yml @@ -38,7 +38,7 @@ jobs: # Avoid losing an entire platform batch if the hosted runner fleet is under pressure. max-parallel: 5 matrix: - # Temporary startup-stall diagnostic: 10 fresh runners for each affected configuration. + # Temporary Perfetto follow-up: ten fresh runners for each affected configuration. os: [windows-latest, ubuntu-latest] project: [chrome, msedge] sample: [1, 2, 3, 4, 5, 6, 7, 8, 9, 10] @@ -67,6 +67,13 @@ jobs: name: "mcp-startup-timelines-${{ matrix.os }}-${{ matrix.project }}-sample-${{ matrix.sample }}" path: test-results/mcp-startup-timelines/*.jsonl if-no-files-found: error + - name: Upload retained Chromium startup traces + if: always() + uses: actions/upload-artifact@v4 + with: + name: "mcp-chromium-traces-${{ matrix.os }}-${{ matrix.project }}-sample-${{ matrix.sample }}" + path: test-results/mcp-chromium-traces/**/*.pftrace + if-no-files-found: warn - name: Upload Ubuntu runner health if: always() && matrix.os == 'ubuntu-latest' uses: actions/upload-artifact@v4 diff --git a/packages/playwright-core/src/server/chromium/chromium.ts b/packages/playwright-core/src/server/chromium/chromium.ts index 68d0a9096e21b..1c4d0a9c85a83 100644 --- a/packages/playwright-core/src/server/chromium/chromium.ts +++ b/packages/playwright-core/src/server/chromium/chromium.ts @@ -26,6 +26,7 @@ import { RecentLogsCollector } from '@utils/debugLogger'; import { removeFolders } from '@utils/fileUtils'; import { gracefullyCloseSet } from '@utils/processLauncher'; import { debugMode } from '@utils/debug'; +import { startupTrace } from '@utils/startupTrace'; import { headersArrayToObject, headersObjectToArray } from '@isomorphic/headers'; import { fetchData } from '../utils'; import { getUserAgent } from '../userAgent'; @@ -56,6 +57,7 @@ import type http from 'http'; import type stream from 'stream'; const ARTIFACTS_FOLDER = path.join(os.tmpdir(), 'playwright-artifacts-'); +let startupTraceOrdinal = 0; export class Chromium extends BrowserType { private _devtools: CRDevTools | undefined; @@ -372,6 +374,18 @@ export class Chromium extends BrowserType { if (args.find(arg => !arg.startsWith('-'))) throw new Error('Arguments can not specify page to be opened'); const chromeArguments = [...chromiumSwitches()]; + const startupTraceDir = process.env.PWTEST_MCP_CHROMIUM_TRACE_DIR; + if (startupTraceDir) { + fs.mkdirSync(startupTraceDir, { recursive: true }); + const tracePath = path.join(startupTraceDir, `${process.pid}-${++startupTraceOrdinal}.pftrace`); + chromeArguments.push( + '--trace-startup=*', + `--trace-startup-file=${tracePath}`, + '--trace-startup-duration=35', + '--trace-startup-format=proto', + ); + startupTrace('chromium.perfetto-trace.configured', { tracePath }); + } // See https://issues.chromium.org/issues/40277080 chromeArguments.push('--enable-unsafe-swiftshader'); diff --git a/tests/mcp/cli-fixtures.ts b/tests/mcp/cli-fixtures.ts index 43f943f26b445..d1bd42bf3257e 100644 --- a/tests/mcp/cli-fixtures.ts +++ b/tests/mcp/cli-fixtures.ts @@ -65,16 +65,22 @@ export const test = baseTest.extend<{ }).toPass(); return await playwright.chromium.connect(endpoint); }); + const slowBrowserGaps = findSlowBrowserGaps(startupTracePath()); + if (slowBrowserGaps.length) + await waitForChromiumStartupTrace(slowBrowserGaps); await cli('show', '--kill'); }, cli: async ({ mcpBrowser, mcpHeadless, childProcess }, use, testInfo) => { await fs.promises.mkdir(testInfo.outputPath('.playwright'), { recursive: true }); const tracePath = startupTracePath(); + const chromiumTraceDir = chromiumStartupTraceDir(); appendStartupTrace(tracePath, 'fixture.start', { title: testInfo.title }); const tracedPids = new Set(); const ownedPids = new Set(); const emergencyTeardown = () => { + const slowBrowserGaps = findSlowBrowserGaps(tracePath); + appendStartupTrace(tracePath, 'fixture.emergency-chromium-trace-retention', { slowBrowserGaps }); collectTracedPids(tracePath, tracedPids, ownedPids); tracedPids.delete(process.pid); appendStartupTrace(tracePath, 'fixture.emergency-teardown.before-kill', { @@ -87,6 +93,8 @@ export const test = baseTest.extend<{ processes: processStates(tracedPids), ownedProcesses: processStates(ownedPids), }); + if (slowBrowserGaps.length) + appendStartupTrace(tracePath, 'fixture.emergency-chromium-trace-recovery', recoverChromiumStartupTracesSync(chromiumTraceDir)); }; process.once('exit', emergencyTeardown); @@ -104,6 +112,11 @@ export const test = baseTest.extend<{ return result; }); + const slowBrowserGaps = findSlowBrowserGaps(tracePath); + appendStartupTrace(tracePath, 'fixture.chromium-trace-retention', { slowBrowserGaps }); + if (slowBrowserGaps.length) + await waitForChromiumStartupTrace(slowBrowserGaps); + collectTracedPids(tracePath, tracedPids, ownedPids); tracedPids.delete(process.pid); appendStartupTrace(tracePath, 'fixture.teardown.before-kill', { @@ -126,6 +139,15 @@ export const test = baseTest.extend<{ continue; } } + const chromiumTraceFiles = await recoverChromiumStartupTraces(chromiumTraceDir); + if (slowBrowserGaps.length) { + if (!chromiumTraceFiles.length) + appendStartupTrace(tracePath, 'fixture.chromium-trace-missing'); + for (const file of chromiumTraceFiles) + await testInfo.attach(`chromium-startup-${file}`, { path: path.join(chromiumTraceDir, file), contentType: 'application/octet-stream' }); + } else { + await fs.promises.rm(chromiumTraceDir, { recursive: true, force: true, maxRetries: 10, retryDelay: 100 }); + } await testInfo.attach('mcp-startup-timeline', { path: tracePath, contentType: 'application/jsonl' }); process.off('exit', emergencyTeardown); }, @@ -160,6 +182,7 @@ function cliEnv() { PWTEST_SOCKETS_DIR: path.join(os.tmpdir(), 'ds-' + crypto.createHash('sha1').update(test.info().outputDir).digest('hex').slice(0, 16)), PWTEST_CLI_CHANNEL_SCAN_DISABLED_FOR_TEST: '1', PWTEST_MCP_STARTUP_TRACE: startupTracePath(), + PWTEST_MCP_CHROMIUM_TRACE_DIR: chromiumStartupTraceDir(), }; } @@ -171,6 +194,12 @@ function startupTracePath(): string { return path.join(traceDir, `${traceId}.jsonl`); } +function chromiumStartupTraceDir(): string { + const testInfo = test.info(); + const traceId = crypto.createHash('sha1').update(`${testInfo.testId}-${testInfo.retry}`).digest('hex'); + return path.join(testInfo.project.outputDir, 'mcp-chromium-traces', traceId); +} + function appendStartupTrace(tracePath: string, phase: string, data: Record = {}) { fs.appendFileSync(tracePath, JSON.stringify({ timestamp: new Date().toISOString(), @@ -183,26 +212,172 @@ function appendStartupTrace(tracePath: string, phase: string, data: Record, ownedPids: Set): void { - const text = fs.readFileSync(tracePath, 'utf-8'); - for (const line of text.split('\n')) { + for (const event of readStartupTraceEvents(tracePath)) { + for (const key of ['pid', 'childPid', 'browserPid', 'daemonPid', 'dashboardPid']) { + if (typeof event[key] === 'number') + tracedPids.add(event[key]); + } + for (const key of ['daemonPid', 'dashboardPid']) { + if (typeof event[key] === 'number') + ownedPids.add(event[key]); + } + } +} + +type StartupTraceEvent = { + monotonicTime?: number, + phase?: string, + pid?: number, + tracePath?: string, +}; + +type SlowBrowserGap = { + phase: string, + duration: number, + pid: number, + completed: boolean, + traceConfiguredAt: number, +}; + +const browserPhasePairs = new Map([ + ['browser.launch-process.start', 'browser.process.spawned'], + ['browser.transport-connect.start', 'browser.transport-connect.end'], + ['browser.launch-persistent-context.start', 'browser.launch-persistent-context.end'], + ['chromium.browser-get-version.start', 'chromium.browser-get-version.end'], + ['chromium.target-set-auto-attach.start', 'chromium.target-set-auto-attach.end'], + ['chromium.target-get-target-info.start', 'chromium.target-get-target-info.end'], + ['chromium.wait-for-pages.start', 'chromium.wait-for-pages.end'], + ['navigation.command.start', 'navigation.command.end'], + ['navigation.lifecycle-wait.start', 'navigation.lifecycle-ready'], + ['dashboard.browser.launch-persistent-context.start', 'dashboard.browser.launch-persistent-context.end'], + ['dashboard.page-goto.start', 'dashboard.page-goto.end'], +]); + +function readStartupTraceEvents(tracePath: string): StartupTraceEvent[] { + const events: StartupTraceEvent[] = []; + for (const line of fs.readFileSync(tracePath, 'utf-8').split('\n')) { if (!line) continue; - let event: Record; try { - event = JSON.parse(line); + events.push(JSON.parse(line)); } catch (error) { appendStartupTrace(tracePath, 'fixture.trace-parse-error', { error: String(error), line }); + } + } + return events; +} + +function findSlowBrowserGaps(tracePath: string): SlowBrowserGap[] { + const events = readStartupTraceEvents(tracePath); + const retentionThreshold = Number(process.env.PWTEST_MCP_CHROMIUM_TRACE_THRESHOLD_MS || 5_000); + const configuredAt = new Map(); + const starts = new Map(); + const gaps: SlowBrowserGap[] = []; + for (const event of events) { + if (event.phase === 'chromium.perfetto-trace.configured' && event.pid && event.monotonicTime) + configuredAt.set(event.pid, event.monotonicTime); + const endPhase = event.phase ? browserPhasePairs.get(event.phase) : undefined; + if (endPhase && event.pid) { + const key = `${event.pid}:${endPhase}`; + const pending = starts.get(key) || []; + pending.push(event); + starts.set(key, pending); continue; } - for (const key of ['pid', 'childPid', 'browserPid', 'daemonPid', 'dashboardPid']) { - if (typeof event[key] === 'number') - tracedPids.add(event[key]); + if (!event.phase || !event.pid || !event.monotonicTime) + continue; + const key = `${event.pid}:${event.phase}`; + const start = starts.get(key)?.shift(); + if (!start?.phase || !start.monotonicTime) + continue; + const duration = event.monotonicTime - start.monotonicTime; + const traceConfiguredAt = configuredAt.get(event.pid); + if (duration >= retentionThreshold && traceConfiguredAt !== undefined) + gaps.push({ phase: start.phase, duration, pid: event.pid, completed: true, traceConfiguredAt }); + } + const now = Number(process.hrtime.bigint() / 1_000_000n); + for (const pending of starts.values()) { + for (const start of pending) { + if (!start.phase || !start.pid || !start.monotonicTime) + continue; + const duration = now - start.monotonicTime; + const traceConfiguredAt = configuredAt.get(start.pid); + if (duration >= retentionThreshold && traceConfiguredAt !== undefined) + gaps.push({ phase: start.phase, duration, pid: start.pid, completed: false, traceConfiguredAt }); } - for (const key of ['daemonPid', 'dashboardPid']) { - if (typeof event[key] === 'number') - ownedPids.add(event[key]); + } + return gaps; +} + +async function waitForChromiumStartupTrace(slowBrowserGaps: SlowBrowserGap[]): Promise { + const traceCompletionTime = Math.max(...slowBrowserGaps.map(gap => gap.traceConfiguredAt)) + 37_000; + while (Number(process.hrtime.bigint() / 1_000_000n) < traceCompletionTime) + await new Promise(resolve => setTimeout(resolve, 100)); +} + +async function recoverChromiumStartupTraces(traceDir: string): Promise { + let files: string[]; + try { + files = await fs.promises.readdir(traceDir); + } catch (error) { + if ((error as NodeJS.ErrnoException).code === 'ENOENT') + return []; + throw error; + } + const traces = files.filter(file => file.endsWith('.pftrace')); + for (const file of files) { + if (file.endsWith('.pftrace')) + continue; + const source = path.join(traceDir, file); + let size: number; + try { + size = (await fs.promises.stat(source)).size; + } catch (error) { + if ((error as NodeJS.ErrnoException).code === 'ENOENT') + continue; + throw error; + } + if (!size) + continue; + const target = `recovered-${crypto.randomUUID()}.pftrace`; + try { + await fs.promises.rename(source, path.join(traceDir, target)); + } catch (error) { + if ((error as NodeJS.ErrnoException).code === 'ENOENT') + continue; + throw error; + } + traces.push(target); + } + return traces; +} + +function recoverChromiumStartupTracesSync(traceDir: string): { traces: string[], errors: string[] } { + const traces: string[] = []; + const errors: string[] = []; + let files: string[]; + try { + files = fs.readdirSync(traceDir); + } catch (error) { + return { traces, errors: [String(error)] }; + } + for (const file of files) { + if (file.endsWith('.pftrace')) { + traces.push(file); + continue; + } + const source = path.join(traceDir, file); + try { + if (!fs.statSync(source).size) + continue; + const target = `emergency-recovered-${crypto.randomUUID()}.pftrace`; + fs.renameSync(source, path.join(traceDir, target)); + traces.push(target); + } catch (error) { + errors.push(`${file}: ${String(error)}`); } } + return { traces, errors }; } function processStates(pids: Iterable): { pid: number, alive: boolean }[] {