Add startup, search and play timing marks plus yt-dlp duration logs

2026-09-30 06:41:50 +00:00
parent 7b818baf8d
commit 7781e0a116
4 changed files with 32 additions and 1 deletions
--- a/plans/done/001-perf-timing-marks-105acc.md
+++ b/plans/done/001-perf-timing-marks-105acc.md
@@ -0,0 +1,129 @@
+---
+id: 001-perf-timing-marks-105acc
+title: Add startup, search and play timing marks plus yt-dlp duration logs
+created: 2026-09-29
+depends_on: []
+est_files: 2
+---
+
+# 001 — Add startup, search and play timing marks plus yt-dlp duration logs
+
+## Objective
+
+Every later speed plan needs a before/after number. After this plan:
+- The browser records `performance.measure` entries `ytp:boot`, `ytp:search`,
+  `ytp:tap-to-play`, and `window.__ytpPerf()` returns their latest values in ms.
+- The server logs one line per yt-dlp call: `[ytdlp] <kind> <ms>ms ok|fail`.
+
+Measured baseline (prod, 2026-09-29): search 4.1–5.0 s, first play `/api/streams` 7.5 s,
+second play 1.2 s, `/api/version` 1.25 s.
+
+## Context the executor must NOT rediscover
+
+`server/server.js:143-165` — the only place yt-dlp is spawned:
+
+```js
+function runYtdlp(args, { signal } = {}) {
+  return new Promise((resolve, reject) => {
+    const child = spawn(YTDLP, args, { stdio: ['ignore', 'pipe', 'pipe'] });
+    ...
+    child.on('error', (e) => reject(new Error('yt-dlp not found: ' + e.message)));
+    child.on('close', (code) => {
+      if (code !== 0) reject(new Error(err.trim() || 'yt-dlp exited with code ' + code));
+      else resolve(out);
+    });
+  });
+}
+```
+
+`frontend/app.js`:
+- `async function boot()` starts at ~line 9749 (`wirePlayerEvents();` is its first line).
+  The first `render()` call inside boot happens after the `hasShareParam` block.
+- `async function runSearchQuery(q, { instant = null } = {})` at ~line 8583; the
+  success path ends with `RecentSearches.cacheResults(q, results);`.
+- `Player.loadVideo(videoObj, …)` at ~line 1650; first statement is
+  `if (!this._handoff) Transition.cancel();`.
+- The master element `playing` listener at ~line 2287:
+  ```js
+  el.addEventListener('playing', () => {
+    if (!masterIs(el)) return;
+    showSpinner(false);
+  ```
+
+## Steps
+
+1. `server/server.js` — in `runYtdlp`, directly after the `const child = spawn(...)` line add:
+   ```js
+   const t0 = Date.now();
+   const kind = String(args.find((a) => /^ytsearch|^https?:/.test(String(a))) || args[0] || '')
+     .replace(/^ytsearch\d*:.*/, 'search').replace(/^https?:\/\/[^/]+\/watch.*/, 'video').slice(0, 40);
+   ```
+   and replace the `child.on('close', …)` handler body with:
+   ```js
+   child.on('close', (code) => {
+     console.log(`[ytdlp] ${kind} ${Date.now() - t0}ms ${code === 0 ? 'ok' : 'fail'}`);
+     if (code !== 0) reject(new Error(err.trim() || 'yt-dlp exited with code ' + code));
+     else resolve(out);
+   });
+   ```
+2. `frontend/app.js` — near the top of the file, directly after the line
+   `const APP_VERSION = '1.0.0';` (~line 24), add:
+   ```js
+   // Timing marks for the speed work (plans/). performance.measure entries are
+   // visible in DevTools → Performance; __ytpPerf() prints the latest ones.
+   function perfMark(name) { try { performance.mark(name); } catch { /* old browser */ } }
+   function perfMeasure(name, start) {
+     try { performance.measure(name, start); } catch { /* start mark missing */ }
+   }
+   window.__ytpPerf = () => {
+     const out = {};
+     try { for (const m of performance.getEntriesByType('measure')) if (m.name.startsWith('ytp:')) out[m.name] = Math.round(m.duration); } catch { /* none */ }
+     return out;
+   };
+   ```
+3. `frontend/app.js` `boot()` — first line of the function body: `perfMark('ytp:boot-start');`.
+   Immediately after the FIRST `render();` call inside `boot()` add
+   `perfMeasure('ytp:boot', 'ytp:boot-start');`.
+4. `frontend/app.js` `runSearchQuery` — after `const mySeq = ++searchSeq;` add
+   `perfMark('ytp:search-start');`. After `RecentSearches.cacheResults(q, results);` add
+   `perfMeasure('ytp:search', 'ytp:search-start');`.
+5. `frontend/app.js` `Player.loadVideo` — first line of the body: `perfMark('ytp:tap');`.
+6. `frontend/app.js` master `playing` listener — after `if (!masterIs(el)) return;` add:
+   ```js
+   if (performance.getEntriesByName('ytp:tap').length) {
+     perfMeasure('ytp:tap-to-play', 'ytp:tap');
+     try { performance.clearMarks('ytp:tap'); } catch { /* ignore */ }
+   }
+   ```
+
+## Out of scope / do NOT touch
+
+- No reporting endpoint, no UI. Don't change any behaviour, only add marks/logs.
+- Do not touch `runYtdlpResilient` or the fallback-client logic.
+
+## Verification
+
+```bash
+cd /home/user/ytplayer && node --check frontend/app.js && cd server && bun build server.js --target=bun --outdir=/tmp/ytp-check >/dev/null && echo SERVER_OK
+cd /home/user/ytplayer && node --test frontend/*.test.js 2>&1 | tail -3
+grep -c "perfMark\|perfMeasure" frontend/app.js
+```
+
+Expected: no syntax errors, `SERVER_OK`, tests `fail 0`, grep count ≥ 8.
+
+## Report format (executor: follow exactly)
+
+Output ONLY the following, no other prose:
+
+1. `git diff` (unified) of all changes.
+2. Raw output of the Verification commands.
+3. `Findings:` — max 10 lines: surprises, deviations from the steps, anything
+   skipped and why.
+
+Do not commit. Do not push. Do not touch files outside the Steps.
+
+## Execution log
+
+- Executor: in-session Agent (haiku), gateway `delegate.sh` not installed. Attempts: 1. Fix rounds: 0.
+- Orchestrator re-ran Verification: syntax OK, `SERVER_OK`, `node --test frontend/*.test.js` 52 pass / 0 fail, mark count 8.
+- Executor Findings (verbatim): All 6 plan steps applied successfully. Frontend timing marks added for boot (start->first paint), search (start->cached), tap-to-play (tap->playing event). Server logs yt-dlp duration on every invocation. Verification: syntax OK, server builds, unit tests pass (0 failures), 8 perfMark/perfMeasure occurrences (exceeds required 8). No deviations or skips.