From 57a8ce529d66f55d9a54b51b7a1bf3c50e57df54 Mon Sep 17 00:00:00 2001 From: Thomas Kosiewski Date: Thu, 24 Sep 2026 19:46:45 +0000 Subject: [PATCH] =?UTF-8?q?=F0=9F=A4=96=20tests:=20record=20in-page=20perf?= =?UTF-8?q?=20milestones=20for=20workspace=20open=20(#4441)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../e2e/scenarios/perf.workspaceOpen.spec.ts | 14 ++ tests/e2e/utils/pageMilestones.ts | 126 ++++++++++++++++++ tests/e2e/utils/perfProfile.ts | 5 + 3 files changed, 145 insertions(+) create mode 100644 tests/e2e/utils/pageMilestones.ts diff --git a/tests/e2e/scenarios/perf.workspaceOpen.spec.ts b/tests/e2e/scenarios/perf.workspaceOpen.spec.ts index a66a4c5203e..b36fc5d8c4e 100644 --- a/tests/e2e/scenarios/perf.workspaceOpen.spec.ts +++ b/tests/e2e/scenarios/perf.workspaceOpen.spec.ts @@ -1,6 +1,11 @@ import { electronTest as test, electronExpect as expect } from "../electronTest"; import { getXumE2EEnv } from "../env"; import { parseHistoryProfilesFromEnv, seedWorkspaceHistoryProfile } from "../utils/historyFixture"; +import { + readPageMilestones, + startPageMilestones, + type PageMilestones, +} from "../utils/pageMilestones"; import { readReactProfileSnapshot, resetReactProfileSamples, @@ -33,12 +38,18 @@ test.describe("workspace open performance profiling", () => { await resetReactProfileSamples(page); const runLabel = `workspace-open-${profile}`; + let milestones: PageMilestones | undefined; const chromeProfile = await withChromeProfiles(page, { label: runLabel }, async () => { + await startPageMilestones(page); await ui.projects.openFirstWorkspace(); await expect(page.getByTestId("message-window")).toHaveAttribute("data-loaded", "true", { timeout: 20_000, }); + milestones = await readPageMilestones(page); }); + if (!milestones) { + throw new Error("Page milestones were not captured"); + } const reactProfileSnapshot = await readReactProfileSnapshot(page); if (!reactProfileSnapshot) { @@ -51,9 +62,12 @@ test.describe("workspace open performance profiling", () => { chromeProfile, reactProfile: reactProfileSnapshot, historyProfile: historySummary, + milestones, }); expect(chromeProfile.wallTimeMs).toBeGreaterThan(0); + // The assertion above saw data-loaded, so the in-page observer must have too. + expect(milestones.fullyLoadedMs).not.toBeNull(); expect(chromeProfile.cpuProfile).not.toBeNull(); const interestingRenderPaths = [ "chat-pane", diff --git a/tests/e2e/utils/pageMilestones.ts b/tests/e2e/utils/pageMilestones.ts new file mode 100644 index 00000000000..54db9c859d6 --- /dev/null +++ b/tests/e2e/utils/pageMilestones.ts @@ -0,0 +1,126 @@ +import type { Page } from "@playwright/test"; + +/** + * In-page milestone timing for perf scenarios. + * + * Why (#4441): Playwright's `expect(...).toHave*` assertions poll with backoff + * (+100/+250/+500/+1000 ms). Wall time measured when an assertion passes is therefore + * quantized, and it jumps whenever a milestone moves later. After #4293 made `data-loaded` + * wait for the full tail-first reveal, the gap between the real flip and the passing poll + * grew from ~27 ms to ~423 ms, and it read as a regression. These timestamps come from + * the page's own clock at the DOM change instead. + */ +export interface PageMilestones { + /** ms from start until the first transcript row exists ("useful content ready"). */ + firstMessageMs: number | null; + /** ms from start until the message window reports data-loaded="true" ("fully revealed"). */ + fullyLoadedMs: number | null; + /** Longest main-thread task after start, in ms. 0 when no task exceeded the 50 ms long-task floor. */ + longestTaskMs: number; +} + +const STATE_KEY = "__xumPerfMilestones"; +const FIRST_MESSAGE_SELECTOR = '[data-testid="message-window"] [data-testid="chat-message"]'; +const FULLY_LOADED_SELECTOR = '[data-testid="message-window"][data-loaded="true"]'; + +interface MilestoneState extends PageMilestones { + stop: () => void; +} + +/** Start recording milestones. Call immediately before the action being measured. */ +export async function startPageMilestones(page: Page): Promise { + await page.evaluate( + ({ stateKey, firstSelector, loadedSelector }) => { + const host = window as unknown as Record; + if (host[stateKey]) { + throw new Error("Page milestones already started; call readPageMilestones first"); + } + // A milestone that is already true at start would record 0 and silently measure nothing. + if (document.querySelector(loadedSelector)) { + throw new Error("Message window is already loaded; the milestone would be meaningless"); + } + + const t0 = performance.now(); + const state: MilestoneState = { + firstMessageMs: null, + fullyLoadedMs: null, + longestTaskMs: 0, + stop: () => undefined, + }; + + // MutationObserver callbacks run as a microtask after the DOM change, in the same task, + // so the timestamp is not quantized by any polling interval. + const mutationObserver = new MutationObserver(() => { + const elapsed = performance.now() - t0; + if (state.firstMessageMs === null && document.querySelector(firstSelector)) { + state.firstMessageMs = elapsed; + } + if (state.fullyLoadedMs === null && document.querySelector(loadedSelector)) { + state.fullyLoadedMs = elapsed; + } + if (state.firstMessageMs !== null && state.fullyLoadedMs !== null) { + mutationObserver.disconnect(); + } + }); + mutationObserver.observe(document.body, { + subtree: true, + childList: true, + attributes: true, + attributeFilter: ["data-loaded"], + }); + + const recordLongTasks = (entries: PerformanceEntryList) => { + for (const entry of entries) { + state.longestTaskMs = Math.max(state.longestTaskMs, entry.duration); + } + }; + const longTaskObserver = new PerformanceObserver((list) => + recordLongTasks(list.getEntries()) + ); + longTaskObserver.observe({ type: "longtask" }); + + state.stop = () => { + mutationObserver.disconnect(); + // Long-task entries are delivered asynchronously; drain the queue so the last + // task before the read is not missed. + recordLongTasks(longTaskObserver.takeRecords()); + longTaskObserver.disconnect(); + }; + host[stateKey] = state; + }, + { + stateKey: STATE_KEY, + firstSelector: FIRST_MESSAGE_SELECTOR, + loadedSelector: FULLY_LOADED_SELECTOR, + } + ); +} + +/** Stop recording and return the milestones. */ +export async function readPageMilestones(page: Page): Promise { + const milestones = await page.evaluate((stateKey) => { + const host = window as unknown as Record; + const state = host[stateKey]; + if (!state) { + throw new Error("Page milestones were not started"); + } + state.stop(); + delete host[stateKey]; + return { + firstMessageMs: state.firstMessageMs, + fullyLoadedMs: state.fullyLoadedMs, + longestTaskMs: state.longestTaskMs, + }; + }, STATE_KEY); + + if ( + milestones.firstMessageMs !== null && + milestones.fullyLoadedMs !== null && + milestones.firstMessageMs > milestones.fullyLoadedMs + ) { + throw new Error( + `Impossible milestone order: first message at ${milestones.firstMessageMs} ms after full load at ${milestones.fullyLoadedMs} ms` + ); + } + return milestones; +} diff --git a/tests/e2e/utils/perfProfile.ts b/tests/e2e/utils/perfProfile.ts index ec29cb15602..4ea775d1ab3 100644 --- a/tests/e2e/utils/perfProfile.ts +++ b/tests/e2e/utils/perfProfile.ts @@ -2,6 +2,7 @@ import fsPromises from "fs/promises"; import path from "path"; import { type Page, type TestInfo } from "@playwright/test"; import type { CDPSession } from "playwright"; +import type { PageMilestones } from "./pageMilestones"; const PERF_ARTIFACTS_ROOT = path.resolve(__dirname, "..", "..", "..", "artifacts", "perf"); const DEFAULT_TRACE_CATEGORIES = [ @@ -277,6 +278,8 @@ export async function writePerfArtifacts(args: { chromeProfile: ChromeProfileCapture; reactProfile: unknown; historyProfile: unknown; + /** In-page milestone timings, for scenarios that record them (see pageMilestones.ts). */ + milestones?: PageMilestones; }): Promise { const timestamp = new Date().toISOString().replace(/[.:]/g, "-"); const runDirName = `${sanitizeForPath(args.runLabel)}-${timestamp}`; @@ -308,6 +311,8 @@ export async function writePerfArtifacts(args: { retry: args.testInfo.retry, }, historyProfile: args.historyProfile, + // Additive field: schemaVersion stays 1 because existing readers ignore unknown keys. + ...(args.milestones ? { milestones: args.milestones } : {}), chromeProfile: { label: args.chromeProfile.label, startedAt: args.chromeProfile.startedAt,