A test that waits for a deadline somebody guessed is waiting for the wrong thing, so it waits for the editor (#93)

The suite spent 88% of its step time asleep: 564 s of steps, 496 s of
them in sleep(n) - fixed spans estimated by hand and then copied from
step to step. That is why it was slow, and why it flickered.

The signal is afterFrames(count, timeout) in ui/render.ts, exposed as
__gm.afterFrames(). It wakes the loop itself, because an editor that
draws nothing would never redeem a promise of a frame, and it gives up
after a timeout instead of hanging the run. settle() in the harness
waits two drawn frames (~32 ms) instead of 150-300 ms and falls back to
sleep(150) when the hook is missing (an old build): silently not
waiting would make every later check a coin toss.

Every action goes through it now - click, doubleClick, wheel, drag,
dragAsset, press, typeText, select, mutate, undo, redo - and with that
about 550 sleep() calls behind those actions became redundant, helpers
that are nothing but a mutate in a coat included. What a frame cannot
answer got its own condition instead: waitUntil(expr), play()/stop()
waiting on __gm.state.mode rather than on 300 ms, saved() for the
autosave (the two hand-written polling loops sampled at 300 ms for
something that arrives after a second), and showTab() as a real tool -
47 places called evaluate("__gm.showTab(...)") raw, and 24 of them
waited for nothing at all and read the old panel.

564 s -> 243 s of step time, the waiting share 88% -> 76%. Three kinds
of wait were kept, and each one bit when it was taken away: loading
bytes (textures, fonts), game time that a repaint cannot stand in for
(time scale, shader and particle clocks, the live values a running
graph carries), and the inertia the scroll step measures on purpose.

Two things the new speed uncovered, both real: 25-animation read the
frame menu unfiltered and had frozen an incomplete list (the CI failure
on c990dbc), and 33-render-on-change measured idleness while the
autosave of the step before was still painting - it waits for
saveStatus to leave dirty/saving now, so it measures that nothing
happens any more instead of that it waited long enough.

tools/e2e.mjs

@@ -11,7 +11,7 @@
  * rely on what earlier ones leave behind, a subset that skips a prerequisite fails on purpose.
  */
 import { STEPS } from './e2e/index.mjs';
-import { runChecks } from './lib/harness.mjs';
+import { runChecks, waited } from './lib/harness.mjs';
 import { PROJECTS, cliArgs } from './lib/projects.mjs';
 
 const { projectId, baseUrl } = cliArgs('e2e.mjs', PROJECTS.fixture);
@@ -35,8 +35,33 @@ if (steps.length !== STEPS.length) {
   console.log(`running ${steps.length}/${STEPS.length} steps: ${steps.map((s) => s.name).join(', ')}`);
 }
 
+/**
+ * One line per step, printed as it finishes: how long it took and how much of that was the
+ * harness sitting out a fixed wait. It also puts the run's position into the log, so a run that
+ * dies half-way says where it stood instead of leaving the last check as the only clue.
+ */
+const timings = [];
+async function timed(step, t) {
+  const at = Date.now();
+  const waitedAt = waited.ms;
+  await step(t);
+  const ms = Date.now() - at;
+  const slept = waited.ms - waitedAt;
+  timings.push({ name: step.name, ms, slept });
+  const no = String(STEPS.indexOf(step) + 1).padStart(2, '0');
+  console.log(`STEP ${no} ${step.name} – ${(ms / 1000).toFixed(1)}s (waited ${(slept / 1000).toFixed(1)}s)`);
+}
+
 await runChecks({ projectId, baseUrl, port: 9333, shotPrefix: 'gm-e2e' }, async (t) => {
   await t.navigate();
   await t.shot('01-loaded');
-  for (const step of steps) await step(t);
+  for (const step of steps) await timed(step, t);
+  const total = timings.reduce((sum, s) => sum + s.ms, 0);
+  const slept = timings.reduce((sum, s) => sum + s.slept, 0);
+  const worst = [...timings].sort((a, b) => b.ms - a.ms).slice(0, 8);
+  console.log(
+    `\nTIMING ${(total / 1000).toFixed(0)}s in steps, ${(slept / 1000).toFixed(0)}s of it waiting ` +
+      `(${Math.round((slept / total) * 100)}%). Slowest: ` +
+      worst.map((s) => `${s.name} ${(s.ms / 1000).toFixed(1)}s`).join(', '),
+  );
 });