diff --git a/e2e/app-ready-diagnostics.spec.ts b/e2e/app-ready-diagnostics.spec.ts index f78565a..fc4b805 100644 --- a/e2e/app-ready-diagnostics.spec.ts +++ b/e2e/app-ready-diagnostics.spec.ts @@ -72,6 +72,76 @@ test.describe('waitForAppReady', () => { await page.context().close() }) + // issue #305 - where the time went: Node's clock and the renderer's, apart + test('timeline: the Node side and the renderer side are reported separately, each with its own marks', async ({ browser }) => { + const page = await stubPage( + browser, + '/__app-ready/late-toolbar', + '
', + ) + await page.goto('/__app-ready/late-toolbar') + const msg = await failure(page) + expect(msg).toContain('waiting for .canvas') + // Node's clock: the document events before the wait (negative), the toolbar during it, the verdict + expect(msg).toMatch(/node timeline \(ms from the wait start\): navigated -\d+, DOMContentLoaded -?\d+, load -?\d+; toolbar visible \d+; gave up \d+/) + // the renderer's clock: its own marks, and where the wait started on that clock + expect(msg).toMatch(/renderer timeline \(ms from navigation start, read at \d+ ; the wait started at -?\d+\): lang set \d+, #root \d+, toolbar attached \d+ \/ visible \d+, canvas visible -/) + expect(msg).toMatch(/renderer work: \d+ frames, longest gap \d+ ms ending at \d+; long tasks \d+, \d+ ms in all/) + expect(msg).toMatch(/navigation: response end \d+, DOMContentLoaded \d+, load \d+; requests \d+, catalog requests 0 ending at -; slowest/) + expect(msg).not.toContain('late trace') + await page.context().close() + }) + + test('a renderer busy at the deadline: the probe goes unanswered, and the late trace is collected when it answers', async ({ browser }) => { + // after load, the main thread is held for 2.5 s: the 600 ms wait fails, the + // 1 s probe cannot run, and the same read comes back once the task ends + const page = await stubPage( + browser, + '/__app-ready/busy', + '
', + ) + await page.goto('/__app-ready/busy') + const msg = await failure(page) + expect(msg).toContain('stage: renderer did not answer') + expect(msg).toContain('did not answer within 1000 ms') + expect(msg).toMatch(/late trace: the renderer answered \d+ ms after the deadline; stage then: nothing rendered into #root/) + // the late read carries the long task that held the renderer + const late = msg.slice(msg.indexOf('late trace')) + const longest = Number(/longest (\d+) ms at/.exec(late)?.[1]) + expect(longest, 'the blocking task is in the late trace').toBeGreaterThanOrEqual(2000) + await page.context().close() + }) + + test('the slowest request is named, with its query values masked; requests are not listed one by one', async ({ browser }) => { + const page = await stubPage( + browser, + '/__app-ready/slow-page', + '
', + ) + await page.route('**/__app-ready/slow.js*', async (r) => { + await new Promise((res) => setTimeout(res, 400)) + await r.fulfill({ status: 200, contentType: 'text/javascript', body: '/* slow */' }) + }) + await page.goto('/__app-ready/slow-page') + const msg = await failure(page) + expect(msg).toMatch(/slowest \d+ ms from \d+, http:\/\/(localhost|127\.0\.0\.1):\d+\/__app-ready\/slow\.js\?key=\*\*\*/) + expect(Number(/slowest (\d+) ms/.exec(msg)?.[1])).toBeGreaterThanOrEqual(300) + expect(msg).not.toContain('s3cret') + expect(msg.match(/slow\.js/g)?.length).toBe(1) + await page.context().close() + }) + + test('a document without a boot trace says so', async ({ browser }) => { + // every context the fixture sees is traced (even `browser.newPage()` goes + // through `browser.newContext()`), so the trace is removed from this document + const page = await stubPage(browser, '/__app-ready/untraced', EMPTY_ROOT) + await page.goto('/__app-ready/untraced') + await page.evaluate(() => delete (window as unknown as { __appReadyTrace?: unknown }).__appReadyTrace) + const msg = await failure(page) + expect(msg).toContain('renderer timeline: not recorded (no boot trace in this document)') + await page.context().close() + }) + test('page errors and console errors are listed, counted and capped', async ({ browser }) => { const script = [ 'for (let i = 0; i < 30; i++) console.error("console-305 same");', diff --git a/e2e/support/appReady.ts b/e2e/support/appReady.ts index 01f0d2d..40d717b 100644 --- a/e2e/support/appReady.ts +++ b/e2e/support/appReady.ts @@ -11,6 +11,14 @@ import { expect, test, type BrowserContext, type Page } from '@playwright/test' // toolbar, then the canvas, each visible), the 8 s budget and the retry policy // are exactly what `openApp` used before. // +// The report also says WHERE the time went: Node's own clock for the document +// events and the wait, and the renderer's own clock for the boot (`bootTrace`, +// an init script of every watched context), kept apart; and when the renderer +// does not answer at the deadline, the same read is collected once it does (the +// "late trace", at most LATE_MS after the verdict, so it changes no verdict). +// Still diagnostics only: the condition, the budget and the retry policy are +// unchanged. +// // `watchPage` must be attached BEFORE the navigation it is meant to explain // (`goto`, `reload`). The shared fixture attaches it to every page of the // default context and of every context made with `browser.newContext()` @@ -82,6 +90,11 @@ type Watch = { /** of the CURRENT document: reset whenever the main frame navigates */ domContentLoaded: boolean load: boolean + /** Node's clock (`Date.now()`) at the current document's navigation and its + * two document events, kept apart from the renderer's own clock */ + navigatedAt: number | null + domContentLoadedAt: number | null + loadAt: number | null } const watches = new WeakMap() @@ -168,6 +181,9 @@ export function watchPage(page: Page): void { closed: false, domContentLoaded: false, load: false, + navigatedAt: null, + domContentLoadedAt: null, + loadAt: null, } watches.set(page, w) page.on('pageerror', (e) => add(w.pageErrors, e.message)) @@ -184,13 +200,113 @@ export function watchPage(page: Page): void { if (f !== page.mainFrame()) return w.domContentLoaded = false w.load = false + w.navigatedAt = Date.now() + w.domContentLoadedAt = null + w.loadAt = null + }) + page.on('domcontentloaded', () => { + w.domContentLoaded = true + w.domContentLoadedAt = Date.now() + }) + page.on('load', () => { + w.load = true + w.loadAt = Date.now() }) - page.on('domcontentloaded', () => (w.domContentLoaded = true)) - page.on('load', () => (w.load = true)) } -/** every page of `context`, the ones it has and the ones it will open */ -export function watchContext(context: BrowserContext): void { +/** + * Issue #305 - the renderer side of a boot, kept by an init script in every + * document of a watched context, so a failure report can say where the time + * went INSIDE the page (the Node side is in `Watch`). Compact by design, so it + * cannot slow the boot it measures: one check per animation frame (no subtree + * observer), a running count / sum / top three of the long tasks, the longest + * frame gap, and the first time each mark is seen. Requests are not recorded + * here; the report reads the browser's own resource timing once. It stops 500 ms + * after the canvas is visible, or after 30 s. Test code only: it never reaches + * a product bundle. + */ +function bootTrace(): void { + const w = window as unknown as { __appReadyTrace?: unknown } + if (w.__appReadyTrace) return + const now = (): number => Math.round(performance.now()) + const marks: Record = {} + const tr = { marks, frames: 0, maxGap: 0, maxGapAt: 0, longCount: 0, longSum: 0, longTop: [] as number[][], fonts: {} as Record> } + w.__appReadyTrace = tr + try { + // the dev build loads about 250 modules; the default buffer keeps 250 + performance.setResourceTimingBufferSize(2000) + } catch { + /* keep the default */ + } + const mark = (k: string): void => { + if (marks[k] === undefined) marks[k] = now() + } + // the parser's own `lang` is no mutation: the first one is the app setting it + new MutationObserver((records) => { + for (const r of records) if (r.attributeName === 'lang' && r.target === document.documentElement) mark('lang') + }).observe(document, { attributes: true, attributeFilter: ['lang'], subtree: true }) + try { + new PerformanceObserver((list) => { + for (const e of list.getEntries()) { + const d = Math.round(e.duration) + tr.longCount++ + tr.longSum += d + tr.longTop.push([Math.round(e.startTime), d]) + tr.longTop.sort((a, b) => b[1] - a[1]) + tr.longTop.length = Math.min(tr.longTop.length, 3) + } + }).observe({ type: 'longtask', buffered: true }) + } catch { + /* no long-task timing in this browser */ + } + const visible = (sel: string): boolean | null => { + const el = document.querySelector(sel) as HTMLElement | null + if (!el) return null + const r = el.getBoundingClientRect() + const s = getComputedStyle(el) + return r.width > 0 && r.height > 0 && s.visibility !== 'hidden' && s.display !== 'none' + } + let last = performance.now() + const frame = (): void => { + const t = performance.now() + const gap = Math.round(t - last) + last = t + tr.frames++ + if (gap > tr.maxGap) { + tr.maxGap = gap + tr.maxGapAt = Math.round(t) + } + if ((document.getElementById('root')?.childElementCount ?? 0) > 0) mark('root') + if (document.querySelector('.gate')) mark('gate') + const tb = visible('.toolbar') + if (tb !== null) mark('toolbarAttached') + if (tb) mark('toolbarVisible') + if (visible('.canvas')) mark('canvasVisible') + try { + for (const f of document.fonts) { + if (!/CJK Punct/.test(f.family)) continue + const k = f.family.replace(/["']/g, '') + const s = (tr.fonts[k] ??= {}) + if (s[f.status] === undefined) s[f.status] = Math.round(t) + } + } catch { + /* fonts not readable yet */ + } + const done = marks.canvasVisible !== undefined && t - marks.canvasVisible > 500 + if (!done && t < 30_000) requestAnimationFrame(frame) + } + requestAnimationFrame(frame) +} + +const traced = new WeakSet() + +/** every page of `context`, the ones it has and the ones it will open; the + * boot trace is registered before any of them navigates again */ +export async function watchContext(context: BrowserContext): Promise { + if (!traced.has(context)) { + traced.add(context) + await context.addInitScript(bootTrace) + } for (const p of context.pages()) watchPage(p) context.on('page', watchPage) } @@ -203,45 +319,131 @@ type Probe = { htmlDir: string toolbar: { present: boolean; visible: boolean } canvas: { present: boolean; visible: boolean } + /** the boot trace's summary, or null on a page without one */ + trace: TraceSummary | null +} + +/** what `bootTrace` kept, plus the browser's navigation and resource timing, + * read once; every time is the renderer's own (ms from its navigation start) */ +type TraceSummary = { + timeOrigin: number + now: number + marks: Record + frames: number + maxGap: number + maxGapAt: number + longCount: number + longSum: number + longTop: number[][] + fonts: Record> + nav: { responseEnd: number; domContentLoaded: number; load: number } | null + requests: number + catalog: number + catalogEnd: number | null + slowest: { url: string; start: number; duration: number } | null } -/** one read of the page, bounded: a renderer that does not answer within - * `ms` is itself the finding */ -async function probe(page: Page, ms: number): Promise<{ probe: Probe | null; answeredInMs: number | null; error?: string }> { +type Read = { probe: Probe; answeredInMs: number } + +/** one read of the page: the DOM state and the boot trace, in ONE evaluate */ +function readPage(page: Page): Promise { const t0 = Date.now() - const read = page.evaluate(() => { - const vis = (sel: string) => { - const el = document.querySelector(sel) as HTMLElement | null - if (!el) return { present: false, visible: false } - const r = el.getBoundingClientRect() - const s = getComputedStyle(el) - return { present: true, visible: r.width > 0 && r.height > 0 && s.visibility !== 'hidden' && s.display !== 'none' } - } - return { - readyState: document.readyState, - rootChildren: document.getElementById('root')?.childElementCount ?? -1, - gate: Boolean(document.querySelector('.gate')), - htmlLang: document.documentElement.lang, - htmlDir: document.documentElement.dir, - toolbar: vis('.toolbar'), - canvas: vis('.canvas'), - } - }) + return page + .evaluate(() => { + const vis = (sel: string) => { + const el = document.querySelector(sel) as HTMLElement | null + if (!el) return { present: false, visible: false } + const r = el.getBoundingClientRect() + const s = getComputedStyle(el) + return { present: true, visible: r.width > 0 && r.height > 0 && s.visibility !== 'hidden' && s.display !== 'none' } + } + type T = Omit + const tr = (window as unknown as { __appReadyTrace?: T }).__appReadyTrace + let trace: TraceSummary | null = null + if (tr) { + const r = Math.round + const navT = performance.getEntriesByType('navigation')[0] as PerformanceNavigationTiming | undefined + const res = performance.getEntriesByType('resource') as PerformanceResourceTiming[] + let slow: PerformanceResourceTiming | null = null + for (const e of res) if (!slow || e.duration > slow.duration) slow = e + const cat = res.filter((e) => /\/i18n\/locales\/|\/templateLabels\//.test(e.name)) + trace = { + ...tr, + marks: { ...tr.marks }, + longTop: tr.longTop.map((x) => [...x]), + fonts: JSON.parse(JSON.stringify(tr.fonts)), + timeOrigin: r(performance.timeOrigin), + now: r(performance.now()), + nav: navT ? { responseEnd: r(navT.responseEnd), domContentLoaded: r(navT.domContentLoadedEventEnd), load: r(navT.loadEventEnd) } : null, + requests: res.length, + catalog: cat.length, + catalogEnd: cat.length ? r(Math.max(...cat.map((e) => e.responseEnd))) : null, + slowest: slow ? { url: slow.name, start: r(slow.startTime), duration: r(slow.duration) } : null, + } + } + return { + readyState: document.readyState, + rootChildren: document.getElementById('root')?.childElementCount ?? -1, + gate: Boolean(document.querySelector('.gate')), + htmlLang: document.documentElement.lang, + htmlDir: document.documentElement.dir, + toolbar: vis('.toolbar'), + canvas: vis('.canvas'), + trace, + } + }) + .then((probe) => ({ probe, answeredInMs: Date.now() - t0 })) +} + +/** a read raced against `ms`: a renderer that does not answer in time is itself + * the finding, and its read is handed back still running (`late`) */ +async function probe(page: Page, ms: number): Promise<{ probe: Probe | null; answeredInMs: number | null; error?: string; late?: Promise }> { + const read = readPage(page) try { - const result = await Promise.race([ - read, - new Promise<'timeout'>((resolve) => setTimeout(() => resolve('timeout'), ms)), - ]) + const result = await Promise.race([read, new Promise<'timeout'>((resolve) => setTimeout(() => resolve('timeout'), ms))]) if (result === 'timeout') { read.catch(() => undefined) - return { probe: null, answeredInMs: null } + return { probe: null, answeredInMs: null, late: read } } - return { probe: result, answeredInMs: Date.now() - t0 } + return result } catch (e) { return { probe: null, answeredInMs: null, error: String((e as Error).message ?? e).split('\n')[0] } } } +/** how long, after a renderer missed the 1 s probe, the report waits for that + * same read to come back (the boot's late state); the wait is over once the + * failure is decided, so it changes no verdict */ +const LATE_MS = 5000 + +/** Node's own clock for the wait being reported */ +export type WaitTimes = { startedAt: number; toolbarAt?: number } + +/** ms from `base`, or `-` */ +const at = (t: number | null | undefined, base: number): string => (t === null || t === undefined ? '-' : String(t - base)) + +/** the Node side: the document events and the wait, ms from the wait's start */ +function nodeLine(w: Watch, times: WaitTimes, failedAt: number): string { + const b = times.startedAt + return `node timeline (ms from the wait start): navigated ${at(w.navigatedAt, b)}, DOMContentLoaded ${at(w.domContentLoadedAt, b)}, load ${at(w.loadAt, b)}; toolbar visible ${at(times.toolbarAt, b)}; gave up ${failedAt - b}` +} + +/** the renderer side, ms from the document's navigation start */ +function traceLines(t: TraceSummary | null, times: WaitTimes | undefined): string[] { + if (!t) return ['renderer timeline: not recorded (no boot trace in this document)'] + const m = t.marks + const waitStart = times ? ` ; the wait started at ${times.startedAt - t.timeOrigin}` : '' + const fonts = Object.entries(t.fonts) + .map(([k, s]) => `${k} ${Object.entries(s).map(([st, v]) => `${st} ${v}`).join(' / ')}`) + .join('; ') + const long = t.longTop.map(([s, d]) => `${d} ms at ${s}`).join(', ') + return [ + `renderer timeline (ms from navigation start, read at ${t.now}${waitStart}): lang set ${at(m.lang, 0)}, #root ${at(m.root, 0)}, toolbar attached ${at(m.toolbarAttached, 0)} / visible ${at(m.toolbarVisible, 0)}, canvas visible ${at(m.canvasVisible, 0)}${m.gate !== undefined ? `, storage gate ${m.gate}` : ''}`, + `renderer work: ${t.frames} frames, longest gap ${t.maxGap} ms ending at ${t.maxGapAt}; long tasks ${t.longCount}, ${t.longSum} ms in all${long ? `, longest ${long}` : ''}${fonts ? `; CJK faces ${fonts}` : ''}`, + `navigation: response end ${t.nav ? t.nav.responseEnd : '-'}, DOMContentLoaded ${t.nav ? t.nav.domContentLoaded : '-'}, load ${t.nav ? t.nav.load : '-'}; requests ${t.requests}, catalog requests ${t.catalog} ending at ${at(t.catalogEnd, 0)}; slowest ${t.slowest ? `${t.slowest.duration} ms from ${t.slowest.start}, ${safeUrl(t.slowest.url)}` : '-'}`, + ] +} + /** the furthest step of the boot this page reached, in words */ function stageOf(w: Watch | undefined, p: Probe | null, answered: boolean): string { if (w?.closed) return 'page closed' @@ -258,11 +460,12 @@ function stageOf(w: Watch | undefined, p: Probe | null, answered: boolean): stri } /** The diagnostic report for `page`, as lines. Exported for the helper's own - * tests. */ -export async function appReadyReport(page: Page, elapsedMs: number, waitingFor: string): Promise { + * tests. `times` is Node's clock for the wait (from `waitForAppReady`). */ +export async function appReadyReport(page: Page, elapsedMs: number, waitingFor: string, times?: WaitTimes): Promise { + const failedAt = Date.now() const w = watches.get(page) const closed = w?.closed || page.isClosed() - const { probe: p, answeredInMs, error } = closed ? { probe: null, answeredInMs: null } : await probe(page, 1000) + const { probe: p, answeredInMs, error, late } = closed ? { probe: null, answeredInMs: null } : await probe(page, 1000) const stage = stageOf(w ? { ...w, closed } : undefined, p, answeredInMs !== null) const yn = (b: boolean | undefined) => (b === undefined ? 'unknown' : b ? 'yes' : 'no') const vis = (v: { present: boolean; visible: boolean } | undefined) => (v ? `present ${yn(v.present)}, visible ${yn(v.visible)}` : 'unknown') @@ -275,6 +478,19 @@ export async function appReadyReport(page: Page, elapsedMs: number, waitingFor: `dom: #root children ${p ? p.rootChildren : 'unknown'}, storage gate ${yn(p?.gate)}, html lang "${cut(p?.htmlLang ?? '?', 40)}" dir "${cut(p?.htmlDir ?? '?', 10)}"`, `toolbar: ${vis(p?.toolbar)}; canvas: ${vis(p?.canvas)}`, ] + // issue #305 - where the time went, Node's clock and the renderer's apart + // (before the event lists, so the report cap never cuts them) + if (w && times) lines.push(nodeLine(w, times, failedAt)) + if (p) lines.push(...traceLines(p.trace, times)) + // a renderer that missed the probe: the same read, collected when it answers + if (late) { + const r = await Promise.race([late.catch(() => null), new Promise<'timeout'>((res) => setTimeout(() => res('timeout'), LATE_MS))]) + if (r === 'timeout' || r === null) lines.push(`late trace: the renderer still had not answered ${Date.now() - failedAt} ms after the deadline`) + else { + lines.push(`late trace: the renderer answered ${Date.now() - failedAt} ms after the deadline; stage then: ${stageOf(w, r.probe, true)}`) + lines.push(...traceLines(r.probe.trace, times)) + } + } if (!w) { lines.push('page events: not watched (watchPage was not attached before the navigation)') return lines @@ -299,14 +515,15 @@ export async function appReadyReport(page: Page, elapsedMs: number, waitingFor: * also attached to the test as `app-ready-diagnostics`. */ export async function waitForAppReady(page: Page, opts: { timeout?: number } = {}): Promise { - const t0 = Date.now() + const times: WaitTimes = { startedAt: Date.now() } let waitingFor = '.toolbar' try { await expect(page.locator('.toolbar')).toBeVisible(opts.timeout !== undefined ? { timeout: opts.timeout } : undefined) + times.toolbarAt = Date.now() waitingFor = '.canvas' await expect(page.locator('.canvas')).toBeVisible(opts.timeout !== undefined ? { timeout: opts.timeout } : undefined) } catch (e) { - const lines = await appReadyReport(page, Date.now() - t0, waitingFor) + const lines = await appReadyReport(page, Date.now() - times.startedAt, waitingFor, times) const first = cut(scrubText(String((e as Error).message ?? e).split('\n')[0]), MAX_TEXT) const report = capReport([first, ...lines].join('\n')) await attach(report) diff --git a/e2e/support/loop.ts b/e2e/support/loop.ts index 8610f41..9766f67 100644 --- a/e2e/support/loop.ts +++ b/e2e/support/loop.ts @@ -35,7 +35,7 @@ export const test = base.extend< // (the fixture callback is named `provide`, not `use`: oxlint's React rule // takes `use(context)` for the React `use` hook) context: async ({ context }, provide) => { - watchContext(context) + await watchContext(context) await provide(context) }, _watchNewContexts: [ @@ -45,7 +45,7 @@ export const test = base.extend< const original = browser.newContext.bind(browser) b.newContext = async (...args: Parameters) => { const ctx = await original(...args) - watchContext(ctx) + await watchContext(ctx) return ctx } b[WATCHED] = true