Tick/toc instrumentation across build + test + mesh phases

run.sh:
  - phase() wrapper logs elapsed seconds per build step.
  - Tracks total build+startup at the end.
  - Output is "==> phase / [Ns] phase" so the slow steps are obvious.

test/run.py:
  - Per-step time.perf_counter() around each scenario step.
  - "slowest steps" summary printed at the end so the worst
    offenders are immediately visible.
  - Total wall-clock time at scenario end.

src/render/mod.rs:
  - browser_now() helper: web_sys::performance().now() on wasm,
    Instant-based on native. Monotonic ms timestamps for tick/toc.
  - Renderer::rebuild_chunk wraps build_chunk_mesh in a t0/t1
    measurement and logs anything over 5ms with vertex/index counts.
    Surfaces sky_visibility cost in the browser console.

web/main.js:
  - Exposes window.voxel_game = wasm after init so the test
    harness can drive scenarios declaratively (set_scene_time,
    teleport, look_at, get_position, etc.).

src/shader.wgsl:
  - Fix duplicate `let to_eye` declaration introduced in Round D
    (specular's normalized to_eye conflicted with fog's raw version).
    Renamed fog's local to_eye_raw. The test harness caught this
    immediately — first WGSL compile error, first scenario run.

Findings from running scenarios/lighting-times-of-day.yaml:
  - 289 chunks × ~100ms avg = ~29s mesh-build on main thread.
  - Page-ready latency dominated by this. window.voxel_game appears
    almost immediately (init resolves before chunks build), but
    the world is invisible until meshes are uploaded.
  - sky_visibility (8 cosine rays × HashMap voxel lookups) is the
    hot path inside build_chunk_mesh.

Next: make chunk-mesh build progressive (one or two chunks per tick
instead of all up-front), so the world becomes visible immediately
and pops in over a few seconds.
This commit is contained in:
Maximus Gorog 2026-05-24 11:49:08 -06:00
parent e7a232ba97
commit c0589d0dfc
5 changed files with 93 additions and 15 deletions

34
run.sh
View file

@ -20,17 +20,33 @@ for arg in "$@"; do
esac esac
done done
# tick/toc — measure each build phase so we know where time goes.
# Bash arithmetic on $SECONDS gives whole-second resolution; cheap and
# portable. For sub-second jobs use `time` directly.
phase() {
local label="$1"; shift
local start=$SECONDS
echo "==> $label"
"$@"
local elapsed=$((SECONDS - start))
echo " [${elapsed}s] $label"
}
TOTAL_START=$SECONDS
if [[ $DO_BUILD -eq 1 ]]; then if [[ $DO_BUILD -eq 1 ]]; then
echo "==> running unit tests (proves spawn / collision / mesh invariants)" phase "running unit tests (proves spawn / collision / mesh invariants)" \
cargo test --lib cargo test --lib
echo "==> building wasm client (release)" phase "building wasm client (release)" \
cargo build --target wasm32-unknown-unknown --release --lib cargo build --target wasm32-unknown-unknown --release --lib
~/.cargo/bin/wasm-bindgen --target web --out-dir web --no-typescript \
target/wasm32-unknown-unknown/release/voxel_game.wasm
echo "==> building server (release)" phase "wasm-bindgen → web/" \
(cd server && cargo build --release) ~/.cargo/bin/wasm-bindgen --target web --out-dir web --no-typescript \
target/wasm32-unknown-unknown/release/voxel_game.wasm
phase "building server (release)" \
bash -c "cd server && cargo build --release"
# Catch JS no-undef / parse errors before they hit the browser. eslint # Catch JS no-undef / parse errors before they hit the browser. eslint
# is optional: warns if absent so this step never blocks an emergency # is optional: warns if absent so this step never blocks an emergency
@ -68,6 +84,8 @@ for i in {1..20}; do
sleep 0.2 sleep 0.2
done done
echo "==> total build+startup: $((SECONDS - TOTAL_START))s"
if [[ $DO_TUNNEL -eq 0 ]]; then if [[ $DO_TUNNEL -eq 0 ]]; then
echo "==> server running at http://localhost:8080 (no tunnel)" echo "==> server running at http://localhost:8080 (no tunnel)"
wait $SERVER_PID wait $SERVER_PID

View file

