Profile world placement stages and per-section rebuilds

apps/web/benchmarks/README.md

@@ -18,6 +18,36 @@ The default load radius is 1, unload radius is 2, viewport is 1280×720 at pixel
 
 Chrome uses its selected GPU by default. `--software-rendering` requests SwiftShader for validation on machines without usable GPU rendering; those results describe software rendering. `--headed` shows the browser. The report records the browser, actual WebGL renderer, operating system, revision, settings, and hashes of every world file requested. Missing files are listed separately. Benchmark results and save files do not belong in Git.
 
+## Profile placement
+
+Add `--profile-placement` to the command above. This option records placement stages and requires section meshing.
+
+The runner instruments four built ESM modules in memory while bundling the benchmark. It leaves library source, package files, and the section worker unchanged. If a method or measured boundary has changed, bundling fails instead of silently omitting that measurement. Without the flag, the runner uses the ordinary benchmark bundle.
+
+The report's `placementProfile` contains:
+
+- `events`: timed spans with IDs, explicit parent IDs, pass, phase, and waypoint. Section builds and their child stages include absolute section coordinates, including the vertical section coordinate. State and model preparation events identify their block or model; they have no section assignment.
+- `summary`: build totals per pass, split into `ownColumnBuilds`, `neighborBuilds`, `unloadBuilds`, and `otherBuilds`, plus `sectionsBuiltTwiceInOneOperation` for sections built at least twice within one operation.
+- `sections`: counts by pass and section coordinates (`x`, `y`, `z`), with `builds`, `succeeded`, the same operation split, `maxBuildsPerOperation`, `inclusiveMs`, and `unionMs`.
+- `stages`: call counts, successes, summed `inclusiveMs`, and `unionMs` by pass and stage, including cleanup. The union counts overlapping intervals of that stage once. Different stages can overlap or contain each other, so neither column can be added across stages to calculate total streaming time. Filter `events` by `phase` to exclude cleanup.
+- `issues` and `incompleteSpans`: missing ownership or unfinished instrumentation. The runner exits unsuccessfully if it detects these issues.
+
+Stage boundaries are:
+
+| Stage | Includes |
+|---|---|
+| `state-preparation` | Selecting prepared state/templates and resolving tints, including cache hits and waits |
+| `state-resolution` | The state cache's loader: model resolution, model atlases, and rotation data |
+| `template-preparation` / `template-build` | Template cache lookup/wait / the cache loader's geometry creation |
+| `model-atlas` | Creating a model texture atlas, including awaited texture loads; warm caches can skip this stage |
+| `section-rebuild` | A rebuild attempt, including neighborhood preparation, mesh replacement, and attempts that need no build |
+| `section-build` / `section-input` | A mesh build / conversion of its entries and templates to worker input |
+| `worker-roundtrip` | Worker dispatch through reply, including queueing, message cloning, and main-thread scheduling; this is not worker CPU time |
+| `synchronous-geometry` | Geometry built on the main thread when no worker is available or a worker rejects |
+| `mesh-assembly` / `atlas-paint` | Page canvases, geometry, materials, bounds, and subscriptions / its nested canvas allocation and image painting |
+
+Profiling adds clock reads, span records, promise continuations, and retained JavaScript memory. Use ordinary runs for performance comparisons. Profiled times describe the instrumented run, and its heap includes profiler records. The worker hash stays unchanged; the instrumented main script has a different hash. Both are recorded in the report.
+
 ## Read the report
 
 Each invocation has two passes. The first starts with fresh browser asset storage and a fresh `AnvilWorldSource`; the second keeps loaded assets and the renderer but creates a fresh world and source. Shared GPU resources and shader programs can also remain warm. Within each pass, returning to earlier stops reloads columns while raw region files can remain cached. The runner serves save files with `Cache-Control: no-store`.

apps/web/benchmarks/placement-profile.ts

