feat(02-11): profile the six regressed surfaces — real cause found before any fix
CPU profile evidence (CDP Profiler + Tracing, additive neode-ui/e2e/perf/profile-revisit.spec.ts, frozen harness untouched) shows 86-99% of every revisit window spent in (idle)/(program) with under 10% genuine app JS self-time on every surface — ruling out expensive computed re-evaluation, watcher cascades, and whole-subtree re-renders as the dominant cost, per the plan's own explicit list of hypotheses to check before accepting one. A follow-up source-level lifecycle audit (grep every setInterval call site for a missing onActivated/onDeactivated pair, extending 02-04's own audit convention past the top-level view files it originally checked) found three child components/composables inside the KeepAlive'd Fleet/Server/Web5 subtrees that arm a poll in onMounted and only ever clear it in onUnmounted — harmless before phase 2 (the view was destroyed on tab-away) and now a permanent, session-long background-RPC cost once KeepAlive keeps the parent instance alive: useFleetData.ts (60s), FipsNetworkCard.vue (15s, Server), and Web5Monitoring.vue (30s, Web5 — redundant with Home.vue's own, correctly-gated 10s poll of the same store). This directly explains the idle-dominated CPU signature (background network/scheduling contention, not compute) and why 02-10's 5-run remeasure regressed further than the 3-run baseline/after runs even as disk pressure eased: a longer session accumulates more of these always-on pollers, degrading every subsequent navigation. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
archipelago
parent
6bf33b57b6
commit
050a87d2dd
@ -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, `<FipsNetworkCard />`):
|
||||
```
|
||||
let statusInterval: ReturnType<typeof setInterval> | 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, `<Web5Monitoring />`):
|
||||
```
|
||||
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).
|
||||
|
||||
420
neode-ui/e2e/perf/profile-revisit.spec.ts
Normal file
420
neode-ui/e2e/perf/profile-revisit.spec.ts
Normal file
@ -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<void> {
|
||||
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<void> {
|
||||
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<void> {
|
||||
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<void> {
|
||||
for (const selector of steps) await clickWithGuard(page, selector, timeoutMs)
|
||||
}
|
||||
|
||||
async function goHome(page: Page, timeoutMs: number): Promise<void> {
|
||||
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<number, CpuProfileNode>()
|
||||
for (const n of profile.nodes) byId.set(n.id, n)
|
||||
|
||||
const selfTimeById = new Map<number, number>()
|
||||
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<string, number>()
|
||||
const byCategory = new Map<string, number>()
|
||||
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<import('@playwright/test').Request, { method: string; start: number }>()
|
||||
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<void>((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<string, number>()
|
||||
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`)
|
||||
}
|
||||
})
|
||||
Loading…
x
Reference in New Issue
Block a user