diff options
| -rw-r--r-- | src/features/messages.js | 23 | ||||
| -rw-r--r-- | tools/feed-scroll-jank.js | 179 |
2 files changed, 188 insertions, 14 deletions
diff --git a/src/features/messages.js b/src/features/messages.js index 278e66f..bb2d788 100644 --- a/src/features/messages.js +++ b/src/features/messages.js @@ -7098,17 +7098,37 @@ export function messagesFeature(ctx) { if (changed && repaint && c.win && (c.win.top || c.win.bottom)) holdScroll(render); }); } + // A row changes height after it was measured — a picture lands in a row + // that painted before its size was known, a clip learns its shape, a link + // card arrives. The stale number is what the spacer uses when the row + // leaves the window: the page then shrinks or grows by the difference, + // the browser's scroll anchoring pulls the reader back by as much, and a + // coasting wheel scroll stalled or even reversed right as the media + // appeared. Keep the measurements live instead (no layout forced: the + // observer runs after layout). + const rowSizer = typeof ResizeObserver === 'undefined' ? null : new ResizeObserver((entries) => { + for (const en of entries) { + const r = en.target, c = r.parentElement && r.parentElement._winC; + if (!c || !r.isConnected) continue; + const hgt = r.getBoundingClientRect().height, key = r.getAttribute('data-key'); + if (hgt > 0 && key) (c.heights || (c.heights = new Map())).set(key, hgt); + } + }); function measureNow(c) { const list = document.querySelector('.notes-feed'); if (!list) return false; c.listTop = list.getBoundingClientRect().top + (window.scrollY || 0); + list._winC = c; const heights = c.heights || (c.heights = new Map()); let changed = false; + const seen = new Set(); for (const r of list.querySelectorAll(':scope > .row[data-key]')) { const hgt = r.getBoundingClientRect().height; const key = r.getAttribute('data-key'); if (hgt > 0 && Math.abs((heights.get(key) || 0) - hgt) > 0.5) { heights.set(key, hgt); changed = true; } + if (rowSizer) { seen.add(r); if (!(list._sized ||= new Set()).has(r)) { list._sized.add(r); rowSizer.observe(r); } } } + if (rowSizer && list._sized) for (const r of list._sized) if (!seen.has(r)) { list._sized.delete(r); rowSizer.unobserve(r); } return changed; } // On scroll: replenish the buffer before the reader reaches its edge, @@ -7897,7 +7917,8 @@ export function messagesFeature(ctx) { const known = size || mediaReady.get(url); return h('img', { src: mediaSrc(url, known), class: 'note-img clickable', loading: feedPaint || known ? 'eager' : 'lazy', alt: label || '', - decoding: known && known.thumb ? 'sync' : undefined, // a few-ms decode: paint it with the page + // a few-ms decode of the copy paints with the page; an original never holds the page for its decode + decoding: known && known.thumb ? 'sync' : 'async', width: size?.width, height: size?.height, style: size ? 'height:auto;aspect-ratio:' + size.width + '/' + size.height + ';--ar:' + (size.width / size.height).toFixed(4) : undefined, onClick: (e) => { if (!onPicture(e)) return; e.stopPropagation(); ctx.openImage && ctx.openImage(url); }, diff --git a/tools/feed-scroll-jank.js b/tools/feed-scroll-jank.js index 3877bf3..b7a014c 100644 --- a/tools/feed-scroll-jank.js +++ b/tools/feed-scroll-jank.js @@ -10,6 +10,10 @@ // bun tools/feed-scroll-jank.js --trackpad # also the native (non-notch) wheel path // bun tools/feed-scroll-jank.js --match v3.coinos.io # which tab (default: v3 if open, else localhost) // bun tools/feed-scroll-jank.js --out dir # keep run.json + run.cpuprofile there +// bun tools/feed-scroll-jank.js --trace --only settled --feeds Popular --seconds 15 +// bun tools/feed-scroll-jank.js --coast --only coast --trace # quick-notch bursts, then hands off: dips/jumps in the coast + what landed +// bun tools/feed-scroll-jank.js --url /feed/t/photography --feeds '#photography' --coast --only coast # a never-seen topic feed (fresh pictures) +// # + a Chrome trace: names the browser work (image decode, layout, paint, GC…) inside each long frame // // Two kinds of scenario per feed: "switch" (click the chip, start turning the // wheel at once while posts arrive) and "settled" (same feed after it has @@ -37,7 +41,10 @@ const page = args.match ? pages.find((t) => t.url.includes(args.match)) if (!page) { console.error('no page tab; open ones:', pages.map((p) => p.url).join(' ')); process.exit(1); } const ws = new WebSocket(page.webSocketDebuggerUrl); let id = 0; const pending = new Map(); -ws.onmessage = (m) => { const d = JSON.parse(m.data); if (d.id && pending.has(d.id)) { const { res, rej } = pending.get(d.id); pending.delete(d.id); d.error ? rej(new Error(JSON.stringify(d.error))) : res(d.result); } }; +const traceEvents = []; let traceDone = null; +ws.onmessage = (m) => { const d = JSON.parse(m.data); if (d.id && pending.has(d.id)) { const { res, rej } = pending.get(d.id); pending.delete(d.id); d.error ? rej(new Error(JSON.stringify(d.error))) : res(d.result); } + else if (d.method === 'Tracing.dataCollected') traceEvents.push(...d.params.value); + else if (d.method === 'Tracing.tracingComplete' && traceDone) traceDone(); }; const send = (method, params = {}) => new Promise((res, rej) => { const i = ++id; pending.set(i, { res, rej }); ws.send(JSON.stringify({ id: i, method, params })); }); await new Promise((r) => (ws.onopen = r)); await send('Runtime.enable'); await send('Page.enable'); await send('Profiler.enable'); @@ -46,6 +53,9 @@ const ev = async (expression) => { if (r.exceptionDetails) throw new Error(r.exceptionDetails.exception?.description || r.exceptionDetails.text); return r.result.value; }; +if (args.url) { // a fresh page: a topic feed nobody has scrolled yet, say /feed/t/photography + await send('Page.navigate', { url: new URL(args.url, page.url).href }); await sleep(Number(args.settle || 9000)); +} const vis = await ev('document.visibilityState'); if (vis !== 'visible') { console.error(`the tab is ${vis}; bring it to the front (a hidden tab gets no frames)`); process.exit(1); } if (!(await ev(`!!document.querySelector('.feed-chips')`))) { @@ -61,7 +71,7 @@ await ev(`(() => { R.start = () => { R.frames = []; R.tasks = []; R.wheel = []; R.rows = { added: 0, removed: 0, batches: 0 }; R.live = true; R.t0 = performance.now(); R.y0 = scrollY; - const tick = (t) => { if (!R.live) return; R.frames.push([t, scrollY]); requestAnimationFrame(tick); }; + const tick = (t) => { if (!R.live) return; R.frames.push([t, scrollY, document.documentElement.scrollHeight]); requestAnimationFrame(tick); }; requestAnimationFrame(tick); R.lt = new PerformanceObserver((l) => { for (const e of l.getEntries()) R.tasks.push([e.startTime, e.duration]); }); R.lt.observe({ type: 'longtask', buffered: false }); @@ -70,21 +80,37 @@ await ev(`(() => { R.et.observe({ type: 'event', durationThreshold: 16, buffered: false }); } catch {} const feed = document.querySelector('.notes-feed'); - R.mo = new MutationObserver((muts) => { let a = 0, r = 0; for (const m of muts) { a += m.addedNodes.length; r += m.removedNodes.length; } if (a || r) { R.rows.batches++; R.rows.added += a; R.rows.removed += r; } }); + R.batches = []; R.loads = []; R.shifts = []; R.wheels = []; + R.mo = new MutationObserver((muts) => { let a = 0, r = 0; for (const m of muts) { a += m.addedNodes.length; r += m.removedNodes.length; } if (a || r) { R.rows.batches++; R.rows.added += a; R.rows.removed += r; R.batches.push([performance.now(), a, r]); } }); if (feed) R.mo.observe(feed, { childList: true }); + // a picture or clip landing: when, how big, where on screen + R.onLoad = (e) => { const el = e.target; if (!el || !/^(IMG|VIDEO)$/.test(el.tagName) || !el.closest('.notes-feed')) return; + const b = el.getBoundingClientRect(); R.loads.push([performance.now(), el.tagName, el.naturalWidth || el.videoWidth || 0, el.naturalHeight || el.videoHeight || 0, Math.round(b.top), Math.round(b.height), (el.currentSrc || el.src || '').split('//').pop().slice(0, 50)]); }; + document.addEventListener('load', R.onLoad, true); document.addEventListener('loadedmetadata', R.onLoad, true); + try { R.ls = new PerformanceObserver((l) => { for (const e of l.getEntries()) R.shifts.push([e.startTime, +e.value.toFixed(4), e.hadRecentInput, (e.sources || []).map((s) => s.node?.tagName || '?').join('+')]); }); R.ls.observe({ type: 'layout-shift', buffered: false }); } catch {} + R.onWheel = (e) => R.wheels.push(e.timeStamp); window.addEventListener('wheel', R.onWheel, { passive: true, capture: true }); + // every programmatic scroll, with who asked: the coast's own steps come + // from tick(); anything else in a frame is a correction fighting it + R.scrolls = []; R._to = window.scrollTo; R._by = window.scrollBy; + const rec = (kind, y0) => { const st = (new Error().stack || '').split(String.fromCharCode(10)); const who = (st.find((l, i) => i > 1 && !/scrollTo|scrollBy/.test(l)) || '').trim().split(' (')[0].slice(0, 40); R.scrolls.push([performance.now(), kind, Math.round(scrollY - y0), who]); }; + window.scrollTo = function (...a) { const y0 = scrollY; R._to.apply(window, a); rec('to', y0); }; + window.scrollBy = function (...a) { const y0 = scrollY; R._by.apply(window, a); rec('by', y0); }; }; R.stop = () => { - R.live = false; R.lt?.disconnect(); R.et?.disconnect(); R.mo?.disconnect(); - return { t0: R.t0, t1: performance.now(), y0: R.y0, y1: scrollY, frames: R.frames, tasks: R.tasks, wheel: R.wheel, rows: R.rows, - timeOrigin: performance.timeOrigin, rowsNow: document.querySelectorAll('.notes-feed > .row').length, booting: !!document.querySelector('.notes-feed[data-booting]') }; + R.live = false; R.lt?.disconnect(); R.et?.disconnect(); R.mo?.disconnect(); R.ls?.disconnect(); + document.removeEventListener('load', R.onLoad, true); document.removeEventListener('loadedmetadata', R.onLoad, true); window.removeEventListener('wheel', R.onWheel, { capture: true }); + if (R._to) { window.scrollTo = R._to; window.scrollBy = R._by; } + return { t0: R.t0, t1: performance.now(), y0: R.y0, y1: scrollY, frames: R.frames, tasks: R.tasks, wheel: R.wheel, rows: R.rows, batches: R.batches, loads: R.loads, shifts: R.shifts, wheels: R.wheels, scrolls: R.scrolls, + vh: innerHeight, timeOrigin: performance.timeOrigin, rowsNow: document.querySelectorAll('.notes-feed > .row').length, booting: !!document.querySelector('.notes-feed[data-booting]') }; }; return true; })()`); // ---- real input -const feedRect = async () => ev(`(() => { const f = document.querySelector('.notes-feed') || document.querySelector('.feed-page'); const r = f.getBoundingClientRect(); return { x: r.x + r.width / 2, y: Math.max(120, Math.min(innerHeight - 80, r.y + r.height / 2)), w: innerWidth, h: innerHeight }; })()`); +const feedRect = async () => ev(`(() => { const f = document.querySelector('.notes-feed') || document.querySelector('.feed-page'); if (!f) return { x: innerWidth / 2, y: innerHeight / 2, w: innerWidth, h: innerHeight }; const r = f.getBoundingClientRect(); return { x: r.x + r.width / 2, y: Math.max(120, Math.min(innerHeight - 80, r.y + r.height / 2)), w: innerWidth, h: innerHeight }; })()`); const wheel = async (x, y, deltaY) => send('Input.dispatchMouseEvent', { type: 'mouseWheel', x, y, deltaX: 0, deltaY }); const clickChip = async (label) => { + await ev('window.scrollTo(0, 0)'); await sleep(250); // the chips sit at the top of the page const r = await ev(`(() => { const b = [...document.querySelectorAll('.feed-chips .feed-chip')].find((x) => x.textContent.trim().toLowerCase() === ${JSON.stringify(label.toLowerCase())}); if (!b) return null; b.scrollIntoView({ inline: 'center', block: 'nearest' }); const q = b.getBoundingClientRect(); return { x: q.x + q.width / 2, y: q.y + q.height / 2 }; })()`); if (!r) throw new Error(`no chip "${label}" (chips: ${await ev(`[...document.querySelectorAll('.feed-chips .feed-chip')].map((b) => b.textContent.trim()).join(' | ')`)})`); await send('Input.dispatchMouseEvent', { type: 'mouseMoved', x: r.x, y: r.y }); @@ -124,6 +150,55 @@ async function scenario(name, { feed, switchTo, dy = 100 }) { results.push(rec); console.log(` ${name.padEnd(26)} ${summarize(rec)}`); } +// A burst of quick notches, then hands off while it coasts; repeated down +// the feed. What the reader feels as "it slows down" shows up here as frames +// whose travel falls short of the coast's own decay (dips) or overshoots it +// (jumps), next to what landed at that moment. +async function coastScenario(name, { feed, bursts = 6, dy = 100 }) { + const r = await feedRect(); + await send('Input.dispatchMouseEvent', { type: 'mouseMoved', x: r.x, y: r.y }); + const tStart = Date.now(); + await ev('window.__jank.start()'); + for (let b = 0; b < bursts; b++) { + for (let i = 0; i < 6; i++) { await wheel(r.x, r.y, dy); await sleep(55); } + await sleep(Number(args.coast || 2600)); + } + const rec = await ev('window.__jank.stop()'); + rec.name = name; rec.feed = feed; rec.wall = [tStart, Date.now()]; rec.coast = true; + results.push(rec); + console.log(` ${name.padEnd(26)} ${summarize(rec)}`); + coastReport(rec); +} +function coastReport(rec) { + const F = rec.frames, dips = [], jumps = []; let lost = 0, travel = 0; + const near = (t, list, w = 70) => list.filter((x) => Math.abs(x[0] - t) <= w); + for (let i = 2; i < F.length; i++) { + const dt = F[i][0] - F[i - 1][0], pdt = F[i - 1][0] - F[i - 2][0]; + const dy = F[i][1] - F[i - 1][1], pdy = F[i - 1][1] - F[i - 2][1]; + if (!pdt || !dt) continue; + const expected = pdy * (dt / pdt) * Math.exp(-dt / 325); + travel += Math.abs(dy); + if (Math.abs(expected) < 4) continue; + const afterWheel = rec.wheels.some((w) => F[i][0] - w >= 0 && F[i][0] - w < 120); + if (Math.abs(dy) < 0.6 * Math.abs(expected)) { dips.push(i); lost += Math.abs(expected) - Math.abs(dy); } + else if (!afterWheel && Math.abs(dy) > 1.6 * Math.abs(expected) + 3) jumps.push(i); + } + rec.s.dips = dips.length; rec.s.jumps = jumps.length; rec.s.lostPx = Math.round(lost); + const what = (i) => { + const t = F[i][0]; const out = []; + const g = F[i][0] - F[i - 1][0]; if (g > 25) out.push(`frame ${g.toFixed(0)}ms`); + if (F[i][2] != null) { const dh = F[i][2] - F[i - 1][2]; if (dh) out.push(`page ${dh > 0 ? 'grew' : 'shrank'} ${dh}px`); if (F[i][1] + rec.vh >= F[i][2] - 2) out.push('AT THE END of the page'); } + const ld = near(t, rec.loads, 120); for (const l of ld.slice(0, 3)) out.push(`${l[1]} ${l[2]}x${l[3]} at top ${l[4]} h${l[5]} ${l[6]}`); if (ld.length > 3) out.push(`+${ld.length - 3} more loads`); + for (const sh of near(t, rec.shifts)) out.push(`shift ${sh[1]}${sh[2] ? ' (input)' : ''} ${sh[3]}`); + for (const b of near(t, rec.batches)) out.push(`rows +${b[1]} −${b[2]}`); + for (const sc of (rec.scrolls || []).filter((x) => x[0] > F[i - 1][0] - 1 && x[0] <= t + 1 && !/tick/.test(x[3]))) out.push(`${sc[1] === 'to' ? 'scrollTo' : 'scrollBy'} ${sc[2]}px by ${sc[3] || '?'}`); + for (const lt of rec.tasks) if (lt[0] <= t && lt[0] + lt[1] >= t - 70) out.push(`long task ${lt[1].toFixed(0)}ms`); + return out.join('; ') || '(nothing recorded nearby)'; + }; + const show = (list, kind) => { for (const i of list.slice(0, Number(args.top || 14))) { const dy = F[i][1] - F[i - 1][1], pdy = F[i - 1][1] - F[i - 2][1]; console.log(` ${kind} @${(F[i][0] - rec.t0).toFixed(0).padStart(5)}ms ${pdy.toFixed(0)}→${dy.toFixed(0)}px/frame ${what(i)}`); } }; + console.log(` coast: ${dips.length} dips (≈${Math.round(lost)}px of travel lost of ${Math.round(travel)}), ${jumps.length} jumps, ${rec.loads.length} media loads, ${rec.shifts.length} layout shifts`); + show(dips, 'dip '); show(jumps, 'jump'); +} function stats(gaps) { const s = [...gaps].sort((a, b) => a - b); const q = (p) => s.length ? s[Math.min(s.length - 1, Math.floor(s.length * p))] : 0; return { n: s.length, p50: q(0.5), p95: q(0.95), max: s.length ? s[s.length - 1] : 0 }; @@ -141,18 +216,32 @@ function summarize(rec) { } await send('Profiler.setSamplingInterval', { interval: Number(args.interval || 250) }); +if (args.trace) await send('Tracing.start', { categories: 'devtools.timeline,disabled-by-default-devtools.timeline,disabled-by-default-devtools.timeline.frame,blink.user_timing,v8.execute', transferMode: 'ReportEvents' }); await send('Profiler.start'); const profT0 = await ev('performance.now()'); +// a user-timing mark lands in the trace with the trace clock: the alignment +const syncNow = await ev(`(() => { performance.mark('jank-sync'); return performance.now(); })()`); // where are we now: settle, then start from another feed so every switch is a real one const current = await ev(`(document.querySelector('.feed-chips .feed-chip.on') || {}).textContent?.trim()`); console.log(`current feed: ${current}\n== mouse wheel (notch, app coast) ==`); -for (const f of feeds) { - if (current !== f || results.length) { await ev('window.scrollTo(0,0)'); await sleep(300); } - await scenario(`switch → ${f}`, { feed: f, switchTo: f, dy: delta }); - await sleep(4000); // let the feed settle +for (const f of (args.only === 'coast' ? [] : feeds)) { + if (args.only !== 'settled') { + if (current !== f || results.length) { await ev('window.scrollTo(0,0)'); await sleep(300); } + await scenario(`switch → ${f}`, { feed: f, switchTo: f, dy: delta }); + await sleep(4000); // let the feed settle + } else if (current !== f) { await clickChip(f); await sleep(5000); } await ev('window.scrollTo(0,0)'); await sleep(400); await scenario(`settled ${f}`, { feed: f, dy: delta }); } +if (args.coast) { + console.log('== bursts then hands-off coast =='); + for (const f of feeds) { + const cur = await ev(`(document.querySelector('.feed-chips .feed-chip.on') || {}).textContent?.trim()`); + if (cur !== f) { await clickChip(f); await sleep(5000); } + await ev(`window.scrollTo(0,${Number(args.start || 0)})`); await sleep(args.start ? 1500 : 400); + await coastScenario(`coast ${f}`, { feed: f, bursts: Number(args.bursts || 6) }); + } +} if (args.trackpad) { console.log('== trackpad-like (native scroll) =='); for (const f of feeds) { @@ -163,13 +252,77 @@ if (args.trackpad) { } } const { profile } = await send('Profiler.stop'); +if (args.trace) { const done = new Promise((r) => (traceDone = r)); await send('Tracing.end'); await done; } ws.close(); if (args.out) { const fs = await import('fs'); fs.mkdirSync(args.out, { recursive: true }); - fs.writeFileSync(`${args.out}/run.json`, JSON.stringify({ page: page.url, probe, results, profT0 }, null, 1)); + fs.writeFileSync(`${args.out}/run.json`, JSON.stringify({ page: page.url, probe, results, profT0, syncNow }, null, 1)); fs.writeFileSync(`${args.out}/run.cpuprofile`, JSON.stringify(profile)); + if (args.trace) fs.writeFileSync(`${args.out}/trace.json`, JSON.stringify({ traceEvents })); } analyze(profile, results, profT0); +if (args.trace) analyzeTrace(traceEvents, results, syncNow); + +// ---- the browser's own work inside each long frame (from the trace) +function analyzeTrace(events, results, syncNow) { + const mark = events.find((e) => e.name === 'jank-sync' && e.cat.includes('blink.user_timing')); + if (!mark) { console.log('\n(trace: no sync mark found; cannot align)'); return; } + const pid = mark.pid, offset = mark.ts - syncNow * 1000; // page ms → trace µs + const threads = new Map(); // tid → name + for (const e of events) if (e.ph === 'M' && e.name === 'thread_name' && e.pid === pid) threads.set(e.tid, e.args.name); + const mainTid = [...threads].find(([, n]) => n === 'CrRendererMain')?.[0]; + // self time per complete event: its duration minus its children's + const byThread = new Map(); + for (const e of events) if (e.ph === 'X' && e.pid === pid && e.dur > 0) { if (!byThread.has(e.tid)) byThread.set(e.tid, []); byThread.get(e.tid).push(e); } + const flat = []; + for (const [tid, list] of byThread) { + list.sort((a, b) => a.ts - b.ts || b.dur - a.dur); + const stack = []; + for (const e of list) { + while (stack.length && stack[stack.length - 1].ts + stack[stack.length - 1].dur <= e.ts) stack.pop(); + e.self = e.dur; if (stack.length) stack[stack.length - 1].self -= e.dur; + e.main = tid === mainTid; e.thread = threads.get(tid) || String(tid); + stack.push(e); flat.push(e); + } + } + flat.sort((a, b) => a.ts - b.ts); + const label = (e) => { const d = e.args?.data || e.args || {}; const extra = d.url ? ' ' + String(d.url).replace(/^https?:\/\//, '').slice(0, 60) : d.imageType ? ' ' + d.imageType : d.functionName ? ' ' + d.functionName : ''; return e.name + extra; }; + // the display's own frame accounting: frames the compositor dropped even + // while the page's animation frames kept ticking (a huge bitmap rasterizing) + const pipes = events.filter((e) => e.name === 'PipelineReporter' && e.ph === 'b' && e.pid === pid && e.args?.chrome_frame_reporter); + if (pipes.length) { + console.log('\n== trace: display frames (compositor pipeline) per scenario =='); + for (const r of results) { + const A = r.t0 * 1000 + offset, B = r.t1 * 1000 + offset; + const inWin = pipes.filter((e) => e.ts >= A && e.ts <= B); + const st = new Map(); for (const e of inWin) { const k = e.args.chrome_frame_reporter.state; st.set(k, (st.get(k) || 0) + 1); } + const dropped = inWin.filter((e) => e.args.chrome_frame_reporter.state === 'STATE_DROPPED'); + // where in the scenario the dropped ones cluster (100 ms bins with ≥2) + const bins = new Map(); for (const e of dropped) { const b = Math.floor((e.ts - A) / 100000); bins.set(b, (bins.get(b) || 0) + 1); } + const clusters = [...bins].filter(([, n]) => n >= 2).sort((a, b) => b[1] - a[1]).slice(0, 10).map(([b, n]) => `${(b * 100)}ms×${n}`).join(' '); + console.log(`${r.name}: ${[...st].map(([k, v]) => k.replace('STATE_', '') + ' ' + v).join(', ')}${clusters ? '\n dropped clusters: ' + clusters : ''}`); + } + } + console.log('\n== trace: browser work inside the long frames (self ms; main thread unless marked) =='); + for (const r of results) { + const gaps = []; + for (let i = 1; i < r.frames.length; i++) { const g = r.frames[i][0] - r.frames[i - 1][0]; if (g > 33) gaps.push([r.frames[i - 1][0], r.frames[i][0], g]); } + if (!gaps.length) { console.log(`${r.name}: no long frames`); continue; } + const tot = new Map(), totOff = new Map(); + const lines = []; + for (const [a, b, g] of gaps) { + const A = a * 1000 + offset, B = b * 1000 + offset; + const inside = flat.filter((e) => e.ts < B && e.ts + e.dur > A && e.self > 500); + const per = new Map(); + for (const e of inside) { const k = (e.main ? '' : '[' + e.thread + '] ') + label(e); const v = Math.min(e.self, Math.min(B, e.ts + e.dur) - Math.max(A, e.ts)); per.set(k, (per.get(k) || 0) + v); (e.main ? tot : totOff).set(e.name, ((e.main ? tot : totOff).get(e.name) || 0) + v); } + const top = [...per].sort((x, y) => y[1] - x[1]).slice(0, 5).map(([k, v]) => `${k} ${(v / 1000).toFixed(0)}`).join(' | '); + lines.push(` ${g.toFixed(0).padStart(4)}ms @${(a - r.t0).toFixed(0).padStart(5)}ms: ${top}`); + } + const sum = (m) => [...m].sort((x, y) => y[1] - x[1]).slice(0, 8).map(([k, v]) => `${k} ${(v / 1000).toFixed(0)}`).join(', '); + console.log(`${r.name}: ${gaps.length} long frames\n main: ${sum(tot)}\n other threads: ${sum(totOff)}`); + for (const l of lines.slice(0, Number(args.top || 14))) console.log(l); + } +} // ---- who was running during the long frames // Profile timestamps are µs on the same monotonic clock as performance.now() @@ -216,7 +369,7 @@ console.log('\n== summary =='); console.log('scenario'.padEnd(28) + 'p95 max >33 >50 >100 stalled ltasks ltMax busy>' + (args.busy || 30) + ' rows±'); for (const r of results) { const s = r.s; - console.log(r.name.padEnd(28) + `${s.p95.toFixed(0).padStart(3)} ${s.max.toFixed(0).padStart(4)} ${String(s.over33).padStart(4)} ${String(s.over50).padStart(4)} ${String(s.over100).padStart(5)} ${(s.stalledMs.toFixed(0) + 'ms').padStart(7)} ${String(s.longTasks).padStart(6)} ${s.longTaskMax.toFixed(0).padStart(5)} ${(ms(busyBy.get(r.name) || 0) + 'ms').padStart(8)} +${r.rows.added}/−${r.rows.removed} in ${r.rows.batches}`); + console.log(r.name.padEnd(28) + (r.coast ? `dips ${s.dips} (${s.lostPx}px) jumps ${s.jumps} ` : '') + `${s.p95.toFixed(0).padStart(3)} ${s.max.toFixed(0).padStart(4)} ${String(s.over33).padStart(4)} ${String(s.over50).padStart(4)} ${String(s.over100).padStart(5)} ${(s.stalledMs.toFixed(0) + 'ms').padStart(7)} ${String(s.longTasks).padStart(6)} ${s.longTaskMax.toFixed(0).padStart(5)} ${(ms(busyBy.get(r.name) || 0) + 'ms').padStart(8)} +${r.rows.added}/−${r.rows.removed} in ${r.rows.batches}`); } if (args.out) console.log(`\nraw: ${args.out}/run.json, ${args.out}/run.cpuprofile (tools/cdp-callers.js <profile> <fn> for callers; --analyze ${args.out} re-reads them)`); } |