@@ -0,0 +1,223 @@
+export interface PlacementProfileContext {
+    pass: "cold" | "warm";
+    phase: "outbound" | "return" | "cleanup";
+    waypoint: number | null;
+    operation: { id: number; kind: "placement" | "unload"; columns: { x: number; z: number }[] } | null;
+}
+
+export type PlacementProfileKind = "section-rebuild" | "section-build" | "section-input" | "worker-roundtrip"
+    | "synchronous-geometry" | "mesh-assembly" | "atlas-paint" | "model-atlas" | "state-resolution"
+    | "state-preparation" | "template-preparation" | "template-build";
+
+export interface PlacementProfileMetadata {
+    [key: string]: string | number | boolean | null | undefined;
+    x?: number;
+    y?: number;
+    z?: number;
+}
+
+export interface PlacementProfileEvent extends PlacementProfileContext, Pick<PlacementProfileMetadata, "x" | "y" | "z"> {
+    spanId: number;
+    parentSpanId?: number;
+    kind: PlacementProfileKind;
+    startMs: number;
+    durationMs: number;
+    success: boolean;
+    error?: string;
+}
+
+interface PendingSpan {
+    spanId: number;
+    parentSpanId?: number;
+    kind: PlacementProfileKind;
+    context: PlacementProfileContext;
+    metadata: PlacementProfileMetadata;
+    startMs: number;
+}
+
+export interface PlacementProfileHooks {
+    begin(kind: PlacementProfileKind, metadata?: PlacementProfileMetadata, parentId?: number): number;
+    end(spanId: number, success: boolean, error?: unknown): void;
+    measure<T>(kind: PlacementProfileKind, metadata: PlacementProfileMetadata, parentId: number | undefined, action: (spanId: number) => T): T;
+    measureAsync<T>(kind: PlacementProfileKind, metadata: PlacementProfileMetadata, parentId: number | undefined, action: (spanId: number) => Promise<T>): Promise<T>;
+}
+
+interface StageSummary {
+    pass: PlacementProfileContext["pass"];
+    kind: PlacementProfileKind;
+    count: number;
+    succeeded: number;
+    inclusiveMs: number;
+    unionMs: number;
+}
+
+interface SectionSummary {
+    pass: PlacementProfileContext["pass"];
+    x: number;
+    y: number;
+    z: number;
+    builds: number;
+    succeeded: number;
+    ownColumnBuilds: number;
+    neighborBuilds: number;
+    unloadBuilds: number;
+    otherBuilds: number;
+    maxBuildsPerOperation: number;
+    inclusiveMs: number;
+    unionMs: number;
+}
+
+const GLOBAL_KEY = "__minerenderPlacementProfile";
+const errorMessage = (error: unknown): string => error instanceof Error ? error.message : String(error);
+
+function unionDuration(events: readonly PlacementProfileEvent[]): number {
+    const ordered = events.slice().sort((a, b) => a.startMs - b.startMs);
+    let total = 0, start = ordered[0]?.startMs ?? 0, end = start;
+    for (const event of ordered) {
+        const nextEnd = event.startMs + event.durationMs;
+        if (event.startMs > end) {
+            total += end - start;
+            start = event.startMs;
+            end = nextEnd;
+        } else end = Math.max(end, nextEnd);
+    }
+    return total + end - start;
+}
+
+/** Installs hooks only for the benchmark bundle. Explicit parent IDs preserve ownership across awaits. */
+export function installPlacementProfiler(started: number, getContext: () => PlacementProfileContext) {
+    const events: PlacementProfileEvent[] = [];
+    const spans = new Map<number, PendingSpan>();
+    const issues: string[] = [];
+    let nextId = 0;
+
+    const metadataCopy = (metadata: PlacementProfileMetadata): PlacementProfileMetadata => {
+        const copy: PlacementProfileMetadata = {};
+        for (const [key, value] of Object.entries(metadata)) {
+            if (value !== undefined) copy[key] = value;
+        }
+        return copy;
+    };
+
+    const hooks: PlacementProfileHooks = {
+        begin(kind, metadata = {}, parentId) {
+            const parent = parentId === undefined ? undefined : spans.get(parentId);
+            if (parentId !== undefined && !parent) issues.push(`Missing parent span ${parentId} for ${kind}`);
+            const spanId = ++nextId;
+            spans.set(spanId, {
+                spanId, parentSpanId: parentId, kind, context: { ...(parent?.context ?? getContext()) },
+                metadata: { ...parent?.metadata, ...metadataCopy(metadata) }, startMs: performance.now() - started
+            });
+            return spanId;
+        },
+        end(spanId, success, error) {
+            const span = spans.get(spanId);
+            if (!span) return;
+            spans.delete(spanId);
+            const durationMs = performance.now() - started - span.startMs;
+            events.push({
+                ...span.metadata, ...span.context,
+                spanId, parentSpanId: span.parentSpanId, kind: span.kind, startMs: span.startMs, durationMs, success,
+                ...(!success && { error: errorMessage(error) })
+            });
+        },
+        measure(kind, metadata, parentId, action) {
+            const spanId = hooks.begin(kind, metadata, parentId);
+            let success = false, error: unknown;
+            try {
+                const result = action(spanId);
+                success = true;
+                return result;
+            } catch (caught) {
+                error = caught;
+                throw caught;
+            } finally {
+                hooks.end(spanId, success, error);
+            }
+        },
+        async measureAsync(kind, metadata, parentId, action) {
+            const spanId = hooks.begin(kind, metadata, parentId);
+            let success = false, error: unknown;
+            try {
+                const result = await action(spanId);
+                success = true;
+                return result;
+            } catch (caught) {
+                error = caught;
+                throw caught;
+            } finally {
+                hooks.end(spanId, success, error);
+            }
+        }
+    };
+    Object.defineProperty(globalThis, GLOBAL_KEY, { configurable: true, writable: true, value: hooks });
+
+    return {
+        report() {
+            const stageEvents = new Map<string, PlacementProfileEvent[]>();
+            const sectionEvents = new Map<string, PlacementProfileEvent[]>();
+            const reportIssues = issues.slice();
+            for (const spanId of spans.keys()) reportIssues.push(`Span ${spanId} is still open`);
+            for (const event of events) {
+                const stageKey = JSON.stringify([event.pass, event.kind]);
+                let stage = stageEvents.get(stageKey);
+                if (!stage) stageEvents.set(stageKey, stage = []);
+                stage.push(event);
+                if (event.kind !== "section-build") continue;
+                if (![event.x, event.y, event.z].every(value => Number.isInteger(value))) {
+                    reportIssues.push(`Section build ${event.spanId} has no integer section coordinates`);
+                    continue;
+                }
+                const sectionKey = JSON.stringify([event.pass, event.x, event.y, event.z]);
+                let section = sectionEvents.get(sectionKey);
+                if (!section) sectionEvents.set(sectionKey, section = []);
+                section.push(event);
+            }
+            const stages: StageSummary[] = [...stageEvents.values()].map(group => ({
+                pass: group[0].pass, kind: group[0].kind, count: group.length,
+                succeeded: group.filter(event => event.success).length,
+                inclusiveMs: group.reduce((total, event) => total + event.durationMs, 0), unionMs: unionDuration(group)
+            }));
+            const sections: SectionSummary[] = [...sectionEvents.values()].map(group => {
+                const operations = new Map<number, number>();
+                let ownColumnBuilds = 0, neighborBuilds = 0, unloadBuilds = 0, otherBuilds = 0;
+                for (const event of group) {
+                    const operation = event.operation;
+                    if (!operation) otherBuilds++;
+                    else {
+                        operations.set(operation.id, (operations.get(operation.id) ?? 0) + 1);
+                        if (operation.kind === "unload") unloadBuilds++;
+                        else if (operation.columns.some(column => column.x === event.x && column.z === event.z)) ownColumnBuilds++;
+                        else neighborBuilds++;
+                    }
+                }
+                return {
+                    pass: group[0].pass, x: group[0].x!, y: group[0].y!, z: group[0].z!, builds: group.length,
+                    succeeded: group.filter(event => event.success).length,
+                    ownColumnBuilds, neighborBuilds, unloadBuilds, otherBuilds,
+                    maxBuildsPerOperation: Math.max(0, ...operations.values()),
+                    inclusiveMs: group.reduce((total, event) => total + event.durationMs, 0), unionMs: unionDuration(group)
+                };
+            });
+            const summary = (["cold", "warm"] as const).map(pass => sections.filter(section => section.pass === pass).reduce((total, section) => ({
+                pass, builds: total.builds + section.builds,
+                ownColumnBuilds: total.ownColumnBuilds + section.ownColumnBuilds,
+                neighborBuilds: total.neighborBuilds + section.neighborBuilds,
+                unloadBuilds: total.unloadBuilds + section.unloadBuilds,
+                otherBuilds: total.otherBuilds + section.otherBuilds,
+                sectionsBuiltTwiceInOneOperation: total.sectionsBuiltTwiceInOneOperation + Number(section.maxBuildsPerOperation >= 2)
+            }), { pass, builds: 0, ownColumnBuilds: 0, neighborBuilds: 0, unloadBuilds: 0, otherBuilds: 0, sectionsBuiltTwiceInOneOperation: 0 }));
+            return {
+                events: events.slice().sort((a, b) => a.spanId - b.spanId), stages, sections, summary,
+                incompleteSpans: [...spans.values()].map(span => {
+                    const { spanId } = span;
+                    return { ...span.metadata, ...span.context, spanId, parentSpanId: span.parentSpanId, kind: span.kind, startMs: span.startMs };
+                }),
+                issues: reportIssues
+            };
+        },
+        restore() {
+            delete (globalThis as typeof globalThis & { [GLOBAL_KEY]?: PlacementProfileHooks })[GLOBAL_KEY];
+        }
+    };
+}

