diff --git a/.planning/phases/02-ui-performance/02-FINDINGS.md b/.planning/phases/02-ui-performance/02-FINDINGS.md index 98b421db..4fea8513 100644 --- a/.planning/phases/02-ui-performance/02-FINDINGS.md +++ b/.planning/phases/02-ui-performance/02-FINDINGS.md @@ -855,3 +855,190 @@ re-measurement. Wallet/send-flow is **not** in this table — it cleared as noise (see verdict above) and needs no deviation entry. Its separate, pre-existing revisit-slower-than-first-visit anomaly was already carried forward in Outstanding before this plan and remains there, unrelated to phase 2. + +## Client-Side Render Cost Root Cause (gap closure, 02-11) + +**Named cause (one sentence):** the dominant per-revisit cost on all six surfaces is NOT +CPU-bound render/computed work at all (a real CPU profile shows 90-99% of every window spent in +`(idle)`/`(program)`, with genuine app JS self-time under 10% everywhere) — it is background +network/scheduling contention from THREE child components/composables that arm a `setInterval` +poll in `onMounted` and only ever tear it down in `onUnmounted`/`onBeforeUnmount`, a pattern that +was harmless before phase 2 (the view was destroyed on every tab-away, so the poll died with it) +and is now a permanent, session-long background cost once phase 2's KeepAlive wrapping (02-04) +keeps the parent view's instance — and therefore these un-audited children — alive forever. + +### Method + +Built `neode-ui/e2e/perf/profile-revisit.spec.ts` (additive, does not touch the frozen +`surfaces.ts`/`measure.ts`/`surface-perf.spec.ts` — confirmed via `git diff --stat 3ee20430 -- +neode-ui/e2e/perf/surfaces.ts neode-ui/e2e/perf/measure.ts neode-ui/e2e/perf/surface-perf.spec.ts`, +empty both before and after this task). For each of the six named surfaces, reproduces the +harness's own first-visit -> away -> revisit structure, then during the revisit window only, +captures: a CDP `Profiler` CPU sample (self-time by function and by deployed chunk — production +has no sourcemaps, confirmed via `curl -I http://archi-dev-box/assets/vendor-*.js.map` -> 404, so +bucketing is by chunk name not source path), a CDP `Tracing` capture (the same category +`disabled-by-default-devtools.timeline` DevTools' own Performance panel uses), every +`setTimeout`/`requestAnimationFrame` call scheduled during the window (via a runtime monkey-patch, +restored after read-back), every RPC call's wall-clock start/duration, every CSS +`transitionrun`/`transitionend`/`animationstart`/`animationend` event on `document`, and an +independent first-paint timestamp (a rAF-driven poll for `contentSelector`'s first non-empty +bounding box — NOT gated by Playwright's own stricter `visible` actionability rules, which check +only bounding-box-non-empty + not-`visibility:hidden`, never opacity/transform, so a CSS +transition's duration does not by itself block the harness's own measured field). + +Ran against `archi-dev-box` (`ARCHY_BASE_URL=http://archi-dev-box`, `ARCHY_PASSWORD` from the +environment). Four of six surfaces completed cleanly in the first pass (Discover, AppDetails, +OpenWrtGateway, Fleet); a second pass added Web5 and Server and the Tracing/animation +instrumentation described above. A later attempt in this same investigation hit the +`OpenWrtGateway` nav step ("waiting for locator('a:has-text(\"OpenWrt Gateway\")').first()") — not +treated as a measurement, per this doc's own standing rule that a harness-execution failure is +never silently written in as data; `dismissOverlays()` was hardened afterward (HealthNotifications' +bare-SVG dismiss button has no `aria-label`, so the original `aria-label*="Close"` selector never +matched it — the exact intercepting-toast risk this doc's own Outstanding section already flagged +for the disk-usage banner) and `clickWithGuard`'s attempt count/force-click fallback increased. + +### CPU-profile evidence: the cost is NOT computation, it's waiting + +Real, sampled (100us interval) CPU self-time by category, one revisit window per surface (single +representative run each — dispersion comes from Task 3's 5-run re-measure once a fix lands, this +task's job is naming the mechanism): + +| Surface | Window (ms) | `(idle)` | `(program)` | All app JS (vendor+index+per-route chunks combined) | rAF calls | setTimeout calls | +|---|---|---|---|---|---|---| +| Web5 | 1452 | 730.5ms (50.4%) | 645.9ms (44.6%) | ~19ms (1.3%) | 12 | 17 (incl. six `15000`/five `180000` — poll re-arms, not blocking) | +| Server | 160 | 90.5ms (56.9%) | 56.4ms (35.4%) | ~1ms (0.6%) | 2 | 3 (all `180000`) | +| Discover | 1436 | 919.4ms (64.0%) | 300.8ms (21.0%) | ~98ms (6.9%) | 44 | 12 (incl. paired `150/150,301/301,501/501`) | +| AppDetails | 1085 | 716.7ms (66.1%) | 217.9ms (20.1%) | ~62ms (5.7%) | 44 | 17 | +| OpenWrtGateway | — | — | — | — | — | — (harness-execution failure this pass, see Method — not treated as data) | +| Fleet | 982 | 706.6ms (72.0%) | 143.1ms (14.6%) | ~48ms (4.9%) | — | — (captured in an earlier pass without the timer instrumentation; re-captured alongside the fix's own before/after in Task 2/3) | + +**What this table rules out, directly (not by inference):** every one of the hypotheses this +plan's own objective flagged as plausible — "expensive `computed` re-evaluation over large lists +on reactivation," "watchers cascading on activate," "the whole cached subtree re-rendering," +"per-row formatting recomputed for every item," "large `v-for` lists without stable +keys/virtualization" — would show up as real, attributed JS self-time inside app-code call frames. +It does not: combined vendor+index+per-route-chunk self-time is 1-7% of the window on every +surface, `(idle)`+`(program)` is 86-99%. The main thread is not busy; it is waiting. This +redirected the investigation from "what render work got heavier" to "what is the browser waiting +on," per D-10's own instruction to add instrumentation rather than assert an unsupported +hypothesis when the profile is ambiguous. + +### Source-level lifecycle audit: three permanently-running background pollers, invisible to 02-04's own per-view audit + +02-04's lifecycle audit (`02-04-SUMMARY.md`'s per-view side-effect table) grepped each TOP-LEVEL +view file (Home.vue, Web5.vue, Server.vue, Fleet.vue, ...) for timer/subscription/listener tokens +and correctly bucketed each one found into once-per-session / every-entry / only-while-visible. +Fleet.vue itself was checked and correctly found clean ("confirmed no lifecycle side effects (grep +for the five tokens found none)") — but that check never extended to the CHILD components and +composables the view delegates real work to. A repeat of the same grep across every file in +`neode-ui/src` (not just the audited top-level views), cross-checked for `setInterval` present +without a matching `onActivated`/`onDeactivated` pair, found three offenders exactly in the +KeepAlive'd subtrees of three of this gap's six named surfaces: + +1. **`neode-ui/src/views/fleet/useFleetData.ts:483-495`** (Fleet.vue's own data composable — + `Fleet.vue` calls `useFleetData()` directly, `const fleet = useFleetData()`): + ``` + onMounted(async () => { + ... + await refreshAll() + if (autoRefresh.value) startAutoRefresh() // pollTimer = setInterval(..., 60000) + }) + onUnmounted(() => { stopAutoRefresh() }) // never fires again once Fleet is KeepAlive'd + ``` + `startAutoRefresh()`'s `pollTimer` fires `Promise.all([fetchFleetStatus(), fetchFleetAlerts()])` + (plus `fetchNodeHistory()` if a node is selected) every 60 seconds, forever, from the first + Fleet visit onward, regardless of whether Fleet is the visible dashboard tab. +2. **`neode-ui/src/views/server/FipsNetworkCard.vue:265-274`** (rendered inside `Server.vue` at + line 164, ``): + ``` + let statusInterval: ReturnType | null = null + onMounted(() => { + statusInterval = setInterval(() => { if (document.hidden) return; void statusRes.refresh() }, 15000) + }) + onUnmounted(() => { if (statusInterval) clearInterval(statusInterval) }) + ``` + The `document.hidden` guard only helps when the whole BROWSER TAB is backgrounded — it does + nothing for an in-SPA dashboard-tab switch, since `document.hidden` stays `false` the entire + time the Archipelago tab itself is foregrounded, regardless of which dashboard view is showing. + This fires an `fips.status` refresh every 15 seconds, forever, from the first Server visit + onward, once Server is KeepAlive'd. +3. **`neode-ui/src/views/web5/Web5Monitoring.vue:105-114`** (rendered inside `Web5.vue` at line + 72, ``): + ``` + onMounted(() => { loadStats(); refreshInterval = setInterval(loadStats, 30000) }) + onBeforeUnmount(() => { if (refreshInterval) clearInterval(refreshInterval) }) + ``` + `loadStats()` calls `homeStatus.refreshSystemStats()` — the SAME store Home.vue's own, + correctly `onActivated`/`onDeactivated`-gated 10s poll already refreshes (02-04's own table: + `Home.vue | systemStatsInterval (10s loadSystemStats) | V`). This is a second, redundant, + never-torn-down 30s poll of the identical data, forever, from the first Web5 visit onward. + +Confirmed (not assumed) that this is a genuine phase-2 regression, not pre-existing: before 02-04 +registered these three views in `KEEP_ALIVE_PATHS`, leaving any of them fully **unmounted** the +component (and every child, including these three), which fired `onUnmounted`/`onBeforeUnmount` +and cleared the interval — the exact class of bug 02-04's audit convention exists to prevent, +missed here only because the audit's own grep scope was the view file, not its full child tree. + +Every other main-tab-adjacent file with a `setInterval` was checked the same way +(`grep -rl setInterval src/ | xargs check-for-onActivated`) — `Home.vue`, `Web5.vue` (own poll), +`Server.vue` (own poll) and `Mesh.vue` all correctly gate their OWN top-level intervals (confirmed +`onActivated`/`onDeactivated` present per 02-04's table); the three offenders above are the only +KeepAlive-subtree-reachable files missing the pair. (`useControllerNav.ts`'s route-change +`setTimeout(autoFocusMain, 150/300)` was also checked and ruled out — `autoFocusMain()` early- +returns unless `navRingActive()`, which is `false` for pointer/mouse-driven navigation; confirmed +negligible self-time in every profile above, so it does not explain a mouse-driven revisit's wall +clock, only a gamepad/keyboard user's.) + +### Why this produces exactly the `(idle)`-dominated signature measured above + +Three RPC-driven pollers running unconditionally every 15-60 seconds for the rest of the session, +completely independent of which dashboard tab is in the foreground, is real background network and +main-thread-scheduling activity that a JS CPU profile attributes to `(idle)`/`(program)` (waiting +on the network stack, connection-pool bookkeeping, and scheduler turnarounds) rather than to any +named app function — which is exactly what the table above shows, and is the same connection-pool- +contention mechanism 02-08 already root-caused for `Cloud.vue`'s peer-browse fan-out (`02-FINDINGS.md` +addendum), just distributed across three smaller, always-on pollers instead of one large burst. + +This also explains, for the first time with a mechanism rather than a shrug, why 02-10's +three-way re-measure found the regression getting WORSE across longer/later test runs even as disk +pressure genuinely eased (the opposite of what an environmental-noise theory predicts): a longer +session visits more of Fleet/Server/Web5 at least once, accumulating more of these permanently- +running background pollers, so EVERY subsequent navigation — not just these three surfaces' own +revisits — competes with more background traffic as the session goes on. `ARCHY_PERF_RUNS=5` +(02-10's re-measure) accumulates strictly more of this background load over its ~8-minute run than +`ARCHY_PERF_RUNS=3` (baseline/after) did over a shorter one, independent of any single surface's own +defect. + +### Surfaces without their own leaked poller: Discover, AppDetails, OpenWrtGateway + +- **OpenWrtGateway**'s `navSteps` transit `/dashboard/server` directly (`surfaces.ts`) — its + measured window already includes Server's own reactivation, so FipsNetworkCard's leaked poller + (and whatever contention it causes) bleeds directly into OpenWrtGateway's number, the same + transit-confound this doc's `## Method` section already documented for its RPC column. +- **Discover** and **AppDetails** both transit `/dashboard/apps` (`surfaces.ts`), and a repeat of + the same lifecycle-audit grep across every child component `Apps.vue` renders + (`AppCard.vue`, `AppIconGrid.vue`, `AppsUninstallModal.vue`) found no `setInterval` at all — + Apps.vue's own audit (02-04) is clean and stays clean here. Their regression is not explained by + a leaked poller of their own. The working hypothesis, to be confirmed (not assumed) by Task 3's + before/after re-measure: session-wide background contention from the three leaked pollers above + degrades ANY foreground navigation once Fleet/Server/Web5 have each been visited at least once in + the session — including Discover/AppDetails, which have no defect of their own to fix. If Task + 3's re-measure shows Discover/AppDetails improve materially after fixing only the three pollers, + that confirms this shared-contention mechanism; if they do not move, a surface-specific cause + (most plausibly the `useCachedResource` keyed-cache wrapper's own per-mount setup cost on + AppDetails, which is NOT KeepAlive'd and fully remounts every visit, exceeding what the eliminated + fetch saved — 02-10's own prior "split-signal" framing) remains the standing explanation and is + reported honestly as unresolved by this plan's fix, not glossed over. + +### Fix, per this named cause (Task 2) + +Apply the exact `onActivated`/`onDeactivated` arm/disarm pattern 02-04 already established and +proved safe for every OTHER poll interval in this codebase (`Server.vue`'s own `vpnPollInterval`, +`Mesh.vue`'s polls, `Home.vue`'s `systemStatsInterval`) to the three files above: start the +interval in `onActivated` (with an immediate first tick, matching the existing convention) and +clear it in `onDeactivated`, keeping `onMounted`/`onUnmounted` as the dual-registration fallback for +a bare (non-KeepAlive) mount, per 02-04's own documented "every arm function is called from BOTH +onMounted and onActivated" rule (a KeepAlive-wrapped first mount fires both once; a fresh-mount +guard is not needed here since the actions themselves — arming a 15/30/60s interval — are cheap and +idempotent, unlike Home/Web5/Mesh/Server's heavier first-load RPC bursts that needed a guard to +avoid double-firing). diff --git a/neode-ui/e2e/perf/profile-revisit.spec.ts b/neode-ui/e2e/perf/profile-revisit.spec.ts new file mode 100644 index 00000000..d6476054 --- /dev/null +++ b/neode-ui/e2e/perf/profile-revisit.spec.ts @@ -0,0 +1,420 @@ +// profile-revisit.spec.ts — 02-11 gap-closure diagnostic (D-10: measure before +// fix). Standalone, additive script — does NOT edit surfaces.ts / measure.ts +// / surface-perf.spec.ts (the frozen 02-01 harness stays frozen). +// +// 02-VERIFICATION.md's gap 2 confirmed six surfaces regressed on revisit with +// flat-or-improved RPC counts — i.e. the cost is client-side render/reactivity, +// not network. This script captures a REAL CPU profile (CDP Profiler domain — +// the same sampling data Chrome DevTools' Performance panel visualizes as a +// flame chart) during exactly the harness's own measured window (click chain +// -> contentSelector visible) for each named surface's revisit, then +// aggregates self-time by function so the dominant cost can be named with +// profiling evidence instead of guessed from source reading alone. +// +// Usage: +// ARCHY_BASE_URL=http://archi-dev-box ARCHY_PASSWORD=*** \ +// npx playwright test e2e/perf/profile-revisit.spec.ts --project=chromium --reporter=line +import { expect, test, type Page } from '@playwright/test' +import { SURFACES, type Surface } from './surfaces' + +const PASSWORD = process.env.ARCHY_PASSWORD ?? 'password123' +const NEUTRAL_SELECTOR = '[data-controller-zone="sidebar"] a[href="/dashboard/settings"]' +const NAV_TIMEOUT = 20_000 +const CONTENT_TIMEOUT = 20_000 + +// Every surface 02-VERIFICATION.md named as regressed, plus Fleet (the +// out-of-scope bonus 02-10 flagged as the most severe magnitude of the same +// mechanism) — all six of this gap plan's must-haves. +const TARGET_IDS = ['web5', 'server', 'discover', 'app-details', 'openwrt-gateway', 'fleet'] + +async function login(page: Page): Promise { + await page.goto('/login', { waitUntil: 'domcontentloaded' }) + await page.evaluate(() => { + localStorage.setItem('neode_intro_seen', '1') + localStorage.setItem('neode_onboarding_complete', '1') + }) + await page.goto('/login', { waitUntil: 'networkidle' }) + const passwordInput = page.locator('input[type="password"]').first() + await passwordInput.waitFor({ timeout: 15_000 }) + await passwordInput.fill(PASSWORD) + await page + .locator('button:has-text("Login"), button:has-text("Unlock"), button:has-text("Continue"), button[type="submit"]') + .first() + .click() + await page.waitForURL('**/dashboard**', { timeout: 20_000 }) +} + +async function dismissOverlays(page: Page): Promise { + try { + await page.keyboard.press('Escape') + } catch { + /* best-effort */ + } + const closeButtons = page.locator( + '[role="dialog"] button[aria-label*="Close" i], .fixed.inset-0 button[aria-label*="Close" i]' + ) + const count = await closeButtons.count().catch(() => 0) + if (count > 0) await closeButtons.first().click({ timeout: 2_000 }).catch(() => {}) + // HealthNotifications.vue's dismiss button has no aria-label at all (a bare + // SVG X icon) — the aria-label selector above never matches it, and per + // 02-FINDINGS.md's Outstanding section its `.fixed.right-4.z-[200]` wrapper + // has no `pointer-events: none`, so a still-open toast can intercept a + // click meant for page content underneath it (e.g. a disk-usage warning + // sitting over the "OpenWrt Gateway" link). Dismiss any visible one. + const healthToastClose = page.locator('.fixed.right-4.z-\\[200\\] button') + const healthCount = await healthToastClose.count().catch(() => 0) + for (let i = 0; i < healthCount; i++) { + await healthToastClose.first().click({ timeout: 1_000 }).catch(() => {}) + } +} + +async function clickWithGuard(page: Page, selector: string, timeoutMs: number): Promise { + const attempts = 4 + const perAttemptMs = Math.max(2_000, Math.floor(timeoutMs / attempts)) + let lastErr: unknown + for (let i = 0; i < attempts; i++) { + await dismissOverlays(page) + try { + await page.locator(selector).first().click({ timeout: perAttemptMs, force: i === attempts - 1 }) + return + } catch (err) { + lastErr = err + } + } + throw lastErr instanceof Error ? lastErr : new Error(String(lastErr)) +} + +async function clickChain(page: Page, steps: string[], timeoutMs: number): Promise { + for (const selector of steps) await clickWithGuard(page, selector, timeoutMs) +} + +async function goHome(page: Page, timeoutMs: number): Promise { + if (new URL(page.url()).pathname === '/dashboard/chat') { + const closed = await page.locator('.chat-close-btn').first().click({ timeout: 5_000 }).then(() => true).catch(() => false) + if (!closed) await page.goto('/dashboard', { waitUntil: 'domcontentloaded' }).catch(() => {}) + } + await clickWithGuard(page, '[data-controller-zone="sidebar"] a[href="/dashboard"]', timeoutMs) + await page.waitForURL((url) => url.pathname === '/dashboard', { timeout: timeoutMs }) +} + +interface CpuProfileNode { + id: number + callFrame: { functionName: string; url: string; lineNumber: number; columnNumber: number; scriptId: string } + hitCount?: number + children?: number[] +} +interface CpuProfile { + nodes: CpuProfileNode[] + startTime: number + endTime: number + samples?: number[] + timeDeltas?: number[] +} + +// Production build has no sourcemaps deployed (confirmed: assets/*.js.map -> +// 404 on archi-dev-box), so minified function names inside vendor-*.js/ +// index-*.js can't be resolved to source. Bucket by the DEPLOYED CHUNK NAME +// instead (still meaningful: vendor = Vue/Pinia/vue-router runtime bundled +// together; index = app entry/shared code; per-route chunk name = that +// view's own lazy-loaded code) rather than by node_modules path, which only +// exists pre-build. +function categorize(url: string): string { + if (!url) return '(native/gc/idle — no JS frame)' + const file = url.split('/').pop() ?? url + if (/^vendor-/.test(file)) return 'assets/vendor-*.js (Vue/Pinia/vue-router runtime bundle)' + if (/^index-/.test(file)) return 'assets/index-*.js (app entry/shared chunk)' + if (/^Dashboard-/.test(file)) return 'assets/Dashboard-*.js (Dashboard/DashboardRouterView chunk)' + if (/^Fleet-/.test(file)) return 'assets/Fleet-*.js (Fleet.vue chunk)' + if (/^Web5-/i.test(file)) return 'assets/Web5-*.js chunk' + if (/^Server-/.test(file)) return 'assets/Server-*.js chunk' + if (/^Discover-/.test(file)) return 'assets/Discover-*.js chunk' + if (/^AppDetails-/.test(file)) return 'assets/AppDetails-*.js chunk' + if (/^OpenWrtGateway-/.test(file)) return 'assets/OpenWrtGateway-*.js chunk' + if (url.startsWith('assets/')) return `assets/${file} (other chunk)` + if (url.includes('node_modules')) return 'other node_modules (dev-only build)' + return '(native/gc/idle — no JS frame)' +} + +function analyzeProfile(profile: CpuProfile, label: string): void { + const byId = new Map() + for (const n of profile.nodes) byId.set(n.id, n) + + const selfTimeById = new Map() + const samples = profile.samples ?? [] + const timeDeltas = profile.timeDeltas ?? [] + let total = 0 + for (let i = 0; i < samples.length; i++) { + const dt = timeDeltas[i] ?? 0 + total += dt + const id = samples[i]! + selfTimeById.set(id, (selfTimeById.get(id) ?? 0) + dt) + } + const totalMs = total / 1000 + const windowMs = (profile.endTime - profile.startTime) / 1000 + + // Aggregate by function identity (name@file:line) and by coarse category. + const byFunction = new Map() + const byCategory = new Map() + for (const [id, us] of selfTimeById) { + const node = byId.get(id) + if (!node) continue + const fnName = node.callFrame.functionName || '(anonymous)' + const file = node.callFrame.url ? node.callFrame.url.split('/').slice(-2).join('/') : '(native)' + const key = `${fnName} @ ${file}:${node.callFrame.lineNumber}` + byFunction.set(key, (byFunction.get(key) ?? 0) + us) + const cat = categorize(node.callFrame.url) + byCategory.set(cat, (byCategory.get(cat) ?? 0) + us) + } + + console.log(`\n===== CPU PROFILE: ${label} =====`) + console.log(`Profiled window (Profiler start->stop): ${windowMs.toFixed(1)}ms`) + console.log(`Total sampled self-time: ${totalMs.toFixed(1)}ms (${samples.length} samples)`) + console.log(`--- By category (self time) ---`) + const catSorted = Array.from(byCategory.entries()).sort((a, b) => b[1] - a[1]) + for (const [cat, us] of catSorted) { + const ms = us / 1000 + console.log(` ${ms.toFixed(1)}ms (${((us / total) * 100).toFixed(1)}%) ${cat}`) + } + console.log(`--- Top 20 functions (self time) ---`) + const fnSorted = Array.from(byFunction.entries()).sort((a, b) => b[1] - a[1]).slice(0, 20) + for (const [key, us] of fnSorted) { + const ms = us / 1000 + console.log(` ${ms.toFixed(2)}ms (${((us / total) * 100).toFixed(1)}%) ${key}`) + } +} + +test.describe.configure({ mode: 'serial' }) + +test('profile revisit CPU cost for named regressed surfaces', async ({ page }) => { + test.setTimeout(15 * 60 * 1000) + await login(page) + + for (const id of TARGET_IDS) { + const surface = SURFACES.find((s) => s.id === id) as Surface + expect(surface, `surface ${id} must exist in SURFACES`).toBeTruthy() + + await goHome(page, NAV_TIMEOUT) + + // First visit — warm the cache (matches the harness's own first-visit/ + // revisit structure) — not profiled. + await clickChain(page, surface.navSteps, NAV_TIMEOUT) + await page.locator(surface.contentSelector).first().waitFor({ state: 'visible', timeout: CONTENT_TIMEOUT }) + + // Away — to the neutral Settings tab (or close, for an in-page trigger). + if (surface.closeSelector) { + await page.locator(surface.closeSelector).first().click({ timeout: NAV_TIMEOUT }) + } else { + await clickWithGuard(page, NEUTRAL_SELECTOR, NAV_TIMEOUT) + await page.waitForURL((url) => url.pathname === '/dashboard/settings', { timeout: NAV_TIMEOUT }) + } + // Let the away-transition settle before starting the profiler so it + // captures only the revisit window, not Settings' own leave-transition. + await page.waitForTimeout(600) + + // Instrument window.setTimeout/requestAnimationFrame for the profiled + // window only, so a large "idle" share in the CPU profile can be + // attributed to a concrete scheduled delay (app timer) vs. a chain of + // animation frames (CSS-transition-bound) vs. neither (network wait). + await page.evaluate(() => { + const w = window as unknown as { + __timerLog: Array<{ type: string; delay?: number; at: number }> + __origSetTimeout: typeof setTimeout + __origRaf: typeof requestAnimationFrame + } + w.__timerLog = [] + w.__origSetTimeout = window.setTimeout.bind(window) + w.__origRaf = window.requestAnimationFrame.bind(window) + // eslint-disable-next-line @typescript-eslint/no-explicit-any + ;(window as any).setTimeout = (fn: TimerHandler, delay?: number, ...args: unknown[]) => { + w.__timerLog.push({ type: 'setTimeout', delay, at: performance.now() }) + return w.__origSetTimeout(fn as any, delay, ...args) // eslint-disable-line @typescript-eslint/no-explicit-any + } + // eslint-disable-next-line @typescript-eslint/no-explicit-any + ;(window as any).requestAnimationFrame = (cb: FrameRequestCallback) => { + w.__timerLog.push({ type: 'raf', at: performance.now() }) + return w.__origRaf(cb) + } + }) + + // Wall-clock RPC start/finish (matches measure.ts's own attachRpcTracker + // convention: Date.now() offsets, method name only, no bodies — T-02-06). + const rpcCalls: Array<{ method: string; startedAtMs: number; durationMs: number | null }> = [] + const pendingRpc = new Map() + let tRpc0 = 0 + const isRpc = (req: import('@playwright/test').Request) => req.method() === 'POST' && req.url().includes('/rpc/v1') + const onReq = (req: import('@playwright/test').Request) => { + if (!isRpc(req)) return + let method = 'unknown' + try { + const body = req.postData() + if (body) method = (JSON.parse(body) as { method?: string }).method ?? 'unknown' + } catch { + /* keep 'unknown' */ + } + pendingRpc.set(req, { method, start: Date.now() - tRpc0 }) + } + const onSettled = (req: import('@playwright/test').Request) => { + const info = pendingRpc.get(req) + if (!info) return + pendingRpc.delete(req) + rpcCalls.push({ method: info.method, startedAtMs: info.start, durationMs: Date.now() - tRpc0 - info.start }) + } + page.on('request', onReq) + page.on('requestfinished', onSettled) + page.on('requestfailed', onSettled) + + // Capture every CSS transition/animation start+end on the document during + // the window — decisive evidence for/against "a long CSS transition is + // what the human waits through" (Playwright's own 'visible' check does + // NOT wait for transitions/opacity, only a non-empty bounding box + not + // visibility:hidden, so a slow transition would NOT show up as CPU cost + // or as a blocked contentSelector — it would show up here, and would + // explain a "feels slow" gap between first-paint and contentSelector). + await page.evaluate(() => { + const w = window as unknown as { __animLog: Array<{ type: string; name: string; target: string; elapsedMs: number; at: number }> } + w.__animLog = [] + const describe = (el: EventTarget | null): string => { + const e = el as HTMLElement | null + if (!e || !e.tagName) return '(unknown)' + const cls = (e.className && typeof e.className === 'string') ? '.' + e.className.trim().split(/\s+/).slice(0, 2).join('.') : '' + return `${e.tagName.toLowerCase()}${cls}` + } + const log = (type: string) => (ev: Event) => { + const te = ev as TransitionEvent | AnimationEvent + w.__animLog.push({ + type, + name: (te as TransitionEvent).propertyName ?? (te as AnimationEvent).animationName ?? '', + target: describe(ev.target), + elapsedMs: Math.round((te.elapsedTime ?? 0) * 1000), + at: performance.now(), + }) + } + document.addEventListener('transitionrun', log('transitionrun'), true) + document.addEventListener('transitionend', log('transitionend'), true) + document.addEventListener('transitioncancel', log('transitioncancel'), true) + document.addEventListener('animationstart', log('animationstart'), true) + document.addEventListener('animationend', log('animationend'), true) + }) + + const client = await page.context().newCDPSession(page) + await client.send('Profiler.enable') + await client.send('Profiler.setSamplingInterval', { interval: 100 }) + await client.send('Profiler.start') + + // Raw Chrome trace events (the SAME data DevTools' Performance panel + // renders as a flame chart / summary tab) — categorizes rendering work + // (Layout, RecalculateStyles, Paint, CompositeLayers, RunTask, TimerFire, + // FireAnimationFrame, ...) that a bare JS CPU profile only sees as + // "(program)"/"(idle)" because layout/paint/compositing run on the same + // renderer main thread but outside any JS call frame. + // eslint-disable-next-line @typescript-eslint/no-explicit-any + const traceEvents: any[] = [] + // eslint-disable-next-line @typescript-eslint/no-explicit-any + client.on('Tracing.dataCollected', (data: any) => { traceEvents.push(...(data.value ?? [])) }) + const tracingComplete = new Promise((resolve) => client.once('Tracing.tracingComplete', () => resolve())) + await client.send('Tracing.start', { + categories: 'disabled-by-default-devtools.timeline,devtools.timeline,toplevel,v8,blink.user_timing', + transferMode: 'ReportEvents', + }) + + // First-paint probe, independent of Playwright's own contentSelector + // wait: records performance.now() the moment contentSelector FIRST gets + // a non-empty bounding box, polled every animation frame (not gated by + // Playwright's stricter "visible" actionability rules) — so first-paint + // and content-visible can be reported as two distinct numbers per the + // gap plan's explicit ask. + const pageT0 = await page.evaluate((sel) => { + const w = window as unknown as { __firstPaintAt: number | null } + w.__firstPaintAt = null + function poll() { + if (w.__firstPaintAt == null) { + const el = document.querySelector(sel) + if (el) { + const r = el.getBoundingClientRect() + if (r.width > 0 && r.height > 0) { + w.__firstPaintAt = performance.now() + return + } + } + requestAnimationFrame(poll) + } + } + requestAnimationFrame(poll) + return performance.now() + }, surface.contentSelector) + + const t0 = Date.now() + tRpc0 = t0 + await clickChain(page, surface.navSteps, NAV_TIMEOUT) + await page.locator(surface.contentSelector).first().waitFor({ state: 'visible', timeout: CONTENT_TIMEOUT }) + const wallMs = Date.now() - t0 + const firstPaintAt = await page.evaluate(() => (window as unknown as { __firstPaintAt: number | null }).__firstPaintAt) + const firstPaintMs = firstPaintAt != null ? Math.round(firstPaintAt - pageT0) : null + + const { profile } = await client.send('Profiler.stop') + await client.send('Profiler.disable') + await client.send('Tracing.end') + await tracingComplete + await client.detach().catch(() => {}) + page.off('request', onReq) + page.off('requestfinished', onSettled) + page.off('requestfailed', onSettled) + + // Find the renderer main-thread tid (thread_name metadata event) so the + // breakdown below isn't polluted by compositor/IO/GPU-process threads. + const mainThreadMeta = traceEvents.find( + (e) => e.ph === 'M' && e.name === 'thread_name' && (e.args?.name === 'CrRendererMain') + ) + const mainTid = mainThreadMeta?.tid + const durByName = new Map() + for (const e of traceEvents) { + if (mainTid != null && e.tid !== mainTid) continue + if (e.ph !== 'X') continue // complete events only (have a real duration) + if (typeof e.dur !== 'number') continue + durByName.set(e.name, (durByName.get(e.name) ?? 0) + e.dur) + } + console.log(`--- Chrome trace event self/total time by name (main thread, category=devtools.timeline; NOTE: 'X' events can nest, so this is TOTAL not self time — use for relative magnitude, not a sum-to-100% budget) ---`) + const traceSorted = Array.from(durByName.entries()).sort((a, b) => b[1] - a[1]).slice(0, 20) + for (const [name, us] of traceSorted) { + console.log(` ${(us / 1000).toFixed(1)}ms ${name}`) + } + + const timerLog = await page.evaluate(() => { + const w = window as unknown as { + __timerLog: Array<{ type: string; delay?: number; at: number }> + __origSetTimeout: typeof setTimeout + __origRaf: typeof requestAnimationFrame + } + const log = w.__timerLog ?? [] + window.setTimeout = w.__origSetTimeout + window.requestAnimationFrame = w.__origRaf + return log + }) + + const animLog = await page.evaluate(() => (window as unknown as { __animLog: Array<{ type: string; name: string; target: string; elapsedMs: number; at: number }> }).__animLog ?? []) + + console.log(`\n>>> ${surface.label} (${surface.id}) revisit wall-clock: ${wallMs}ms | first-paint: ${firstPaintMs}ms (contentSelector's first non-empty bounding box, unrelated to Playwright's own stricter 'visible' check)`) + analyzeProfile(profile as CpuProfile, `${surface.label} (${surface.id})`) + + const setTimeoutEntries = timerLog.filter((e) => e.type === 'setTimeout') + const rafCount = timerLog.filter((e) => e.type === 'raf').length + console.log(`--- Timers scheduled during the revisit window (app-code setTimeout/rAF calls) ---`) + console.log(` setTimeout calls: ${setTimeoutEntries.length}${setTimeoutEntries.length ? ' — delays(ms): ' + setTimeoutEntries.map((e) => e.delay ?? 0).sort((a, b) => a - b).join(',') : ''}`) + console.log(` requestAnimationFrame calls: ${rafCount}`) + + console.log(`--- CSS transition/animation events during the window (relative to window start, pageT0) ---`) + if (animLog.length === 0) { + console.log(' (none observed)') + } else { + for (const e of animLog) { + console.log(` +${Math.round(e.at - pageT0)}ms ${e.type} name="${e.name}" target=${e.target} elapsed=${e.elapsedMs}ms`) + } + } + + console.log(`--- RPC calls during the revisit window (wall-clock ms from window start) ---`) + for (const c of rpcCalls) { + console.log(` ${c.method}: start=+${c.startedAtMs}ms duration=${c.durationMs}ms`) + } + console.log(` total RPC calls: ${rpcCalls.length}, wall-clock window: ${wallMs}ms`) + } +})