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 new file mode 100644 index 0000000000000..f03269c0a2eac --- /dev/null +++ b/.github/scripts/run-mcp-startup-diagnostic.sh @@ -0,0 +1,64 @@ +#!/usr/bin/env bash + +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 + run_tests npm run test-mcp -- --project="$project" --workers=1 --timeout=60000 + exit $? +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 +run_tests timeout --signal=INT --kill-after=30s 35m npm run test-mcp -- --project="$project" --workers=1 --timeout=60000 +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/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..ae6ac79a78624 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,20 @@ 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 + # Avoid losing an entire platform batch if the hosted runner fleet is under pressure. + max-parallel: 5 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 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] + exclude: + - os: ubuntu-latest project: msedge runs-on: ${{ matrix.os }} permissions: @@ -58,8 +54,30 @@ 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: 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 }} 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 + - 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 + with: + name: "mcp-runner-health-${{ matrix.os }}-${{ matrix.project }}-sample-${{ matrix.sample }}" + path: mcp-runner-health/runner-health.tsv + 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/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/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/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..3abf4e13f7dbb 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); @@ -69,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; }); @@ -85,6 +89,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 +114,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 +147,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,10 +160,30 @@ 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(); + 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') { @@ -167,7 +195,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 +303,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 +323,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 +346,14 @@ 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) }); - await page.goto(dashboard.url); + startupTrace('dashboard.page-goto.start', { url: 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(); // eslint-disable-next-line no-console @@ -343,6 +385,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 +400,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..d1bd42bf3257e 100644 --- a/tests/mcp/cli-fixtures.ts +++ b/tests/mcp/cli-fixtures.ts @@ -65,12 +65,38 @@ 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) => { - 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(); + 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', { + processes: processStates(tracedPids), + ownedProcesses: processStates(ownedPids), + }); + for (const pid of ownedPids) + killProcessGroup(pid); + appendStartupTrace(tracePath, 'fixture.emergency-teardown.after-kill', { + processes: processStates(tracedPids), + ownedProcesses: processStates(ownedPids), + }); + if (slowBrowserGaps.length) + appendStartupTrace(tracePath, 'fixture.emergency-chromium-trace-recovery', recoverChromiumStartupTracesSync(chromiumTraceDir)); + }; + process.once('exit', emergencyTeardown); await use(async (...args: string[]) => { const cliArgs = args.filter(arg => typeof arg === 'string'); @@ -80,22 +106,50 @@ export const test = baseTest.extend<{ () => runCli(childProcess, cliArgs, cliOptions, { mcpBrowser, mcpHeadless }) ); if (result.daemonPid) - allPids.push(result.daemonPid); + ownedPids.add(result.daemonPid); if (result.dashboardPid) - allPids.push(result.dashboardPid); + ownedPids.add(result.dashboardPid); return result; }); - for (const pid of allPids) + 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', { + processes: processStates(tracedPids), + ownedProcesses: processStates(ownedPids), + }); + for (const pid of ownedPids) killProcessGroup(pid); + 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(tracedPids), + ownedProcesses: processStates(ownedPids), + }); - 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; } } + 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); }, boundBrowser: async ({ mcpBrowser, playwright }, use) => { const browserName = (mcpBrowser === 'chrome' || mcpBrowser === 'msedge') ? 'chromium' : mcpBrowser; @@ -127,9 +181,218 @@ 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(), + PWTEST_MCP_CHROMIUM_TRACE_DIR: chromiumStartupTraceDir(), }; } +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 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(), + monotonicTime: Number(process.hrtime.bigint() / 1_000_000n), + pid: process.pid, + ppid: process.ppid, + phase, + ...data, + }) + '\n'); +} + +function collectTracedPids(tracePath: string, tracedPids: Set, ownedPids: Set): void { + 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; + try { + 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; + } + 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 }); + } + } + 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 }[] { + 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({