apps/web/benchmarks/world.ts

@@ -2,6 +2,7 @@ import {
     AnvilParser, AnvilWorldSource, AssetLoader, Env, MineRenderWorld, Renderer,
     SectionMesh, SectionWorker, WorldStreamer
 } from "minerender";
+import { installPlacementProfiler, PlacementProfileContext } from "./placement-profile";
 
 export interface WorldBenchmarkConfig {
     version: string;
@@ -15,6 +16,7 @@ export interface WorldBenchmarkConfig {
     biomeBlendRadius: number;
     renderEntities: boolean;
     maxCachedRegions: number;
+    profilePlacement: boolean;
 }
 
 const CAMERA_HEIGHT = 160;
@@ -114,6 +116,9 @@ async function runWorldBenchmark(config: WorldBenchmarkConfig) {
     const operations: Operation[] = [];
     const observedDataVersions = new Set<number>();
     let context: Pick<Operation, "pass" | "phase" | "waypoint"> = { pass: "cold", phase: "outbound", waypoint: null };
+    let operation: PlacementProfileContext["operation"] = null;
+    let nextOperationId = 0;
+    const placementProfile = config.profilePlacement ? installPlacementProfiler(started, () => ({ ...context, operation })) : undefined;
     let frames: ReturnType<typeof frameSampler> | undefined;
     const worker = { created: 0, buildRequests: 0, buildReplies: 0, buildFailures: 0, synchronousBuilds: 0 };
     const workerStats = () => ({ ...worker, fallbackBuilds: worker.buildFailures + worker.synchronousBuilds });
@@ -252,10 +257,18 @@ async function runWorldBenchmark(config: WorldBenchmarkConfig) {
                 readEntityRegion: config.renderEntities ? (x, z, signal) => readFile("entity-region", x, z, `/world-files/entities/r.${x}.${z}.mca`, signal) : undefined
             });
             const streamer = new WorldStreamer({
-                placeChunk: chunk => timed("placement", { x: chunk.x, z: chunk.z }, () => world.placeChunk(chunk)),
+                placeChunk: chunk => timed("placement", { x: chunk.x, z: chunk.z }, async () => {
+                    operation = { id: ++nextOperationId, kind: "placement", columns: [{ x: chunk.x, z: chunk.z }] };
+                    try { await world.placeChunk(chunk); }
+                    finally { operation = null; }
+                }),
                 unloadChunkColumns: columns => timed("unload", {
                     columnCount: columns.length, columns: columns.map(({ x, z }) => ({ x, z }))
-                }, () => world.unloadChunkColumns(columns))
+                }, async () => {
+                    operation = { id: ++nextOperationId, kind: "unload", columns: columns.map(({ x, z }) => ({ x, z })) };
+                    try { await world.unloadChunkColumns(columns); }
+                    finally { operation = null; }
+                })
             }, {
                 getChunk: (x, z, signal) => timed("source", { x, z }, () => source.getChunk(x, z, signal))
             }, { loadRadius: config.loadRadius, unloadRadius: config.unloadRadius });
