From c38e68329210ecd171c2132129a8d819beb8c657 Mon Sep 17 00:00:00 2001 From: Fr0zka Date: Wed, 28 Oct 2026 19:10:19 +0100 Subject: [PATCH] research: Unreal arrival traces with swept tunnels (L102) Six null-RHI traces on 55e20f4, no address-space cap. FI: first admission 0.385 s, LOD0-2 settled 1.943 s (1.555 s from admission; L97 2.109 s), UWorld::Tick max 6.7 ms (L97 21 ms). SW: 0.415 / 1.706 s (1.292 s from admission), max 12.0 ms. EndPhysics gap <= 2 ms. Peak RSS ~2.32 GiB. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016dhxM43dnWvUu2B5Ph1iG1 --- .../WorldAssemblerM3/Linux102/REPORT.md | 16 + .../Linux102/RunL102UnrealArrival.py | 484 ++++++++++++++++++ 2 files changed, 500 insertions(+) create mode 100644 Standalone/Research/WorldAssemblerM3/Linux102/REPORT.md create mode 100644 Standalone/Research/WorldAssemblerM3/Linux102/RunL102UnrealArrival.py diff --git a/Standalone/Research/WorldAssemblerM3/Linux102/REPORT.md b/Standalone/Research/WorldAssemblerM3/Linux102/REPORT.md new file mode 100644 index 0000000..5815a94 --- /dev/null +++ b/Standalone/Research/WorldAssemblerM3/Linux102/REPORT.md @@ -0,0 +1,16 @@ +# Linux 102 + +Six complete null-RHI Unreal traces on `55e20f4`, with the L97 low-priority tile settings and tick logging enabled. Unreal was launched as `taskset -c 0-11 timeout 1740s`; it had no address-space cap. No build was needed: the VFHost plugin source matches this checkout and its module binary postdates the source. + +| Stratum | First admission | LOD0–2 settled | From admission | `UWorld::Tick` p99 / worst max | `AVoxelWorld::Tick` p99 / worst max | EndPhysics gap max | +|---|---:|---:|---:|---:|---:|---:| +| FI | 0.385 s (0.382–0.388) | 1.943 s (1.922–1.951) | 1.555 s (1.541–1.566) | 4.8–6.6 / 6.7 ms | 4.2–4.8 / 5.1 ms | 1 ms | +| SW | 0.415 s (0.414–0.417) | 1.706 s (1.706–1.713) | 1.292 s (1.289–1.298) | 8.5–10.0 / 12.0 ms | 7.9–9.4 / 11.3 ms | 2 ms | + +Times are medians across three complete runs, with ranges in parentheses. Tick p99 columns show the three-run range; max is the worst per-run maximum. + +Compared with L97, median settle from first admission was 2.109 s / 21 ms max `UWorld::Tick` for FI and 1.316 s / 11 ms for SW. L102 measured 1.555 s / 6.7 ms for FI and 1.292 s / 12.0 ms for SW. The largest EndPhysics gap fell from 16 ms / 7 ms to 1 ms / 2 ms. + +Peak Unreal RSS (`VmHWM`) was 2,378.7 MiB (2.32 GiB): FI runs were 2,370.5–2,378.7 MiB and SW runs 2,275.3–2,295.6 MiB. There was no L97-era executable or RSS record available; a separate old host/plugin build would be needed, so the memory delta is unknown. + +Failed L102 runs: none. All six exited 0 and settled LOD0–2. Logs and per-run summaries are in `Saved/Linux/l102/unreal-arrival/`. No installs, commits, pushes, or stashes. diff --git a/Standalone/Research/WorldAssemblerM3/Linux102/RunL102UnrealArrival.py b/Standalone/Research/WorldAssemblerM3/Linux102/RunL102UnrealArrival.py new file mode 100644 index 0000000..dcce191 --- /dev/null +++ b/Standalone/Research/WorldAssemblerM3/Linux102/RunL102UnrealArrival.py @@ -0,0 +1,484 @@ +#!/usr/bin/env python3 +"""Run one pinned null-RHI SW/FI arrival for Linux 102.""" +from __future__ import annotations + +import argparse +from collections import Counter +from datetime import datetime +import json +import re +import subprocess +import time +from pathlib import Path + +ROOT = Path(__file__).resolve().parents[4] +HOST = Path("/home/jahni/VFHost") +HOST_PLUGIN_SAVED = HOST / "Plugins/VoxelForge/Saved/Linux/l102" +HOST_SAVED = HOST / "Saved/Linux/l102" +EDITOR = Path("/home/jahni/UnrealEngine/Engine/Binaries/Linux/UnrealEditor-Cmd") +OUT = ROOT / "Saved/Linux/l102/unreal-arrival" +SPAWNS_M = { + "FI": (25.8369140625, 3.19921875, -737.0), + "SW": (25.8369140625, 3.19921875, -200.0), +} +MOVE_START_S = 20.0 +MOVE_DURATION_S = 12.0 +EXIT_S = MOVE_START_S + MOVE_DURATION_S + 5.0 +RUN_TIMEOUT_S = 1740 + + +def read_events(path: Path) -> list[dict]: + events = [] + if path.is_file(): + for line in path.read_text(encoding="utf-8", errors="replace").splitlines(): + if line.startswith("{"): + try: + events.append(json.loads(line)) + except json.JSONDecodeError: + pass + return events + + +def percentile(values: list[float], fraction: float) -> float | None: + if not values: + return None + ordered = sorted(values) + return ordered[min(len(ordered) - 1, int(round((len(ordered) - 1) * fraction)))] + + +def sample_unreal_peak_rss() -> tuple[int, int] | None: + executable = str(EDITOR).encode() + project = str(HOST / "VFHost.uproject").encode() + peak: tuple[int, int] | None = None + for process in Path("/proc").glob("[0-9]*"): + try: + command_line = (process / "cmdline").read_bytes() + if executable not in command_line or project not in command_line: + continue + status = (process / "status").read_text(encoding="ascii", errors="ignore") + match = re.search(r"^VmHWM:\s+(\d+)\s+kB$", status, re.MULTILINE) + if match: + rss_kib = int(match.group(1)) + if peak is None or rss_kib > peak[0]: + peak = (rss_kib, int(process.name)) + except (FileNotFoundError, PermissionError, ProcessLookupError, OSError): + continue + return peak + + +def endphysics_gap(stdout: Path) -> tuple[float | None, int | None]: + release_times: dict[int, dict[int, datetime]] = {} + pattern = re.compile( + r"^\[(\d{4}\.\d{2}\.\d{2}-\d{2}\.\d{2}\.\d{2}:\d{3})\].*" + r"LogTick: tick\s+(\d+)\s+-+\s+Release tick group ([34])") + with stdout.open(encoding="utf-8", errors="replace") as stream: + for line in stream: + match = pattern.match(line) + if not match: + continue + timestamp = datetime.strptime(match.group(1), "%Y.%m.%d-%H.%M.%S:%f") + frame = int(match.group(2)) + group = int(match.group(3)) + release_times.setdefault(frame, {})[group] = timestamp + gaps = [(round((times[4] - times[3]).total_seconds() * 1000.0, 3), frame) + for frame, times in release_times.items() if 3 in times and 4 in times] + return max(gaps, default=(None, None)) + + +def run(stratum: str, repeat: int, phase: str, ready_depth: int, + background_cap: int, worker_reserve: int, helper_background: int, + tile_background_low: int, tile_background_normal: int, startup_boost: int, + tick_logs: bool, insights: bool) -> dict: + label = (f"{phase}-{stratum.lower()}-rd{ready_depth}-bg{background_cap}" + f"-reserve{worker_reserve}-helperbg{helper_background}" + f"-tilelow{tile_background_low}-tilenormal{tile_background_normal}" + f"-ticklog{int(tick_logs)}" + f"-boost{startup_boost}-{repeat}") + trace = OUT / f"{label}.trace.jsonl" + utrace = OUT / f"{label}.utrace" + abslog = OUT / f"{label}.log" + stdout = OUT / f"{label}.stdout.log" + output = HOST_PLUGIN_SAVED / "output" / label + userdir = HOST_SAVED / "user" / label + zendata = HOST_SAVED / "zen" / label + ddc = HOST_SAVED / "DDC" + for directory in (OUT, output, userdir, zendata, ddc): + directory.mkdir(parents=True, exist_ok=True) + trace.unlink(missing_ok=True) + utrace.unlink(missing_ok=True) + spawn_cm = ",".join(f"{value * 100.0:.3f}" for value in SPAWNS_M[stratum]) + command = [ + str(EDITOR), str(HOST / "VFHost.uproject"), "-nullrhi", "-unattended", + "-nop4", "-nosplash", "-NoSound", "-corelimit=12", "-NoZenAutoLaunch", + "-notraceserver", "-nocrashreports", + "-DisablePlugins=AndroidFileServer", + "-ddc=NoZenLocalFallback", f"-userdir={userdir}", f"-ZenDataPath={zendata}", + f"-LocalDataCachePath={ddc}", "-run=VoxelForgeExplore", "-seed=0", + "-archetype=TunnelNetwork", f"-slot={1 if stratum == 'FI' else 0}", + "-modes=export", "-gameconfig=1", "-coreworldtest=1", + "-ownerfourstrateplan=1", "-corevoxelsizecm=25", "-coreislandtest=0", + "-corefallbacktest=0", "-coreofftest=0", "-coreplantest=0", + "-settingsref=/Game/VoxelForge/DA_Settings.DA_Settings", "-corehybridmesher=0", + f"-out={output}", "-voxel.StreamingCoarseFirst=1", + "-voxel.StreamingDynamicNearReserve=1", + "-voxel.StreamingLegacyPendingResultCap=0", + "-voxel.CoreRegionConcurrentAdmission=1", + "-voxel.StreamingResultBacklogCap=256", + f"-voxel.StreamingReadyQueueDepth={ready_depth}", + f"-voxel.StreamingBackgroundWorkerCap={background_cap}", + f"-voxel.StreamingBackgroundWorkerReserve={worker_reserve}", + f"-voxel.CoreParallelForBackgroundPriority={helper_background}", + f"-voxel.StreamingTileBackgroundLow={tile_background_low}", + f"-voxel.StreamingTileBackgroundNormal={tile_background_normal}", + f"-voxel.TestLogTickFunctions={int(tick_logs)}", + "-voxel.CoreColumnCacheDirectMapped=0", "-voxel.CoreMCGradientMemoization=1", + "-voxel.StreamingCollisionLookahead=1", + f"-voxel.StreamingStartupApplyBoost={startup_boost}", + "-voxel.TestMove=1", "-voxel.TestMoveSpeedCmPerSecond=140.0", + f"-voxel.TestMoveStartSeconds={MOVE_START_S:.1f}", + f"-voxel.TestMoveDurationSeconds={MOVE_DURATION_S:.1f}", + f"-voxel.TestExitSeconds={EXIT_S:.1f}", "-voxel.TestMoveDirection=1,0,0", + "-voxel.StreamingSchedulerPolicy=3", "-voxel.TestExitOnSteady=0", + "-coreworldstreamtrace=1", f"-voxel.StartupTraceSpawnCm={spawn_cm}", + "-voxel.StartupTraceUntilEndPlay=1", "-voxel.StartupTraceThroughCrossing=1", + "-voxel.StartupTraceMaxTiles=16384", f"-voxel.StartupTraceFile={trace}", + f"-abslog={abslog}", + ] + if insights: + command += ["-trace=cpu,task,frame", "-statnamedevents", + f"-tracefile={utrace}", "-tracefiletrunc"] + wrapped = ["taskset", "-c", "0-11", "timeout", f"{RUN_TIMEOUT_S}s", *command] + started = time.monotonic() + with stdout.open("w", encoding="utf-8") as stream: + process = subprocess.Popen(wrapped, cwd=ROOT, stdout=stream, + stderr=subprocess.STDOUT) + peak_rss = None + while process.poll() is None: + observed = sample_unreal_peak_rss() + if observed and (peak_rss is None or observed[0] > peak_rss[0]): + peak_rss = observed + time.sleep(0.25) + exit_code = process.wait() + observed = sample_unreal_peak_rss() + if observed and (peak_rss is None or observed[0] > peak_rss[0]): + peak_rss = observed + + events = read_events(trace) + worker_backend_config = next( + (e for e in events if e.get("type") == "worker_backend_config"), {}) + worker_cap_readback = next( + (e for e in events if e.get("type") == "streaming_worker_cap_readback"), {}) + samples = [e for e in events if e.get("type") == "streaming_sample"] + arrival = [e for e in samples if float(e.get("t_s", 0.0)) < MOVE_START_S] + full = next((e for e in arrival + if sum(e.get("desired_by_lod", [0] * 9)[:3]) > 0 + and sum(e.get("settled_by_lod", [0] * 9)[:3]) + >= sum(e.get("desired_by_lod", [0] * 9)[:3])), None) + first_admission = next((e for e in events if e.get("type") == "scheduler_admission" + and e.get("desired_rebuilt") == 1), None) + request_events = [e for e in events if e.get("type") == "request"] + initial_request_events = [e for e in request_events if e.get("epoch") == 0] + tile_by_ordinal = {e.get("request_ordinal"): e for e in events + if e.get("type") == "tile"} + collision_count = sum(1 for e in events if e.get("type") == "collision_ready" + and e.get("level", 9) <= 2 + and full and e.get("t_s", 1e30) <= full["t_s"]) + initial_tiles = [tile_by_ordinal[r.get("request_ordinal")] for r in initial_request_events + if full and r.get("t_s", 1e30) <= full["t_s"] + and r.get("request_ordinal") in tile_by_ordinal + and tile_by_ordinal[r["request_ordinal"]].get("level", 9) <= 2] + burst_start_s = float(first_admission["t_s"]) if first_admission else -1.0 + burst_end_s = float(full["t_s"]) if full else -1.0 + work_by_frame = {int(e.get("frame", -1)): e for e in events + if e.get("type") == "game_thread_work_frame"} + work_values = [e for e in work_by_frame.values() + if burst_start_s <= float(e.get("t_s", -1.0)) <= burst_end_s] + arrival_frame_ids = {int(e.get("frame", -1)) for e in work_values} + scheduler_by_frame = {int(e.get("frame", -1)): e for e in events + if e.get("type") == "scheduler_admission"} + scheduler_values = [e for e in events if e.get("type") == "scheduler_admission" + and burst_start_s <= float(e.get("t_s", -1.0)) <= burst_end_s] + apply_by_frame = {int(e.get("frame", -1)): e for e in events + if e.get("type") == "apply_frame"} + commandlet_tick_by_frame = {int(e.get("frame", -1)): e for e in events + if e.get("type") == "commandlet_world_tick_frame"} + garbage_collect_by_frame = {int(e.get("frame", -1)): e for e in events + if e.get("type") == "garbage_collect"} + # apply_frame N+1 records the interval containing AVoxelWorld::Tick N. Its apply_ms + # belongs to Tick N+1, so use apply_by_frame[N] for the same-tick apply breakdown. + near_intervals = [apply_by_frame[frame + 1] for frame in arrival_frame_ids + if frame + 1 in apply_by_frame] + rmc_by_frame: dict[int, dict[str, float]] = {} + for event in events: + frame = int(event.get("frame", -1)) + if event.get("type") != "rmc_submit" or frame not in arrival_frame_ids: + continue + values = rmc_by_frame.setdefault(frame, { + "component_acquire_ms": 0.0, + "create_section_group_ms": 0.0, + "create_sections_ms": 0.0, + "collision_handoff_ms": 0.0, + }) + for key in values: + values[key] += float(event.get(key, 0.0)) + collision_completion_by_frame: dict[int, float] = {} + for event in events: + frame = int(event.get("frame", -1)) + if event.get("type") == "collision_completion" and frame in arrival_frame_ids: + collision_completion_by_frame[frame] = collision_completion_by_frame.get(frame, 0.0) \ + + float(event.get("handler_ms", 0.0)) + near_requests = [r for r in request_events if full and r.get("t_s", 1e30) <= full["t_s"] + and r.get("level", 9) <= 2] + initial_lod0_counts = Counter( + tuple(r.get("tile", ())) for r in near_requests if r.get("level") == 0) + repeated_lod0_keys = [ + {"tile": list(tile), "requests": count} + for tile, count in sorted(initial_lod0_counts.items()) if count > 1] + initial_scheduler_frames = [e for e in events + if e.get("type") == "scheduler_admission" and full + and e.get("t_s", 1e30) <= full["t_s"]] + worst_interval = max(near_intervals, key=lambda e: float(e.get("frame_ms", 0.0)), default=None) + worst_interval_frame_id = int(worst_interval.get("frame", -1)) if worst_interval else -1 + worst_work_frame_id = worst_interval_frame_id - 1 + worst_work = work_by_frame.get(worst_work_frame_id, {}) + worst_apply = apply_by_frame.get(worst_work_frame_id, {}) + worst_scheduler = scheduler_by_frame.get(worst_work_frame_id, {}) + worst_rmc = rmc_by_frame.get(worst_work_frame_id, {}) + worst_collision_completion_ms = collision_completion_by_frame.get(worst_work_frame_id, 0.0) + rmc_values = [rmc_by_frame.get(frame, {}) for frame in arrival_frame_ids] + apply_values = [apply_by_frame[frame] for frame in arrival_frame_ids + if frame in apply_by_frame] + commandlet_tick_values = [commandlet_tick_by_frame[frame] for frame in arrival_frame_ids + if frame in commandlet_tick_by_frame] + garbage_collect_values = [garbage_collect_by_frame[frame] for frame in arrival_frame_ids + if frame in garbage_collect_by_frame] + + def work_stat(name: str, fraction: float | None = None) -> float | None: + values = [float(e.get(name, 0.0)) for e in work_values] + return percentile(values, fraction) if fraction is not None else max(values, default=0.0) + + def scheduler_stat(name: str, fraction: float | None = None) -> float | None: + values = [float(e.get(name, 0.0)) for e in scheduler_values] + return percentile(values, fraction) if fraction is not None else max(values, default=0.0) + + def rmc_stat(name: str, fraction: float | None = None) -> float | None: + values = [float(e.get(name, 0.0)) for e in rmc_values] + return percentile(values, fraction) if fraction is not None else max(values, default=0.0) + + def commandlet_stat(name: str, fraction: float | None = None) -> float | None: + values = [float(e.get(name, 0.0)) for e in commandlet_tick_values] + return percentile(values, fraction) if fraction is not None else max(values, default=0.0) + + row = { + "label": label, "stratum": stratum, "repeat": repeat, "phase": phase, + "ready_queue_depth": ready_depth, + "requested_background_worker_cap": background_cap, + "background_worker_cap": worker_cap_readback.get( + "streaming_background_worker_cap", background_cap), + "requested_background_worker_reserve": worker_reserve, + "background_worker_reserve": worker_backend_config.get( + "streaming_background_worker_reserve", worker_cap_readback.get( + "background_worker_reserve", worker_reserve)), + "requested_core_parallel_for_background_priority": helper_background, + "core_parallel_for_background_priority": worker_backend_config.get( + "core_parallel_for_background_priority", helper_background), + "requested_streaming_tile_background_low": tile_background_low, + "streaming_tile_background_low": worker_backend_config.get( + "streaming_tile_background_low", tile_background_low), + "requested_streaming_tile_background_normal": tile_background_normal, + "streaming_tile_background_normal": worker_backend_config.get( + "streaming_tile_background_normal", tile_background_normal), + "effective_tile_slots": worker_backend_config.get("effective_tile_slots"), + "background_worker_threads": worker_backend_config.get("taskgraph_background_threads"), + "startup_apply_boost": startup_boost, "insights": insights, + "engine_tick_logs": tick_logs, + "exit_code": exit_code, + "launch_wrapper": "taskset -c 0-11 timeout 1740s (no address-space limit)", + "peak_rss_kib": peak_rss[0] if peak_rss else None, + "peak_rss_mib": round(peak_rss[0] / 1024.0, 1) if peak_rss else None, + "peak_rss_pid": peak_rss[1] if peak_rss else None, + "endphysics_to_postphysics_gap_ms_max": None, + "endphysics_gap_frame": None, + "wall_s": round(time.monotonic() - started, 3), + "desired_t_s": next((e.get("t_s") for e in events if e.get("type") == "desired_set"), None), + "first_admission_t_s": first_admission.get("t_s") if first_admission else None, + "lod02_full_settled_t_s": full.get("t_s") if full else None, + "near_settle_from_first_admission_s": round( + float(full["t_s"]) - float(first_admission["t_s"]), 4) + if full and first_admission else None, + "desired_by_lod": full.get("desired_by_lod", [])[:3] if full else None, + "settled_by_lod": full.get("settled_by_lod", [])[:3] if full else None, + "near_admitted_tiles": len(near_requests), + "initial_lod0_admissions": sum(initial_lod0_counts.values()), + "repeated_lod0_request_keys_before_settle": repeated_lod0_keys, + "peak_result_backlog_before_settle": max( + (int(e.get("result_backlog", 0)) for e in initial_scheduler_frames), default=0), + "last_admission_t_s": max((e.get("t_s", 0.0) for e in near_requests), default=None), + "near_tile_events": len(initial_tiles), + "near_worker_seconds": round(sum(e.get("worker_task_s", 0.0) for e in initial_tiles), 4), + "near_core_seconds": round(sum(e.get("core_generate_s", 0.0) for e in initial_tiles), 4), + "collision_ready_by_settle": collision_count, + "burst_frame_count": len(near_intervals), + "burst_frame_ms_p95": round(sorted(e.get("frame_ms", 0.0) for e in near_intervals)[ + min(len(near_intervals) - 1, int(.95 * (len(near_intervals) - 1)))], 3) + if near_intervals else None, + "burst_frame_ms_max": round(max((e.get("frame_ms", 0.0) for e in near_intervals), default=0.0), 3), + "burst_full_world_tick_ms_p99": round(commandlet_stat("world_tick_ms", .99) or 0.0, 3), + "burst_full_world_tick_ms_max": round(commandlet_stat("world_tick_ms") or 0.0, 3), + "burst_world_pre_actor_ms_p99": round(commandlet_stat("world_pre_actor_ms", .99) or 0.0, 3), + "burst_world_pre_actor_ms_max": round(commandlet_stat("world_pre_actor_ms") or 0.0, 3), + "burst_world_actor_phase_ms_p99": round(commandlet_stat("world_actor_phase_ms", .99) or 0.0, 3), + "burst_world_actor_phase_ms_max": round(commandlet_stat("world_actor_phase_ms") or 0.0, 3), + "burst_world_post_actor_ms_p99": round(commandlet_stat("world_post_actor_ms", .99) or 0.0, 3), + "burst_world_post_actor_ms_max": round(commandlet_stat("world_post_actor_ms") or 0.0, 3), + "burst_commandlet_readiness_check_ms_max": round( + commandlet_stat("readiness_check_ms") or 0.0, 3), + "burst_commandlet_sleep_ms_p99": round(commandlet_stat("sleep_ms", .99) or 0.0, 3), + "burst_commandlet_sleep_ms_max": round(commandlet_stat("sleep_ms") or 0.0, 3), + "burst_commandlet_loop_ms_max": round(commandlet_stat("loop_ms") or 0.0, 3), + "burst_gc_count": len(garbage_collect_values), + "burst_gc_duration_ms_max": round(max( + (float(e.get("duration_ms", 0.0)) for e in garbage_collect_values), default=0.0), 3), + "burst_max_meshes_per_frame": max((e.get("meshes_applied", 0) for e in apply_values), default=0), + "burst_max_apply_ms": round(max((e.get("apply_ms", 0.0) for e in apply_values), default=0.0), 3), + "burst_max_admit_per_frame": max((sum(e.get("submitted_by_lod", [0] * 9)[:3]) + for e in scheduler_values), default=0), + "burst_frame_timing_count": len(work_values), + "burst_active_generation_workers_p95": round(work_stat("active_generation_workers", .95) or 0.0, 3), + "burst_active_generation_workers_max": round(work_stat("active_generation_workers") or 0.0, 3), + "burst_active_tile_tasks_max": round(work_stat("active_tile_tasks") or 0.0, 3), + "burst_world_tick_ms_p99": round(work_stat("tick_ms", .99) or 0.0, 3), + "burst_world_tick_ms_max": round(work_stat("tick_ms") or 0.0, 3), + "burst_update_chunks_ms_p99": round(work_stat("update_chunks_ms", .99) or 0.0, 3), + "burst_update_chunks_ms_max": round(work_stat("update_chunks_ms") or 0.0, 3), + "burst_pending_drain_ms_p99": round(work_stat("pending_drain_ms", .99) or 0.0, 3), + "burst_pending_drain_ms_max": round(work_stat("pending_drain_ms") or 0.0, 3), + "burst_post_apply_callbacks_ms_p99": round(work_stat("post_apply_callbacks_ms", .99) or 0.0, 3), + "burst_post_apply_callbacks_ms_max": round(work_stat("post_apply_callbacks_ms") or 0.0, 3), + "burst_visibility_reconcile_ms_p99": round(work_stat("visibility_reconcile_ms", .99) or 0.0, 3), + "burst_visibility_reconcile_ms_max": round(work_stat("visibility_reconcile_ms") or 0.0, 3), + "burst_collision_probe_ms_max": round(work_stat("collision_probe_ms") or 0.0, 3), + "burst_visible_apply_probe_ms_max": round(work_stat("visible_apply_probe_ms") or 0.0, 3), + "burst_lod0_ready_ms_max": round(work_stat("lod0_ready_ms") or 0.0, 3), + "burst_steady_trace_ms_max": round(work_stat("steady_trace_ms") or 0.0, 3), + "burst_modification_ms_max": round(work_stat("modification_ms") or 0.0, 3), + "burst_lifecycle_audit_ms_p99": round(work_stat("lifecycle_audit_ms", .99) or 0.0, 3), + "burst_lifecycle_audit_ms_max": round(work_stat("lifecycle_audit_ms") or 0.0, 3), + "burst_collision_gate_ms_p99": round(work_stat("collision_gate_ms", .99) or 0.0, 3), + "burst_collision_gate_ms_max": round(work_stat("collision_gate_ms") or 0.0, 3), + "burst_unload_ms_p99": round(work_stat("unload_ms", .99) or 0.0, 3), + "burst_unload_ms_max": round(work_stat("unload_ms") or 0.0, 3), + "burst_trace_json_ms_p99": round(work_stat("trace_json_ms", .99) or 0.0, 3), + "burst_trace_json_ms_max": round(work_stat("trace_json_ms") or 0.0, 3), + "burst_desired_rebuild_ms_max": round(scheduler_stat("desired_rebuild_ms") or 0.0, 3), + "burst_rmc_create_group_ms_p99": round(rmc_stat("create_section_group_ms", .99) or 0.0, 3), + "burst_rmc_create_group_ms_max": round(rmc_stat("create_section_group_ms") or 0.0, 3), + "burst_rmc_collision_handoff_ms_max": round(rmc_stat("collision_handoff_ms") or 0.0, 3), + "burst_collision_completion_ms_max": round(max( + collision_completion_by_frame.values(), default=0.0), 3), + "worst_frame_breakdown": { + "frame": worst_work_frame_id, + "world_tick_frame": worst_work_frame_id, + "frame_interval_end_frame": worst_interval_frame_id, + "frame_interval_ms": round(float(worst_interval.get("frame_ms", 0.0)), 3) + if worst_interval else None, + "apply_ms": round(float(worst_apply.get("apply_ms", 0.0)), 3) + if worst_apply else None, + "result_drain_ms": round(float(worst_apply.get("drain_ms", 0.0)), 3) + if worst_apply else None, + "outside_world_tick_ms": round(max(0.0, float(worst_interval.get("frame_ms", 0.0)) + - float(worst_work.get("tick_ms", 0.0))), 3) + if worst_interval else None, + "outside_full_world_tick_ms": round(max(0.0, float(worst_interval.get("frame_ms", 0.0)) + - float(commandlet_tick_by_frame.get(worst_work_frame_id, {}).get("world_tick_ms", 0.0))), 3) + if worst_interval else None, + "full_world_tick_ms": round(float(commandlet_tick_by_frame.get( + worst_work_frame_id, {}).get("world_tick_ms", 0.0)), 3), + "world_pre_actor_ms": round(float(commandlet_tick_by_frame.get( + worst_work_frame_id, {}).get("world_pre_actor_ms", 0.0)), 3), + "world_actor_phase_ms": round(float(commandlet_tick_by_frame.get( + worst_work_frame_id, {}).get("world_actor_phase_ms", 0.0)), 3), + "world_post_actor_ms": round(float(commandlet_tick_by_frame.get( + worst_work_frame_id, {}).get("world_post_actor_ms", 0.0)), 3), + "commandlet_readiness_check_ms": round(float(commandlet_tick_by_frame.get( + worst_work_frame_id, {}).get("readiness_check_ms", 0.0)), 3), + "commandlet_sleep_ms": round(float(commandlet_tick_by_frame.get( + worst_work_frame_id, {}).get("sleep_ms", 0.0)), 3), + "commandlet_loop_ms": round(float(commandlet_tick_by_frame.get( + worst_work_frame_id, {}).get("loop_ms", 0.0)), 3), + "gc_duration_ms": round(float(garbage_collect_by_frame.get( + worst_work_frame_id, {}).get("duration_ms", 0.0)), 3), + "world_tick_ms": round(float(worst_work.get("tick_ms", 0.0)), 3), + "active_generation_workers": int(worst_work.get("active_generation_workers", 0)), + "active_tile_tasks": int(worst_work.get("active_tile_tasks", 0)), + "collision_gate_ms": round(float(worst_work.get("collision_gate_ms", 0.0)), 3), + "update_chunks_ms": round(float(worst_work.get("update_chunks_ms", 0.0)), 3), + "desired_rebuild_ms": round(float(worst_scheduler.get("desired_rebuild_ms", 0.0)), 3), + "pending_drain_ms": round(float(worst_work.get("pending_drain_ms", 0.0)), 3), + "post_apply_callbacks_ms": round(float(worst_work.get("post_apply_callbacks_ms", 0.0)), 3), + "collision_probe_ms": round(float(worst_work.get("collision_probe_ms", 0.0)), 3), + "visibility_reconcile_ms": round(float(worst_work.get("visibility_reconcile_ms", 0.0)), 3), + "visible_apply_probe_ms": round(float(worst_work.get("visible_apply_probe_ms", 0.0)), 3), + "lod0_ready_ms": round(float(worst_work.get("lod0_ready_ms", 0.0)), 3), + "unload_ms": round(float(worst_work.get("unload_ms", 0.0)), 3), + "steady_trace_ms": round(float(worst_work.get("steady_trace_ms", 0.0)), 3), + "modification_ms": round(float(worst_work.get("modification_ms", 0.0)), 3), + "lifecycle_audit_ms": round(float(worst_work.get("lifecycle_audit_ms", 0.0)), 3), + "trace_json_ms": round(float(worst_work.get("trace_json_ms", 0.0)), 3), + "trace_archive_serialize_ms": round(float( + worst_work.get("trace_archive_serialize_ms", 0.0)), 3), + "collision_completion_ms": round(worst_collision_completion_ms, 3), + **{key: round(float(worst_rmc.get(key, 0.0)), 3) + for key in ("component_acquire_ms", "create_section_group_ms", + "create_sections_ms", "collision_handoff_ms")}, + }, + "trace": str(trace.relative_to(ROOT)), "utrace": str(utrace.relative_to(ROOT)), + "abslog": str(abslog.relative_to(ROOT)), "stdout": str(stdout.relative_to(ROOT)), + } + stdout_text = stdout.read_text(encoding="utf-8", errors="replace") + gap_ms, gap_frame = endphysics_gap(stdout) + row["endphysics_to_postphysics_gap_ms_max"] = gap_ms + row["endphysics_gap_frame"] = gap_frame + failure = re.search(r"\[VoxelForgeCoreWorldTest\] failed: ([^\r\n]+)", stdout_text) + if failure: + row["world_test_failure"] = failure.group(1) + with (OUT / "runs.jsonl").open("a", encoding="utf-8") as stream: + stream.write(json.dumps(row, sort_keys=True) + "\n") + (OUT / f"{label}.summary.json").write_text(json.dumps(row, indent=2) + "\n", + encoding="utf-8") + print("[L102UnrealArrival] " + json.dumps(row, sort_keys=True), flush=True) + if exit_code: + raise SystemExit(f"Unreal commandlet failed: {stdout}; exit={exit_code}") + if not full or len(arrival) < 8: + raise SystemExit(f"Unreal arrival trace incomplete: {stdout}; exit={exit_code}") + if insights and (not utrace.is_file() or utrace.stat().st_size < 1024): + raise SystemExit(f"Unreal Insights trace missing or empty: {utrace}") + return row + + +def main() -> int: + parser = argparse.ArgumentParser() + parser.add_argument("--stratum", choices=("FI", "SW"), required=True) + parser.add_argument("--repeat", type=int, default=1) + parser.add_argument("--phase", choices=("probe", "before", "after", "snapshot"), default="probe") + parser.add_argument("--ready-depth", type=int, default=64) + parser.add_argument("--background-cap", type=int, choices=(0, 1), default=1) + parser.add_argument("--worker-reserve", type=int, choices=(0, 1, 2, 3), default=0) + parser.add_argument("--helper-background", type=int, choices=(0, 1), default=1) + parser.add_argument("--tile-background-low", type=int, choices=(0, 1), default=1) + parser.add_argument("--tile-background-normal", type=int, choices=(0, 1), default=0) + parser.add_argument("--startup-boost", type=int, choices=(0, 1), default=1) + parser.add_argument("--tick-logs", action="store_true") + parser.add_argument("--insights", action="store_true") + args = parser.parse_args() + if not EDITOR.is_file(): + raise SystemExit(f"missing Unreal commandlet executable: {EDITOR}") + run(args.stratum, args.repeat, args.phase, args.ready_depth, + args.background_cap, args.worker_reserve, args.helper_background, + args.tile_background_low, args.tile_background_normal, args.startup_boost, + args.tick_logs, args.insights) + return 0 + + +if __name__ == "__main__": + raise SystemExit(main())