@ -484,7 +484,22 @@ impl Renderer {
let Some(chunk) = world.chunks.get(&coord) else { let Some(chunk) = world.chunks.get(&coord) else {
return; return;
}; };
// tick/toc — mesh build (esp. the sky_visibility hemisphere
// raycasts) is the suspected hot path on world init. Times
// come through the browser console for now; once we have a
// real perf overlay they'll go there.
let t0 = browser_now();
let mesh = build_chunk_mesh(world, chunk); let mesh = build_chunk_mesh(world, chunk);
let mesh_ms = browser_now() - t0;
if mesh_ms > 5.0 {
log::info!(
"rebuild_chunk {:?}: {:.1}ms ({} verts, {} idx)",
coord,
mesh_ms,
mesh.vertices.len(),
mesh.indices.len()
);
}
if mesh.indices.is_empty() { if mesh.indices.is_empty() {
self.chunk_buffers.remove(&coord); self.chunk_buffers.remove(&coord);
return; return;
@ -627,6 +642,29 @@ impl Renderer {
} }
} }
/// Cross-platform "now" in milliseconds — uses the browser's
/// `performance.now()` on wasm, `Instant::now()` on native. Always
/// monotonic. Pairs with `browser_now()` calls to give tick/toc
/// elapsed times for instrumenting hot paths (mesh build, etc.).
fn browser_now() -> f64 {
#[cfg(target_arch = "wasm32")]
{
web_sys::window()
.and_then(|w| w.performance())
.map(|p| p.now())
.unwrap_or(0.0)
}
#[cfg(not(target_arch = "wasm32"))]
{
use std::time::Instant;
// The "0.0 epoch" is the first call; subsequent diffs are correct.
thread_local! {
static EPOCH: Instant = Instant::now();
}
EPOCH.with(|e| (Instant::now() - *e).as_secs_f64() * 1000.0)
}
}
/// Run a single full-screen-triangle render pass: clear target if /// Run a single full-screen-triangle render pass: clear target if
/// `clear` is `Some`, load otherwise; set pipeline; bind groups in /// `clear` is `Some`, load otherwise; set pipeline; bind groups in
/// order; draw three vertices. Used for every post-chain step so the /// order; draw three vertices. Used for every post-chain step so the

View file

@ -386,9 +386,11 @@ fn fs_main(in: VsOut) -> @location(0) vec4<f32> {
lit = lit + in.color * sun_col * trans; lit = lit + in.color * sun_col * trans;
} }
let to_eye = eye_world() - in.world_pos; // Reuse `to_eye` from the specular block (normalized eye-to-fragment).
let dist = length(to_eye); // Fog needs the *raw* distance though, so recompute that here.
let view_dir = -to_eye / max(dist, 0.0001); let to_eye_raw = eye_world() - in.world_pos;
let dist = length(to_eye_raw);
let view_dir = -to_eye_raw / max(dist, 0.0001);
let color = apply_fog(lit, dist, view_dir); let color = apply_fog(lit, dist, view_dir);
return vec4<f32>(color, 1.0); return vec4<f32>(color, 1.0);

View file

@ -166,25 +166,39 @@ def main() -> int:
p, browser, page = attach_page() p, browser, page = attach_page()
failures = 0 failures = 0
total_start = time.perf_counter()
timings: list[tuple[str, float]] = []
try: try:
for i, step in enumerate(scenario.get("steps", [])): for i, step in enumerate(scenario.get("steps", [])):
step_summary = next(iter(step.keys())) if step else f"step{i}"
print(f"step {i}:") print(f"step {i}:")
step_start = time.perf_counter()
try: try:
ok = run_step(page, step, name, args.halt_on_fail) ok = run_step(page, step, name, args.halt_on_fail)
step_ms = (time.perf_counter() - step_start) * 1000
timings.append((step_summary, step_ms))
print(f" [{step_ms:6.1f}ms]")
if not ok: if not ok:
failures += 1 failures += 1
if args.halt_on_fail: if args.halt_on_fail:
break break
except Exception as e: # noqa: BLE001 except Exception as e: # noqa: BLE001
step_ms = (time.perf_counter() - step_start) * 1000
timings.append((step_summary, step_ms))
print(f" [!] step error: {e}", file=sys.stderr) print(f" [!] step error: {e}", file=sys.stderr)
failures += 1 failures += 1
if args.halt_on_fail: if args.halt_on_fail:
break break
total_ms = (time.perf_counter() - total_start) * 1000
print() print()
if failures == 0: print(f"# {name}: {len(scenario.get('steps', []))} steps in {total_ms / 1000:.2f}s "
print(f"# {name}: OK ({len(scenario.get('steps', []))} steps)") f"({failures} failure{'s' if failures != 1 else ''})")
else: # Per-step breakdown so the slowest steps are obvious.
print(f"# {name}: FAILED ({failures} step(s))", file=sys.stderr) if timings:
timings_sorted = sorted(enumerate(timings), key=lambda x: -x[1][1])
print("# slowest steps:")
for i, (kind, ms) in timings_sorted[:5]:
print(f"# step {i:>2} {kind:>12} {ms:>7.1f}ms")
finally: finally:
browser.close() browser.close()
p.stop() p.stop()

View file

@ -22,6 +22,12 @@ function applyInputMode(mode) {
} }
init().then(() => { init().then(() => {
// Expose all wasm-bindgen exports on window.voxel_game so the
// Playwright test harness (test/run.py + scenarios) can drive the
// game declaratively from JS: set_scene_time, teleport, look_at,
// get_position, etc. Dev-affordance only; production users never
// touch this surface.
window.voxel_game = wasm;
wasm.reset_input(); wasm.reset_input();
setupTouch(); setupTouch();
setupGamepad(); setupGamepad();