@@ -316,7 +329,8 @@ async function runWorldBenchmark(config: WorldBenchmarkConfig) {
             runs.push({ pass, cacheStatus: `fresh source; ${pass === "cold" ? "cold" : "warm"} assets`, waypoints, cleanupMs, heapBytesAfterCleanupGc });
         }
         status.textContent = "Benchmark complete";
-        return { settings, environment, observedDataVersions: [...observedDataVersions].sort((a, b) => a - b), runs, operations, worker: workerStats() };
+        return { settings, environment, observedDataVersions: [...observedDataVersions].sort((a, b) => a - b), runs, operations,
+            worker: workerStats(), placementProfile: placementProfile?.report() };
     } catch (error) {
         status.textContent = `Benchmark failed: ${errorMessage(error)}`;
         throw error;
@@ -332,6 +346,7 @@ async function runWorldBenchmark(config: WorldBenchmarkConfig) {
             SectionWorker.prototype.build = original.buildWorker;
             if (createWorkerDescriptor) Object.defineProperty(provider, "createWorker", createWorkerDescriptor);
             else delete provider.createWorker;
+            placementProfile?.restore();
             running = false;
         }
     }

apps/web/build.mjs

@@ -4,6 +4,7 @@ import glob from "glob";
 import { parseArgs } from "node:util";
 import { copyFile, mkdir, readFile, rm, writeFile } from "node:fs/promises";
 import { dirname, relative, sep } from "node:path";
+import { instrumentPlacementModule } from "./scripts/placement-profile.mjs";
 
 const { values: args } = parseArgs({
     options: {
@@ -74,3 +75,8 @@ if (args.serve) {
         await writeFile(output, html);
     }));
 }
+
+for (const name of ["Chunk", "SectionMesh", "SectionModels", "UVMapper"]) {
+    const file = `../../packages/minerender/dist/browser/esm/${name === "UVMapper" ? "" : "world/"}${name}.mjs`;
+    instrumentPlacementModule(await readFile(file, "utf8"), name);
+}