From a7820c868f1380003bcec770a572c5ddb9519662 Mon Sep 17 00:00:00 2001 From: Erik Thorelli Date: Thu, 15 Oct 2026 17:54:01 -0700 Subject: [PATCH 1/4] feat(booth): soak test and frame-rate probe for long unattended runs [Agent: Claude Code | Model: Opus 5.5 | Thinking: High | Acting on behalf of: Erik | Skill: none] Nothing shows whether the build survives a show day unattended, or what frame rate it holds on the booth hardware. - --soak= (app/booth_soak.gd) visits every AppRouter route in turn for --soak-dwell seconds (default 30) with nobody playing. Every 5 s it appends a CSV row: route, frames per second, median, p99 and worst frame times, static and video memory, objects, nodes, orphan nodes and resources. Frames on a route's first second, or during a route change, count as loading hitches instead. - At the end it prints and saves a frame-rate table per route (p50, p95, p99, max, share of frames over 16.7 and 33.3 ms) from bounded histograms, the worst loading hitch, and a leak check: counts at the hub from the second visit to the last (the first warms caches), with small limits. It exits 0 when steady and 1 when they kept growing. It announces each pass ("SOAK cycle N"). - A soak turns off the idle return and the game-over card, ignores --route and writes no session log, so its visits never count as booth sessions. It keeps the heartbeat, so it can run under the watchdog. - tools/booth/soak.py runs a build or this checkout's project with --soak, samples resident memory with ps (release builds can't report their own), and fails when it grew more than 25% from the start of the second pass, once a third has begun. It stops a run that outlasts its time and collects the CSV, summary, game.log and rss.csv. - docs/builds.md gains "Soak test and frame rate". - Tests: tests/booth_soak.gd (parsing, percentile and leak-check math, and a short real soak in a bounded child), tools/booth/test_soak.py (argument passing, RSS sampling, warm-up versus growth, the three-pass rule, split log lines, the timeout, usage errors). --- docs/builds.md | 14 + hoppys-adventure-arcade/app/app_router.gd | 23 +- hoppys-adventure-arcade/app/booth_soak.gd | 263 ++++++++++++++++++ hoppys-adventure-arcade/app/booth_soak.gd.uid | 1 + hoppys-adventure-arcade/tests/booth_soak.gd | 89 ++++++ .../tests/booth_soak.gd.uid | 1 + tools/booth/soak.py | 142 ++++++++++ tools/booth/test_soak.py | 143 ++++++++++ 8 files changed, 670 insertions(+), 6 deletions(-) create mode 100644 hoppys-adventure-arcade/app/booth_soak.gd create mode 100644 hoppys-adventure-arcade/app/booth_soak.gd.uid create mode 100644 hoppys-adventure-arcade/tests/booth_soak.gd create mode 100644 hoppys-adventure-arcade/tests/booth_soak.gd.uid create mode 100644 tools/booth/soak.py create mode 100644 tools/booth/test_soak.py diff --git a/docs/builds.md b/docs/builds.md index 9b124fc2..5041f29f 100644 --- a/docs/builds.md +++ b/docs/builds.md @@ -47,6 +47,20 @@ python3 tools/booth/sessions_report.py booth/ # se python3 tools/booth/sessions_report.py booth-a/ booth-b/ --csv sessions.csv # combine machines; one CSV row per session ``` +## Soak test and frame rate + +Before a show, let the build run unattended on the booth machine for a full show day: + +```sh +python3 tools/booth/soak.py --minutes 600 -- "/Applications/Hoppy’s Adventure Arcade.app/Contents/MacOS/" -- --booth +python3 tools/booth/soak.py --minutes 10 --godot "$GODOT" # a quick run of this checkout's project +``` + +- **The soak.** The game runs with `--soak=`. It visits every route in turn and stays `--soak-dwell=` (default 30) on each with nobody playing. A soak turns off the idle return and the game-over card, ignores `--route`, and writes no session log, so its visits never count as booth sessions. +- **Frame rate.** Every 5 seconds the game appends a CSV row: the route, frames per second, median, 99th-percentile and worst frame times, and the engine's memory and object counts. At the end it prints a table per route with the share of frames slower than 16.7 ms (60 fps) and 33.3 ms (30 fps), plus the worst loading hitch. Run it fullscreen (`--booth`) on the booth hardware to measure at the booth resolution; headless frame times mean nothing. +- **Leak check.** The game compares its object, node, orphan-node and resource counts at the hub from the second visit to the last; the first visit warms caches. Debug builds also compare static memory, which release builds don't report. Growth beyond small limits makes the game exit 1. +- **Resident memory.** `soak.py` samples the process's memory with `ps` every 30 seconds (`--rss-every`). The first pass over the routes loads everything once, so the check runs from the start of the second pass to the end, once a third pass has begun, and fails if memory grew more than 25% (`--max-rss-growth`). It stops a run that outlasts its time by 10 minutes (`--grace`). Results land in `soak-results/` (`--out`): the game's CSV and summary, `game.log` and `rss.csv`. macOS and Linux. + ## Build locally ```sh diff --git a/hoppys-adventure-arcade/app/app_router.gd b/hoppys-adventure-arcade/app/app_router.gd index fecfeab9..2efa0317 100644 --- a/hoppys-adventure-arcade/app/app_router.gd +++ b/hoppys-adventure-arcade/app/app_router.gd @@ -2,6 +2,7 @@ extends CanvasLayer const BoothLog := preload("res://app/booth_log.gd") const BoothHeartbeat := preload("res://app/booth_heartbeat.gd") const NextPlayerCard := preload("res://app/next_player_card.gd") +const BoothSoak := preload("res://app/booth_soak.gd") const ROUTES := { "heroes_vs_villains": "res://scenes/beatem_up/reinvent/heroes_vs_villains.tscn", "code_city_brawl": "res://scenes/beatem_up/code_city_brawl.tscn", @@ -61,6 +62,8 @@ var retry_limit := 0 var game_overs := 0 var next_player: NextPlayerCard var next_player_left := 0.0 +## The soak test (app/booth_soak.gd), when the game was launched with `--soak=`. +var soak: BoothSoak func _ready() -> void: # The veil tween must keep running while a microgame has the tree paused. process_mode = Node.PROCESS_MODE_ALWAYS @@ -81,14 +84,22 @@ func _ready() -> void: set_booth(BOOTH_FLAG in args) if booth: print("AppRouter: booth attract route %s, %d retries per player" % [attract, retry_limit]) - var log_path := session_log_path(args, booth) - if log_path != "": - start_session_log(log_path) var beat_path := heartbeat_path(args) if beat_path != "": heartbeat = BoothHeartbeat.new(beat_path) add_child(heartbeat) print("AppRouter: heartbeat at %s" % ProjectSettings.globalize_path(beat_path)) + var soak_minutes := BoothSoak.minutes_from(args) + if soak_minutes > 0.0: + # The soak changes routes itself: no idle return, no launch route, no next-player card, + # and no session log, so its visits never count as booth sessions. + idle_limit = INF + soak = BoothSoak.new(soak_minutes, args) + add_child(soak) + return + var log_path := session_log_path(args, booth) + if log_path != "": + start_session_log(log_path) var start := launch_route(args) if start != "": _launch.call_deferred(start) @@ -195,13 +206,13 @@ static func retry_count(args: PackedStringArray) -> int: ## Games call this when the player loses, before showing their own retry screen. Returns true when ## the booth takes over: the player has used their retries, so the game shows nothing and the ## router thanks them and sends the booth to the attract route. Always false outside booth mode, -## and while a route change is already under way (it takes the player elsewhere anyway). The -## session log counts every game over, booth or not. +## while a route change is already under way (it takes the player elsewhere anyway), and during a +## soak, which changes routes itself. The session log counts every game over, booth or not. ## `score_line` is shown on the card, in the game's own style ("SCORE 01234"). func booth_game_over(score_line := "") -> bool: if session_log: session_log.count_game_over() - if not booth or busy: + if not booth or busy or soak != null: return false game_overs += 1 if game_overs <= retry_limit: diff --git a/hoppys-adventure-arcade/app/booth_soak.gd b/hoppys-adventure-arcade/app/booth_soak.gd new file mode 100644 index 00000000..59beec6f --- /dev/null +++ b/hoppys-adventure-arcade/app/booth_soak.gd @@ -0,0 +1,263 @@ +extends Node +## Soak test and frame-rate probe for long unattended runs: ` -- --soak=`. The game +## visits every AppRouter route in turn and stays `--soak-dwell=` (default 30) on each with +## nobody playing, for the given minutes. Every SAMPLE_SECONDS it appends a CSV row: the route, the +## frame rate and frame times, and the engine's memory and object counts. At the end it prints a +## frame-rate table per route and a leak check, writes both next to the CSV in `--soak-log=` +## (default user://soak), and quits: 0 when the counts held steady, 1 when they kept growing. +## Run it rendered and fullscreen on the booth machine for frame rates at the booth resolution; +## headless runs measure only the leak check. tools/booth/soak.py wraps a run and adds the +## process's resident memory, which release builds can't report from inside. +const MINUTES_PREFIX := "--soak=" +const DWELL_PREFIX := "--soak-dwell=" +const FOLDER_PREFIX := "--soak-log=" +const DEFAULT_DWELL := 30.0 +const DEFAULT_FOLDER := "user://soak" +const SAMPLE_SECONDS := 5.0 +## Frames this soon after a route opens are loading, not play: they count as load hitches. +const SETTLE_SECONDS := 1.0 +## Frame-time histogram: BUCKET_MS wide buckets up to BUCKETS * BUCKET_MS, then one overflow bucket. +const BUCKET_MS := 0.5 +const BUCKETS := 200 +## The leak check needs this many visits to the hub: the first warms caches and is not compared. +const MIN_CYCLES := 3 +## Growth from the second hub visit to the last that counts as a leak: [absolute, fraction]. +const LIMITS := {"objects": [500, 0.05], "nodes": [100, 0.0], "orphan_nodes": [20, 0.0], + "resources": [50, 0.1], "static_mb": [32.0, 0.1]} +const COLUMNS := ["elapsed_s", "cycle", "route", "frames", "fps", "frame_p50_ms", "frame_p99_ms", + "frame_max_ms", "static_mb", "video_mb", "objects", "nodes", "orphan_nodes", "resources"] + +var minutes := 0.0 +var dwell := DEFAULT_DWELL +var folder := DEFAULT_FOLDER +var csv_path := "" +var summary_path := "" +var router: Node +var routes: Array[String] = [] +var index := -1 +var cycle := 0 +var elapsed := 0.0 +var on_route := 0.0 +var since_sample := 0.0 +var last_usec := 0 +var window: PackedFloat32Array = [] +## Per route: {"histogram": PackedInt32Array, "frames": int, "ms": total frame time, "max": float}. +var stats := {} +var load_hitch := {"ms": 0.0, "route": ""} +## Engine counts at the end of each hub visit, for the leak check. +var hub_snapshots: Array[Dictionary] = [] +var finished := false + +## The soak length from `--soak=`, or 0.0 when absent or not a positive number. +static func minutes_from(args: PackedStringArray) -> float: + for arg in args: + if arg.begins_with(MINUTES_PREFIX): + var value := arg.trim_prefix(MINUTES_PREFIX) + if value.is_valid_float() and value.to_float() > 0.0: + return value.to_float() + push_warning("--soak needs a positive number of minutes, not %s; no soak" % value) + return 0.0 + +func _init(soak_minutes: float, args: PackedStringArray) -> void: + name = "BoothSoak" + process_mode = Node.PROCESS_MODE_ALWAYS + minutes = soak_minutes + for arg in args: + if arg.begins_with(DWELL_PREFIX) and arg.trim_prefix(DWELL_PREFIX).is_valid_float(): + dwell = maxf(0.2, arg.trim_prefix(DWELL_PREFIX).to_float()) + elif arg.begins_with(FOLDER_PREFIX) and arg.length() > FOLDER_PREFIX.length(): + folder = arg.trim_prefix(FOLDER_PREFIX) + +func _ready() -> void: + router = get_parent() + routes.assign(router.ROUTES.keys()) + if not DirAccess.dir_exists_absolute(folder): + DirAccess.make_dir_recursive_absolute(folder) + # The process id keeps two soaks started in the same second apart. + var stamp := "%s-%d" % [Time.get_datetime_string_from_system().replace(":", "-"), + OS.get_process_id()] + csv_path = folder.path_join("soak-%s.csv" % stamp) + summary_path = folder.path_join("soak-%s-summary.txt" % stamp) + _append(",".join(COLUMNS)) + print("SOAK %s min, %s s per route, %d routes; samples to %s" % [minutes, dwell, routes.size(), + ProjectSettings.globalize_path(csv_path)]) + last_usec = Time.get_ticks_usec() + _next_route() + +func _process(delta: float) -> void: + if finished: + return + var now := Time.get_ticks_usec() + var span := (now - last_usec) / 1000.0 + last_usec = now + elapsed += delta + if router.busy or on_route < SETTLE_SECONDS: + if span > load_hitch.ms: + load_hitch = {"ms": span, "route": _route()} + else: + _count(span) + on_route += delta + since_sample += delta + if since_sample >= SAMPLE_SECONDS: + _sample() + if elapsed >= minutes * 60.0: + _finish() + elif on_route >= dwell and not router.busy: + if _route() == "hub": + hub_snapshots.append(_counts()) + _next_route() + +func _route() -> String: + return routes[index] if index >= 0 else "" + +func _next_route() -> void: + index = (index + 1) % routes.size() + if index == 0: + cycle += 1 + # tools/booth/soak.py times its memory check from these lines. + print("SOAK cycle %d at %.1f s" % [cycle, elapsed]) + on_route = 0.0 + router.go(routes[index]) + +func _count(span: float) -> void: + window.append(span) + var route := _route() + if not stats.has(route): + var histogram := PackedInt32Array() + histogram.resize(BUCKETS + 1) + stats[route] = {"histogram": histogram, "frames": 0, "ms": 0.0, "max": 0.0} + var entry: Dictionary = stats[route] + entry.histogram[mini(int(span / BUCKET_MS), BUCKETS)] += 1 + entry.frames += 1 + entry.ms += span + entry.max = maxf(entry.max, span) + +func _counts() -> Dictionary: + return { + "static_mb": Performance.get_monitor(Performance.MEMORY_STATIC) / 1048576.0, + "video_mb": Performance.get_monitor(Performance.RENDER_VIDEO_MEM_USED) / 1048576.0, + "objects": int(Performance.get_monitor(Performance.OBJECT_COUNT)), + "nodes": int(Performance.get_monitor(Performance.OBJECT_NODE_COUNT)), + "orphan_nodes": int(Performance.get_monitor(Performance.OBJECT_ORPHAN_NODE_COUNT)), + "resources": int(Performance.get_monitor(Performance.OBJECT_RESOURCE_COUNT)), + } + +func _sample() -> void: + var sorted := window.duplicate() + sorted.sort() + var frames := sorted.size() + var total_ms := 0.0 + for span in sorted: + total_ms += span + var counts := _counts() + _append(",".join(PackedStringArray([ + "%.1f" % elapsed, str(cycle), _route(), str(frames), + "%.1f" % (1000.0 * frames / total_ms if total_ms > 0.0 else 0.0), + "%.2f" % (sorted[int(frames * 0.5)] if frames else 0.0), + "%.2f" % (sorted[mini(frames - 1, int(frames * 0.99))] if frames else 0.0), + "%.2f" % (sorted[frames - 1] if frames else 0.0), + "%.1f" % counts.static_mb, "%.1f" % counts.video_mb, str(counts.objects), str(counts.nodes), + str(counts.orphan_nodes), str(counts.resources)]))) + window.clear() + since_sample = 0.0 + +## The frame time (ms) below which `share` of a route's frames fall, to the bucket's upper edge. +static func percentile(histogram: PackedInt32Array, frames: int, share: float) -> float: + var target := ceili(frames * share) + var seen := 0 + for i in histogram.size(): + seen += histogram[i] + if seen >= target: + return (i + 1) * BUCKET_MS + return BUCKETS * BUCKET_MS + +## Frames slower than `ms`, as a share of all of the route's frames. +static func slower_than(histogram: PackedInt32Array, frames: int, ms: float) -> float: + var slow := 0 + for i in range(int(ms / BUCKET_MS), histogram.size()): + slow += histogram[i] + return float(slow) / maxf(1.0, frames) + +## The leak check's findings: "" when steady or too few to compare, else what kept growing. +static func growth(snapshots: Array[Dictionary]) -> String: + if snapshots.size() < 2: + return "" + var first := snapshots[1] + var last := snapshots[snapshots.size() - 1] + var grew := PackedStringArray() + for key: String in LIMITS: + var before := float(first[key]) + var change := float(last[key]) - before + if key == "static_mb" and before <= 0.0: + continue # Release builds don't report static memory. + if change > maxf(LIMITS[key][0], before * LIMITS[key][1]): + var shape := "%s %.1f -> %.1f" if key == "static_mb" else "%s %d -> %d" + grew.append(shape % [key, first[key], last[key]]) + return ", ".join(grew) + +func _finish() -> void: + finished = true + if since_sample > 0.0: + _sample() + if _route() == "hub": + hub_snapshots.append(_counts()) + var size := DisplayServer.window_get_size() + var lines := PackedStringArray() + lines.append("SOAK %.1f min, %d cycles, window %dx%d, vsync %s, %s" % [elapsed / 60.0, cycle, + size.x, size.y, "off" if DisplayServer.window_get_vsync_mode() == DisplayServer.VSYNC_DISABLED + else "on", DisplayServer.get_name()]) + lines.append("SOAK %-20s %7s %6s %7s %7s %7s %7s %8s %8s" % ["route", "frames", "fps", "p50 ms", + "p95 ms", "p99 ms", "max ms", ">16.7ms", ">33.3ms"]) + for route in routes: + if not stats.has(route): + continue + var entry: Dictionary = stats[route] + var frames: int = entry.frames + var top: float = entry.max + lines.append("SOAK %-20s %7d %6.1f %7.1f %7.1f %7.1f %7.1f %7.1f%% %7.1f%%" % [route, frames, + 1000.0 * frames / maxf(entry.ms, 0.001), + minf(top, percentile(entry.histogram, frames, 0.5)), + minf(top, percentile(entry.histogram, frames, 0.95)), + minf(top, percentile(entry.histogram, frames, 0.99)), top, + 100.0 * slower_than(entry.histogram, frames, 16.7), + 100.0 * slower_than(entry.histogram, frames, 33.3)]) + lines.append("SOAK worst load hitch: %.0f ms (%s)" % [load_hitch.ms, load_hitch.route]) + var verdict := "too short to judge: %d hub visits, needs %d" % [hub_snapshots.size(), MIN_CYCLES] + var code := 0 + if hub_snapshots.size() >= MIN_CYCLES: + var first := hub_snapshots[1] + var last := hub_snapshots[hub_snapshots.size() - 1] + for key in ["objects", "nodes", "orphan_nodes", "resources"]: + lines.append("SOAK %-13s %8d -> %8d (hub, visit 2 -> %d)" % [key, first[key], last[key], + hub_snapshots.size()]) + lines.append("SOAK static memory %s" % ("%.1f MB -> %.1f MB" % [first.static_mb, + last.static_mb] if first.static_mb > 0.0 else "not reported by release builds")) + var grew := growth(hub_snapshots) + verdict = "steady" if grew == "" else "GROWING: " + grew + code = 0 if grew == "" else 1 + lines.append("SOAK verdict: " + verdict) + var text := "\n".join(lines) + print(text) + var file := FileAccess.open(summary_path, FileAccess.WRITE) + if file: + file.store_string(text + "\n") + file.close() + print("SOAK summary at %s" % ProjectSettings.globalize_path(summary_path)) + router.go("hub") + await get_tree().create_timer(1.0, true).timeout + get_tree().unload_current_scene() + # By path: suites preload this script before autoloads exist. + get_node(^"/root/AudioService").shutdown() + await get_tree().create_timer(0.4, true).timeout + get_tree().quit(code) + +func _append(line: String) -> void: + var file := FileAccess.open(csv_path, FileAccess.READ_WRITE if FileAccess.file_exists(csv_path) + else FileAccess.WRITE) + if file == null: + push_warning("Soak: cannot write %s (%s)" % [csv_path, + error_string(FileAccess.get_open_error())]) + return + file.seek_end() + file.store_line(line) + file.close() diff --git a/hoppys-adventure-arcade/app/booth_soak.gd.uid b/hoppys-adventure-arcade/app/booth_soak.gd.uid new file mode 100644 index 00000000..f1e051f6 --- /dev/null +++ b/hoppys-adventure-arcade/app/booth_soak.gd.uid @@ -0,0 +1 @@ +uid://blbs4eo3800rk diff --git a/hoppys-adventure-arcade/tests/booth_soak.gd b/hoppys-adventure-arcade/tests/booth_soak.gd new file mode 100644 index 00000000..ad829353 --- /dev/null +++ b/hoppys-adventure-arcade/tests/booth_soak.gd @@ -0,0 +1,89 @@ +extends SceneTree +## Soak test (app/booth_soak.gd): --soak parsing, the frame-time math and the leak check on fixed +## numbers, then a short real soak in a child process at a fixed 60 fps. It must visit every route, +## write CSV samples and a summary with a frame-rate row per route, judge three hub visits as +## steady, and exit 0. Run headless with --script res://tests/booth_soak.gd. +const BoothSoak := preload("res://app/booth_soak.gd") +const ChildGame := preload("res://tests/support/child_game.gd") +const FOLDER := "user://test_soak" +var failures := 0 + +func _initialize() -> void: + call_deferred("run") + +func check(ok: bool, message: String) -> void: + print("PASS: " if ok else "FAIL: ", message) + if not ok: + failures += 1 + +func counts(nodes: int, static_mb := 0.0) -> Dictionary: + return {"objects": 3000, "nodes": nodes, "orphan_nodes": 0, "resources": 600, + "static_mb": static_mb, "video_mb": 0.0} + +func clean() -> void: + var dir := DirAccess.open(FOLDER) + if dir == null: + return + for file_name in dir.get_files(): + dir.remove(file_name) + DirAccess.remove_absolute(FOLDER) + +func run() -> void: + clean() + check(BoothSoak.minutes_from(PackedStringArray()) == 0.0, "No --soak, no soak") + check(is_equal_approx(BoothSoak.minutes_from(PackedStringArray(["--soak=480"])), 480.0), + "--soak sets the minutes") + check(BoothSoak.minutes_from(PackedStringArray(["--soak=0"])) == 0.0 + and BoothSoak.minutes_from(PackedStringArray(["--soak=long"])) == 0.0, + "A zero or non-numeric --soak runs no soak") + + var histogram := PackedInt32Array() + histogram.resize(BoothSoak.BUCKETS + 1) + histogram[33] = 90 # 16.5-17 ms + histogram[80] = 10 # 40-40.5 ms + check(is_equal_approx(BoothSoak.percentile(histogram, 100, 0.5), 17.0) + and is_equal_approx(BoothSoak.percentile(histogram, 100, 0.95), 40.5), + "Percentiles come from the frame-time histogram") + check(is_equal_approx(BoothSoak.slower_than(histogram, 100, 33.3), 0.1), + "The share of frames slower than 33.3 ms is counted") + + var steady: Array[Dictionary] = [counts(400), counts(69), counts(70), counts(69)] + check(BoothSoak.growth(steady) == "", "Counts that hold steady pass (the first visit is ignored)") + var leaking: Array[Dictionary] = [counts(69), counts(69), counts(400), counts(900)] + check(BoothSoak.growth(leaking).begins_with("nodes 69 -> 900"), "Nodes that keep growing fail") + var memory: Array[Dictionary] = [counts(69, 300.0), counts(69, 300.0), counts(69, 420.0)] + check(BoothSoak.growth(memory).begins_with("static_mb 300.0 -> 420.0"), + "Static memory that keeps growing fails when the build reports it") + + var child: Dictionary = await ChildGame.run(self, ["--fixed-fps", "60", "--", "--soak=0.8", + "--soak-dwell=1.5", "--soak-log=" + ProjectSettings.globalize_path(FOLDER)], 300.0) + var text_out: String = child.log + check(child.code == 0, "A short soak exits 0 (exit %d)" % child.code) + var routes: Array = root.get_node("AppRouter").ROUTES.keys() + var missing := [] + for route: String in routes: + if not RegEx.create_from_string("(?m)^SOAK %s +\\d+" % route).search(text_out): + missing.append(route) + check(missing.is_empty(), + "The frame-rate table has a row for every route (missing %s)" % [missing]) + check(text_out.contains("SOAK verdict: steady"), "Three or more hub visits are judged steady") + var csv := "" + var summary := "" + var dir := DirAccess.open(FOLDER) + if dir != null: + for file_name in dir.get_files(): + var text := FileAccess.get_file_as_string(FOLDER.path_join(file_name)) + if file_name.ends_with("-summary.txt"): + summary = text + elif file_name.ends_with(".csv"): + csv = text + var rows := csv.strip_edges().split("\n") + check(rows.size() > 3 and rows[0] == ",".join(BoothSoak.COLUMNS), + "The CSV has the documented columns and a row per sample") + check(summary.contains("SOAK verdict: steady") and summary.contains("SOAK worst load hitch"), + "The summary file holds the table and the verdict") + + clean() + await root.get_node("AudioService").settle() + print("Booth soak failures: ", failures) + quit(1 if failures else 0) diff --git a/hoppys-adventure-arcade/tests/booth_soak.gd.uid b/hoppys-adventure-arcade/tests/booth_soak.gd.uid new file mode 100644 index 00000000..8b753040 --- /dev/null +++ b/hoppys-adventure-arcade/tests/booth_soak.gd.uid @@ -0,0 +1 @@ +uid://chmv4v846e830 diff --git a/tools/booth/soak.py b/tools/booth/soak.py new file mode 100644 index 00000000..ad2e8b48 --- /dev/null +++ b/tools/booth/soak.py @@ -0,0 +1,142 @@ +"""Run a soak test of the game and watch its memory from outside. + +Usage: + python3 tools/booth/soak.py --minutes 480 -- "" -- --booth # a build, fullscreen + python3 tools/booth/soak.py --minutes 10 --godot "$GODOT" # this checkout's project + +The game runs with --soak= (hoppys-adventure-arcade/app/booth_soak.gd). It visits every +route in turn, writes frame times and engine counts to a CSV, prints a frame-rate table per route +and a leak check, and exits 0 (steady) or 1 (counts kept growing). Release builds can't report +their own memory, so this wrapper samples the process's resident memory with `ps` into rss.csv. +The first pass over the routes loads everything once, so memory is compared from the start of the +second pass (the game prints "SOAK cycle 2") to the end, and only once a third pass has begun. The +run fails when it grew by more than --max-rss-growth percent. A run that outlasts --minutes by +--grace minutes is stopped and fails. +Everything lands in --out: the game's CSV and summary, game.log and rss.csv. macOS and Linux. +Standard library only. +""" +from __future__ import annotations + +import argparse +import re +import subprocess +import sys +import time +from pathlib import Path + +PROJECT = Path(__file__).resolve().parents[2] / "hoppys-adventure-arcade" +CYCLE = re.compile(r"^SOAK cycle (\d+)\b") + + +def rss_mb(pid: int) -> float | None: + """The process's resident memory in MB, or None when ps can't see it. Under 1 MB the process is + still starting (forked, not yet the game), so that reading is skipped too.""" + try: + out = subprocess.run(["ps", "-o", "rss=", "-p", str(pid)], capture_output=True, text=True, timeout=10).stdout + kilobytes = int(out.strip()) + except (OSError, ValueError, subprocess.TimeoutExpired): + return None + return kilobytes / 1024.0 if kilobytes >= 1024 else None + + +def game_command(args: argparse.Namespace, out: Path) -> list[str]: + """The game's command line, with the soak's user arguments after its "--".""" + command = [args.godot, "--path", str(PROJECT)] if args.godot else list(args.command) + if "--" not in command[1:]: + command.append("--") + command += [f"--soak={args.minutes:g}", f"--soak-dwell={args.dwell:g}", f"--soak-log={out.resolve()}"] + return command + + +def rss_verdict(samples: list[tuple[float, float]], cycles: dict[int, float], limit: float) -> tuple[str, bool]: + """Compare memory when the second pass began with the last sample: (message, grew too much). + `cycles` maps each pass the game announced to the run time it began at.""" + if 3 not in cycles: + return f"RSS: {len(cycles)} pass(es) over the routes, needs 3 to judge", False + after = [rss for elapsed, rss in samples if elapsed >= cycles[2]] + if len(after) < 2: + return f"RSS: {len(after)} sample(s) after the first pass, too few to judge", False + reference, last = after[0], after[-1] + growth = 100.0 * (last - reference) / reference + message = f"RSS: {reference:.0f} MB -> {last:.0f} MB ({growth:+.1f}%, limit {limit:g}%)" + return message, growth > limit + + +def main(argv: list[str] | None = None) -> int: + parser = argparse.ArgumentParser(description=__doc__.splitlines()[0], + usage="%(prog)s --minutes M [options] (--godot GODOT | -- GAME [ARGS ...])") + parser.add_argument("--minutes", type=float, required=True, help="how long the game soaks") + parser.add_argument("--dwell", type=float, default=30.0, help="seconds on each route (default 30)") + parser.add_argument("--out", type=Path, default=Path("soak-results"), help="results folder (default soak-results)") + parser.add_argument("--godot", help="run this checkout's project with this Godot instead of a build") + parser.add_argument("--rss-every", type=float, default=30.0, help="seconds between memory samples (default 30)") + parser.add_argument("--max-rss-growth", type=float, default=25.0, help="percent RSS growth that fails the run (default 25)") + parser.add_argument("--grace", type=float, default=10.0, help="minutes past --minutes before the run is stopped (default 10)") + # Everything after the first "--" is the game's command line, which can hold its own "--". + argv = sys.argv[1:] if argv is None else argv + split = argv.index("--") if "--" in argv else len(argv) + args = parser.parse_args(argv[:split]) + args.command = argv[split + 1:] + if args.minutes <= 0 or args.dwell <= 0 or args.rss_every <= 0: + parser.error("--minutes, --dwell and --rss-every must be positive") + if bool(args.godot) == bool(args.command): + parser.error("pass either --godot or a game command after --") + args.out.mkdir(parents=True, exist_ok=True) + command = game_command(args, args.out) + print("soak: " + " ".join(command)) + deadline = time.monotonic() + (args.minutes + args.grace) * 60.0 + samples: list[tuple[float, float]] = [] + cycles: dict[int, float] = {} + pending = "" + with (args.out / "game.log").open("w", encoding="utf-8") as log, (args.out / "rss.csv").open("w", encoding="utf-8") as rss, \ + (args.out / "game.log").open(encoding="utf-8", errors="replace") as tail: + rss.write("elapsed_s,rss_mb\n") + try: + game = subprocess.Popen(command, stdout=log, stderr=subprocess.STDOUT) + except OSError as error: + print(f"soak: cannot start the game: {error}", file=sys.stderr) + return 2 + started = time.monotonic() + next_sample = started + timed_out = False + while game.poll() is None: + now = time.monotonic() + if now >= deadline: + timed_out = True + game.kill() + game.wait() + break + # Whole lines only: a read can stop partway through one. + pending += tail.read() + *lines, pending = pending.split("\n") + for line in lines: + if match := CYCLE.match(line): + cycles.setdefault(int(match.group(1)), now - started) + if now >= next_sample: + memory = rss_mb(game.pid) + if memory is not None: + samples.append((now - started, memory)) + rss.write(f"{now - started:.1f},{memory:.1f}\n") + rss.flush() + next_sample = now + args.rss_every + time.sleep(min(0.2, args.rss_every)) + report = [line for line in (args.out / "game.log").read_text(encoding="utf-8", errors="replace").splitlines() + if line.startswith("SOAK ")] + print("\n".join(report) if report else "soak: the game printed no SOAK lines; see game.log") + message, grew = rss_verdict(samples, cycles, args.max_rss_growth) + print(f"soak: {message}") + if timed_out: + print(f"soak: the game ran past {args.minutes:g} + {args.grace:g} minutes and was stopped", file=sys.stderr) + return 2 + if game.returncode != 0: + print(f"soak: the game exited with status {game.returncode}", file=sys.stderr) + return 1 + if grew: + print("soak: resident memory kept growing", file=sys.stderr) + return 1 + print(f"soak: passed; results in {args.out}") + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/tools/booth/test_soak.py b/tools/booth/test_soak.py new file mode 100644 index 00000000..c460c527 --- /dev/null +++ b/tools/booth/test_soak.py @@ -0,0 +1,143 @@ +"""Tests for soak.py, run against a stand-in game. Run: python3 -m unittest discover -s tools/booth -v""" +from __future__ import annotations + +import io +import json +import sys +import tempfile +import unittest +from contextlib import redirect_stderr, redirect_stdout +from pathlib import Path + +sys.path.insert(0, str(Path(__file__).resolve().parent)) +import soak # noqa: E402 + +# Records its arguments, announces passes over the routes like the game, then behaves as its first +# argument says. "grow" and "warmup" add 8 MB at a time, touched so it counts as resident memory. +FAKE_GAME = r""" +import json, sys, time +mode = sys.argv[1] +with open(sys.argv[2], "w") as record: + json.dump(sys.argv[3:], record) +hold = [] +def grow(blocks): + for _ in range(blocks): + hold.append(bytearray(8 * 1024 * 1024)) + hold[-1][::4096] = b"x" * len(hold[-1][::4096]) + time.sleep(0.05) +if mode == "hang": + time.sleep(1000) +print("SOAK cycle 1 at 0.0 s", flush=True) +if mode == "short": + grow(12) + time.sleep(0.6) + sys.exit(0) +grow(12 if mode == "warmup" else 0) # loading everything once is not a leak +time.sleep(0.4) +print("SOAK cycle 2 at 30.0 s", flush=True) +time.sleep(0.4) +print("SOAK cycle 3 at 60.0", end="", flush=True) # a line split across reads +time.sleep(0.3) +print(" s", flush=True) +grow(12 if mode == "grow" else 0) +time.sleep(0.6) +print("SOAK verdict: steady", flush=True) +sys.exit(1 if mode == "leaky" else 0) +""" + + +class SoakTest(unittest.TestCase): + def setUp(self) -> None: + folder = tempfile.TemporaryDirectory() + self.addCleanup(folder.cleanup) + self.dir = Path(folder.name) + self.fake = self.dir / "fake_game.py" + self.fake.write_text(FAKE_GAME, encoding="utf-8") + self.args_file = self.dir / "args.json" + self.out = self.dir / "results" + + def run_soak(self, mode: str, *options: str, game_args: tuple[str, ...] = ("--", "--booth")) -> tuple[int, str, str]: + argv = ["--minutes", "0.05", "--dwell", "2", "--out", str(self.out), "--rss-every", "0.1", *options, + "--", sys.executable, str(self.fake), mode, str(self.args_file), *game_args] + with redirect_stdout(io.StringIO()) as out, redirect_stderr(io.StringIO()) as err: + code = soak.main(argv) + return code, out.getvalue(), err.getvalue() + + def test_passes_the_soak_arguments_after_the_games_separator(self) -> None: + code, out, _ = self.run_soak("steady") + self.assertEqual(code, 0, out) + self.assertEqual(json.loads(self.args_file.read_text()), + ["--", "--booth", "--soak=0.05", "--soak-dwell=2", f"--soak-log={self.out.resolve()}"]) + self.assertIn("SOAK verdict: steady", out) + self.assertIn("soak: passed", out) + + def test_adds_a_separator_when_the_game_has_none(self) -> None: + self.run_soak("steady", game_args=()) + self.assertEqual(json.loads(self.args_file.read_text())[0], "--") + + def test_samples_resident_memory(self) -> None: + self.run_soak("steady") + rows = (self.out / "rss.csv").read_text().splitlines() + self.assertEqual(rows[0], "elapsed_s,rss_mb") + self.assertGreaterEqual(len(rows), 4) + self.assertTrue(all(float(row.split(",")[1]) > 0 for row in rows[1:])) + self.assertIn("SOAK verdict: steady", (self.out / "game.log").read_text()) + + def test_fails_when_resident_memory_keeps_growing(self) -> None: + code, out, err = self.run_soak("grow", "--max-rss-growth", "20") + self.assertEqual(code, 1, out + err) + self.assertIn("resident memory kept growing", err) + + def test_growth_during_the_first_pass_is_warm_up(self) -> None: + code, out, err = self.run_soak("warmup", "--max-rss-growth", "20") + self.assertEqual(code, 0, out + err) + self.assertIn("soak: passed", out) + + def test_needs_three_passes_to_judge_memory(self) -> None: + code, out, _ = self.run_soak("short", "--max-rss-growth", "20") + self.assertEqual(code, 0) + self.assertIn("needs 3 to judge", out) + + def test_fails_when_the_game_reports_growth(self) -> None: + code, _, err = self.run_soak("leaky") + self.assertEqual(code, 1) + self.assertIn("exited with status 1", err) + + def test_stops_a_game_that_outlasts_its_time(self) -> None: + code, _, err = self.run_soak("hang", "--grace", "0.02") + self.assertEqual(code, 2) + self.assertIn("was stopped", err) + + def test_godot_mode_runs_this_checkouts_project(self) -> None: + args = soak.argparse.Namespace(godot="/opt/godot", command=[], minutes=480.0, dwell=30.0) + self.assertEqual(soak.game_command(args, Path("out")), + ["/opt/godot", "--path", str(soak.PROJECT), "--", "--soak=480", "--soak-dwell=30", + f"--soak-log={Path('out').resolve()}"]) + + def test_rss_verdict(self) -> None: + passes = {1: 0.0, 2: 100.0, 3: 200.0} + self.assertFalse(soak.rss_verdict([(0, 100.0)], {1: 0.0, 2: 100.0}, 25)[1]) + warmup_then_steady = [(t, 100.0 if t < 100 else 300.0 + t / 100) for t in range(0, 400, 40)] + self.assertFalse(soak.rss_verdict(warmup_then_steady, passes, 25)[1]) + growing = [(t, 100.0 + t) for t in range(0, 400, 40)] + message, grew = soak.rss_verdict(growing, passes, 25) + self.assertTrue(grew) + self.assertIn("limit 25%", message) + self.assertIn("too few", soak.rss_verdict([(10, 100.0), (150, 120.0)], passes, 25)[0]) + + def test_rejects_bad_usage(self) -> None: + for argv in (["--minutes", "1"], ["--minutes", "0", "--", "game"], + ["--minutes", "1", "--godot", "g", "--", "game"]): + with redirect_stderr(io.StringIO()), self.assertRaises(SystemExit) as stop: + soak.main(argv) + self.assertEqual(stop.exception.code, 2, argv) + + def test_missing_game_is_an_error(self) -> None: + with redirect_stdout(io.StringIO()), redirect_stderr(io.StringIO()) as err: + code = soak.main(["--minutes", "0.05", "--out", str(self.out), "--", str(self.dir / "nope")]) + self.assertEqual(code, 2) + self.assertIn("cannot start the game", err.getvalue()) + + +if __name__ == "__main__": + unittest.main() From 2aa44d6415399dd62eb15822bc9a3f6024ca1fb6 Mon Sep 17 00:00:00 2001 From: Erik Thorelli Date: Thu, 15 Oct 2026 19:00:08 -0700 Subject: [PATCH 2/4] fix(booth): make the soak's clocks, routes, percentiles and memory check exact [Agent: Claude Code | Model: Opus 5.5 | Thinking: High | Acting on behalf of: Erik | Skill: none] Addresses CodeRabbit review 5542002152 on #83. booth_soak.gd: - Wall-clock time drives the deadline, the dwell and the samples, so hit-stop's time scale and capped deltas can't stretch a soak. The dwell and the settle period start once a route has opened. - Each route change is awaited; AppRouter.go() now returns whether the scene opened, and a route that doesn't ends the soak with exit 2 instead of recording samples under the wrong label. Results that can't be written also exit 2. - --soak and --soak-dwell reject non-finite values; short dwells settle for half the dwell. --soak-routes limits a soak to some routes. - Slow frames are counted exactly against 16.7 and 33.3 ms; a percentile in the overflow bucket is capped at the worst frame instead of reading as 100.5 ms. The frame window is cleared on each route change, and the final hub snapshot needs a settled visit. - Each settled hub visit prints "SOAK hub ". soak.py: - Measures resident memory at each "SOAK hub " and compares the second visit with the last, instead of arbitrary samples. - Validates every number as finite (positive minutes, dwell and sampling; non-negative grace and growth limit), drops soak options already in the command, gives each run its own folder, always kills and reaps the game, reads the log once more after exit, and fails a game that never prints a verdict. Tests: a real negative soak (tests/support/soak_leak.gd leaks nodes beside it, skipped as a suite) must exit 1; --soak-routes keeps the steady and leaking runs short; the wrapper's memory tests use an injected sampler keyed to the fake game's hub visits. --- docs/builds.md | 8 +- hoppys-adventure-arcade/app/app_router.gd | 7 +- hoppys-adventure-arcade/app/booth_soak.gd | 189 ++++++++++++------ hoppys-adventure-arcade/tests/booth_soak.gd | 104 +++++++--- .../tests/support/soak_leak.gd | 10 + .../tests/support/soak_leak.gd.uid | 1 + tools/booth/soak.py | 140 ++++++++----- tools/booth/test_soak.py | 140 ++++++++----- tools/tests/suites.toml | 1 + 9 files changed, 400 insertions(+), 200 deletions(-) create mode 100644 hoppys-adventure-arcade/tests/support/soak_leak.gd create mode 100644 hoppys-adventure-arcade/tests/support/soak_leak.gd.uid diff --git a/docs/builds.md b/docs/builds.md index 5041f29f..5446a81f 100644 --- a/docs/builds.md +++ b/docs/builds.md @@ -56,10 +56,10 @@ python3 tools/booth/soak.py --minutes 600 -- "/Applications/Hoppy’s Adventure python3 tools/booth/soak.py --minutes 10 --godot "$GODOT" # a quick run of this checkout's project ``` -- **The soak.** The game runs with `--soak=`. It visits every route in turn and stays `--soak-dwell=` (default 30) on each with nobody playing. A soak turns off the idle return and the game-over card, ignores `--route`, and writes no session log, so its visits never count as booth sessions. -- **Frame rate.** Every 5 seconds the game appends a CSV row: the route, frames per second, median, 99th-percentile and worst frame times, and the engine's memory and object counts. At the end it prints a table per route with the share of frames slower than 16.7 ms (60 fps) and 33.3 ms (30 fps), plus the worst loading hitch. Run it fullscreen (`--booth`) on the booth hardware to measure at the booth resolution; headless frame times mean nothing. -- **Leak check.** The game compares its object, node, orphan-node and resource counts at the hub from the second visit to the last; the first visit warms caches. Debug builds also compare static memory, which release builds don't report. Growth beyond small limits makes the game exit 1. -- **Resident memory.** `soak.py` samples the process's memory with `ps` every 30 seconds (`--rss-every`). The first pass over the routes loads everything once, so the check runs from the start of the second pass to the end, once a third pass has begun, and fails if memory grew more than 25% (`--max-rss-growth`). It stops a run that outlasts its time by 10 minutes (`--grace`). Results land in `soak-results/` (`--out`): the game's CSV and summary, `game.log` and `rss.csv`. macOS and Linux. +- **The soak.** The game runs with `--soak=` (wall-clock time). It visits every route in turn and stays `--soak-dwell=` (default 30) on each with nobody playing, counted from when the route has opened. `--soak-routes=hub,heroes_vs_villains` keeps it to those routes; the hub is always included. A soak turns off the idle return and the game-over card, ignores `--route`, and writes no session log, so its visits never count as booth sessions. +- **Frame rate.** Every 5 seconds the game appends a CSV row for the current route: frames per second, median, 99th-percentile and worst frame times, and the engine's memory and object counts. At the end it prints a table per route: the share of frames slower than 16.7 ms (60 fps) and 33.3 ms (30 fps), percentiles capped at the worst frame, and the worst loading hitch. Run it fullscreen (`--booth`) on the booth hardware to measure at the booth resolution; headless frame times mean nothing. +- **Leak check.** At the end of each hub visit the game records its object, node, orphan-node and resource counts and prints `SOAK hub `. It compares the second visit with the last, since the first warms caches. Debug builds also compare static memory, which release builds don't report. Growth beyond small limits makes the game exit 1. A route that won't open, or results that can't be written, make it exit 2. +- **Resident memory.** `soak.py` samples the process's memory with `ps` every 30 seconds (`--rss-every`) into `rss.csv`, and again at each `SOAK hub ` line. It compares the second hub visit with the last, once there are three, and fails above 25% growth (`--max-rss-growth`). It also fails a game that exits without a verdict, and stops a run that outlasts its time by 10 minutes (`--grace`). Each run gets its own folder under `soak-results/` (`--out`), holding the game's CSV and summary, `game.log` and `rss.csv`. macOS and Linux. ## Build locally diff --git a/hoppys-adventure-arcade/app/app_router.gd b/hoppys-adventure-arcade/app/app_router.gd index 2efa0317..1093262e 100644 --- a/hoppys-adventure-arcade/app/app_router.gd +++ b/hoppys-adventure-arcade/app/app_router.gd @@ -105,9 +105,11 @@ func _ready() -> void: _launch.call_deferred(start) ## `reason` is how a game session in progress ends, for the session log: "menu" unless the router ## itself is leaving the game (booth mode's idle return passes "idle"). -func go(route: String, reason := "menu") -> void: +## Returns true once the route's scene has opened, false when the change was refused or failed; +## callers that don't need to know can ignore it. +func go(route: String, reason := "menu") -> bool: if busy or not ROUTES.has(route) or not ResourceLoader.exists(ROUTES[route]): - return + return false busy = true veil.mouse_filter = Control.MOUSE_FILTER_STOP AudioService.play_ui(2) @@ -129,6 +131,7 @@ func go(route: String, reason := "menu") -> void: await create_tween().tween_property(veil, "modulate:a", 0.0, 0.25).finished veil.mouse_filter = Control.MOUSE_FILTER_IGNORE busy = false + return error == OK ## Visitors can't quit a booth from the menu; staff close the window instead (force = true). ## A forced quit wins even mid-transition: auto_accept_quit is off, so nothing else would close. func quit_game(force := false) -> void: diff --git a/hoppys-adventure-arcade/app/booth_soak.gd b/hoppys-adventure-arcade/app/booth_soak.gd index 59beec6f..33fcca09 100644 --- a/hoppys-adventure-arcade/app/booth_soak.gd +++ b/hoppys-adventure-arcade/app/booth_soak.gd @@ -1,25 +1,33 @@ extends Node ## Soak test and frame-rate probe for long unattended runs: ` -- --soak=`. The game ## visits every AppRouter route in turn and stays `--soak-dwell=` (default 30) on each with -## nobody playing, for the given minutes. Every SAMPLE_SECONDS it appends a CSV row: the route, the -## frame rate and frame times, and the engine's memory and object counts. At the end it prints a -## frame-rate table per route and a leak check, writes both next to the CSV in `--soak-log=` -## (default user://soak), and quits: 0 when the counts held steady, 1 when they kept growing. +## nobody playing, for the given minutes of wall-clock time. Every SAMPLE_SECONDS it appends a CSV +## row: the route, the frame rate and frame times, and the engine's memory and object counts. At +## the end it prints a frame-rate table per route and a leak check, writes both next to the CSV in +## `--soak-log=` (default user://soak), and quits: 0 when the counts held steady, 1 when +## they kept growing, 2 when a route failed to open or the results couldn't be written. +## `--soak-routes=hub,heroes_vs_villains` limits the soak to those routes (the hub is always one). ## Run it rendered and fullscreen on the booth machine for frame rates at the booth resolution; ## headless runs measure only the leak check. tools/booth/soak.py wraps a run and adds the -## process's resident memory, which release builds can't report from inside. +## process's resident memory, which release builds can't report from inside; it reads the +## "SOAK hub " lines to measure it at the same point of each pass. const MINUTES_PREFIX := "--soak=" const DWELL_PREFIX := "--soak-dwell=" const FOLDER_PREFIX := "--soak-log=" +const ROUTES_PREFIX := "--soak-routes=" const DEFAULT_DWELL := 30.0 +const MIN_DWELL := 0.2 const DEFAULT_FOLDER := "user://soak" const SAMPLE_SECONDS := 5.0 -## Frames this soon after a route opens are loading, not play: they count as load hitches. +## Frames this soon after a route opens are loading, not play: they count as load hitches. Short +## dwells settle for half the dwell instead. const SETTLE_SECONDS := 1.0 ## Frame-time histogram: BUCKET_MS wide buckets up to BUCKETS * BUCKET_MS, then one overflow bucket. const BUCKET_MS := 0.5 const BUCKETS := 200 -## The leak check needs this many visits to the hub: the first warms caches and is not compared. +## Frame times the summary reports the share of frames above (60 and 30 fps). +const SLOW_MS: Array[float] = [16.7, 33.3] +## The leak check needs this many settled hub visits: the first warms caches and is not compared. const MIN_CYCLES := 3 ## Growth from the second hub visit to the last that counts as a leak: [absolute, fraction]. const LIMITS := {"objects": [500, 0.05], "nodes": [100, 0.0], "orphan_nodes": [20, 0.0], @@ -29,32 +37,43 @@ const COLUMNS := ["elapsed_s", "cycle", "route", "frames", "fps", "frame_p50_ms" var minutes := 0.0 var dwell := DEFAULT_DWELL +var settle := SETTLE_SECONDS var folder := DEFAULT_FOLDER +## The routes named by --soak-routes, or empty for all of them. +var only: PackedStringArray = [] var csv_path := "" var summary_path := "" var router: Node var routes: Array[String] = [] var index := -1 var cycle := 0 +## Wall-clock seconds since the soak began, on the route since it opened, and since the last row. var elapsed := 0.0 var on_route := 0.0 var since_sample := 0.0 var last_usec := 0 +## True while a route change is under way; nothing counts towards the dwell then. +var changing := false var window: PackedFloat32Array = [] -## Per route: {"histogram": PackedInt32Array, "frames": int, "ms": total frame time, "max": float}. +## Per route: {"histogram": PackedInt32Array, "frames": int, "ms": total, "max": float, +## "slow": [frames over each SLOW_MS]}. var stats := {} var load_hitch := {"ms": 0.0, "route": ""} -## Engine counts at the end of each hub visit, for the leak check. +## Engine counts at the end of each settled hub visit, for the leak check. var hub_snapshots: Array[Dictionary] = [] +## Why the soak can't be trusted, if anything went wrong: a route that didn't open, or results +## that couldn't be written. Either makes the exit status 2. +var failure := "" var finished := false -## The soak length from `--soak=`, or 0.0 when absent or not a positive number. +## The soak length from `--soak=`, or 0.0 when absent or not a positive, finite number. static func minutes_from(args: PackedStringArray) -> float: for arg in args: if arg.begins_with(MINUTES_PREFIX): var value := arg.trim_prefix(MINUTES_PREFIX) - if value.is_valid_float() and value.to_float() > 0.0: - return value.to_float() + var parsed := value.to_float() + if value.is_valid_float() and is_finite(parsed) and parsed > 0.0: + return parsed push_warning("--soak needs a positive number of minutes, not %s; no soak" % value) return 0.0 @@ -63,16 +82,31 @@ func _init(soak_minutes: float, args: PackedStringArray) -> void: process_mode = Node.PROCESS_MODE_ALWAYS minutes = soak_minutes for arg in args: - if arg.begins_with(DWELL_PREFIX) and arg.trim_prefix(DWELL_PREFIX).is_valid_float(): - dwell = maxf(0.2, arg.trim_prefix(DWELL_PREFIX).to_float()) + if arg.begins_with(DWELL_PREFIX): + var value := arg.trim_prefix(DWELL_PREFIX) + var parsed := value.to_float() + if value.is_valid_float() and is_finite(parsed): + dwell = maxf(MIN_DWELL, parsed) + else: + push_warning("--soak-dwell needs a number of seconds, not %s; using %s" \ + % [value, dwell]) elif arg.begins_with(FOLDER_PREFIX) and arg.length() > FOLDER_PREFIX.length(): folder = arg.trim_prefix(FOLDER_PREFIX) + elif arg.begins_with(ROUTES_PREFIX): + only = arg.trim_prefix(ROUTES_PREFIX).split(",", false) + settle = minf(SETTLE_SECONDS, dwell * 0.5) func _ready() -> void: router = get_parent() - routes.assign(router.ROUTES.keys()) - if not DirAccess.dir_exists_absolute(folder): - DirAccess.make_dir_recursive_absolute(folder) + for route: String in router.ROUTES: + if only.is_empty() or route in only or route == "hub": + routes.append(route) + for route in only: + if not router.ROUTES.has(route): + push_warning("--soak-routes: unknown route %s, skipped" % route) + if not DirAccess.dir_exists_absolute(folder) \ + and DirAccess.make_dir_recursive_absolute(folder) != OK: + failure = "cannot create %s" % ProjectSettings.globalize_path(folder) # The process id keeps two soaks started in the same second apart. var stamp := "%s-%d" % [Time.get_datetime_string_from_system().replace(":", "-"), OS.get_process_id()] @@ -84,40 +118,58 @@ func _ready() -> void: last_usec = Time.get_ticks_usec() _next_route() -func _process(delta: float) -> void: +func _process(_delta: float) -> void: if finished: return var now := Time.get_ticks_usec() var span := (now - last_usec) / 1000.0 last_usec = now - elapsed += delta - if router.busy or on_route < SETTLE_SECONDS: - if span > load_hitch.ms: - load_hitch = {"ms": span, "route": _route()} + var seconds := span / 1000.0 + elapsed += seconds + since_sample += seconds + if changing or router.busy: + _hitch(span) else: - _count(span) - on_route += delta - since_sample += delta + on_route += seconds + if on_route < settle: + _hitch(span) + else: + _count(span) if since_sample >= SAMPLE_SECONDS: _sample() if elapsed >= minutes * 60.0: _finish() - elif on_route >= dwell and not router.busy: + elif not changing and not router.busy and on_route >= dwell: if _route() == "hub": - hub_snapshots.append(_counts()) + _snapshot_hub() _next_route() func _route() -> String: return routes[index] if index >= 0 else "" +## Open the next route and wait for it. The dwell starts once the scene is there; a route that +## doesn't open ends the soak, since its samples would carry the wrong label. func _next_route() -> void: index = (index + 1) % routes.size() if index == 0: cycle += 1 - # tools/booth/soak.py times its memory check from these lines. print("SOAK cycle %d at %.1f s" % [cycle, elapsed]) + var route := routes[index] on_route = 0.0 - router.go(routes[index]) + window.clear() + changing = true + var opened: bool = await router.go(route) + changing = false + var scene := get_tree().current_scene + if finished: + return + if not opened or scene == null or scene.scene_file_path != router.ROUTES[route]: + failure = "route %s did not open" % route + _finish() + +func _hitch(span: float) -> void: + if span > load_hitch.ms: + load_hitch = {"ms": span, "route": _route()} func _count(span: float) -> void: window.append(span) @@ -125,12 +177,20 @@ func _count(span: float) -> void: if not stats.has(route): var histogram := PackedInt32Array() histogram.resize(BUCKETS + 1) - stats[route] = {"histogram": histogram, "frames": 0, "ms": 0.0, "max": 0.0} + stats[route] = {"histogram": histogram, "frames": 0, "ms": 0.0, "max": 0.0, "slow": [0, 0]} var entry: Dictionary = stats[route] entry.histogram[mini(int(span / BUCKET_MS), BUCKETS)] += 1 entry.frames += 1 entry.ms += span entry.max = maxf(entry.max, span) + for i in SLOW_MS.size(): + if span > SLOW_MS[i]: + entry.slow[i] += 1 + +func _snapshot_hub() -> void: + hub_snapshots.append(_counts()) + # tools/booth/soak.py samples resident memory when it reads this line. + print("SOAK hub %d at %.1f s" % [hub_snapshots.size(), elapsed]) func _counts() -> Dictionary: return { @@ -142,6 +202,7 @@ func _counts() -> Dictionary: "resources": int(Performance.get_monitor(Performance.OBJECT_RESOURCE_COUNT)), } +## One CSV row for the frames since the last one, which all belong to the current route. func _sample() -> void: var sorted := window.duplicate() sorted.sort() @@ -161,22 +222,17 @@ func _sample() -> void: window.clear() since_sample = 0.0 -## The frame time (ms) below which `share` of a route's frames fall, to the bucket's upper edge. +## The frame time (ms) below which `share` of a route's frames fall, to the bucket's upper edge; +## INF when it lands in the overflow bucket, whose frames have no upper bound (callers cap it at the +## route's worst frame). static func percentile(histogram: PackedInt32Array, frames: int, share: float) -> float: var target := ceili(frames * share) var seen := 0 for i in histogram.size(): seen += histogram[i] if seen >= target: - return (i + 1) * BUCKET_MS - return BUCKETS * BUCKET_MS - -## Frames slower than `ms`, as a share of all of the route's frames. -static func slower_than(histogram: PackedInt32Array, frames: int, ms: float) -> float: - var slow := 0 - for i in range(int(ms / BUCKET_MS), histogram.size()): - slow += histogram[i] - return float(slow) / maxf(1.0, frames) + return INF if i >= BUCKETS else (i + 1) * BUCKET_MS + return INF ## The leak check's findings: "" when steady or too few to compare, else what kept growing. static func growth(snapshots: Array[Dictionary]) -> String: @@ -195,12 +251,8 @@ static func growth(snapshots: Array[Dictionary]) -> String: grew.append(shape % [key, first[key], last[key]]) return ", ".join(grew) -func _finish() -> void: - finished = true - if since_sample > 0.0: - _sample() - if _route() == "hub": - hub_snapshots.append(_counts()) +## The summary lines and exit status: 0 steady (or too short to judge), 1 growing, 2 failed. +func verdict() -> Dictionary: var size := DisplayServer.window_get_size() var lines := PackedStringArray() lines.append("SOAK %.1f min, %d cycles, window %dx%d, vsync %s, %s" % [elapsed / 60.0, cycle, @@ -219,10 +271,9 @@ func _finish() -> void: minf(top, percentile(entry.histogram, frames, 0.5)), minf(top, percentile(entry.histogram, frames, 0.95)), minf(top, percentile(entry.histogram, frames, 0.99)), top, - 100.0 * slower_than(entry.histogram, frames, 16.7), - 100.0 * slower_than(entry.histogram, frames, 33.3)]) + 100.0 * entry.slow[0] / maxf(1.0, frames), 100.0 * entry.slow[1] / maxf(1.0, frames)]) lines.append("SOAK worst load hitch: %.0f ms (%s)" % [load_hitch.ms, load_hitch.route]) - var verdict := "too short to judge: %d hub visits, needs %d" % [hub_snapshots.size(), MIN_CYCLES] + var text := "too short to judge: %d hub visits, needs %d" % [hub_snapshots.size(), MIN_CYCLES] var code := 0 if hub_snapshots.size() >= MIN_CYCLES: var first := hub_snapshots[1] @@ -233,31 +284,53 @@ func _finish() -> void: lines.append("SOAK static memory %s" % ("%.1f MB -> %.1f MB" % [first.static_mb, last.static_mb] if first.static_mb > 0.0 else "not reported by release builds")) var grew := growth(hub_snapshots) - verdict = "steady" if grew == "" else "GROWING: " + grew + text = "steady" if grew == "" else "GROWING: " + grew code = 0 if grew == "" else 1 - lines.append("SOAK verdict: " + verdict) - var text := "\n".join(lines) - print(text) + if failure != "": + text = "FAILED: " + failure + code = 2 + lines.append("SOAK verdict: " + text) + return {"lines": lines, "code": code} + +func _finish() -> void: + if finished: + return + finished = true + if not window.is_empty(): + _sample() + if _route() == "hub" and not changing and not router.busy and on_route >= dwell: + _snapshot_hub() var file := FileAccess.open(summary_path, FileAccess.WRITE) - if file: + if file == null and failure == "": + failure = "cannot write %s" % ProjectSettings.globalize_path(summary_path) + var result := verdict() + var text := "\n".join(result.lines) + if file != null: file.store_string(text + "\n") file.close() + print(text) print("SOAK summary at %s" % ProjectSettings.globalize_path(summary_path)) + if router.busy: + await get_tree().create_timer(1.0, true).timeout router.go("hub") await get_tree().create_timer(1.0, true).timeout get_tree().unload_current_scene() # By path: suites preload this script before autoloads exist. get_node(^"/root/AudioService").shutdown() await get_tree().create_timer(0.4, true).timeout - get_tree().quit(code) + get_tree().quit(result.code) +## Append one line to the CSV; a failure marks the soak failed rather than stopping it. func _append(line: String) -> void: var file := FileAccess.open(csv_path, FileAccess.READ_WRITE if FileAccess.file_exists(csv_path) else FileAccess.WRITE) if file == null: - push_warning("Soak: cannot write %s (%s)" % [csv_path, - error_string(FileAccess.get_open_error())]) + if failure == "": + failure = "cannot write %s (%s)" % [ProjectSettings.globalize_path(csv_path), + error_string(FileAccess.get_open_error())] return file.seek_end() - file.store_line(line) + var written := file.store_line(line) file.close() + if not written and failure == "": + failure = "cannot write %s" % ProjectSettings.globalize_path(csv_path) diff --git a/hoppys-adventure-arcade/tests/booth_soak.gd b/hoppys-adventure-arcade/tests/booth_soak.gd index ad829353..f6aa9ed9 100644 --- a/hoppys-adventure-arcade/tests/booth_soak.gd +++ b/hoppys-adventure-arcade/tests/booth_soak.gd @@ -1,11 +1,19 @@ extends SceneTree ## Soak test (app/booth_soak.gd): --soak parsing, the frame-time math and the leak check on fixed -## numbers, then a short real soak in a child process at a fixed 60 fps. It must visit every route, -## write CSV samples and a summary with a frame-rate row per route, judge three hub visits as -## steady, and exit 0. Run headless with --script res://tests/booth_soak.gd. +## numbers, then short real soaks in child processes: one over every route must write CSV samples +## and a summary with a frame-rate row per route and exit 0; one over the hub and the platformer +## menu must judge its hub visits steady; the same next to a script that leaks nodes must judge them +## growing and exit 1. +## Run headless with --script res://tests/booth_soak.gd. const BoothSoak := preload("res://app/booth_soak.gd") const ChildGame := preload("res://tests/support/child_game.gd") const FOLDER := "user://test_soak" +const SHORT_FOLDER := "user://test_soak_short" +const LEAK_FOLDER := "user://test_soak_leak" +## Every route at least once, even on a slow CI runner. +const FULL := ["--soak=0.4", "--soak-dwell=0.6"] +## Two light routes: three settled hub visits in seconds. +const SHORT := ["--soak=0.2", "--soak-dwell=0.6", "--soak-routes=hub,platformer"] var failures := 0 func _initialize() -> void: @@ -21,12 +29,24 @@ func counts(nodes: int, static_mb := 0.0) -> Dictionary: "static_mb": static_mb, "video_mb": 0.0} func clean() -> void: - var dir := DirAccess.open(FOLDER) + for folder in [FOLDER, SHORT_FOLDER, LEAK_FOLDER]: + var dir := DirAccess.open(folder) + if dir == null: + continue + for file_name in dir.get_files(): + dir.remove(file_name) + DirAccess.remove_absolute(folder) + +## The files a soak wrote in `folder`: {"csv": text, "summary": text}. +func results(folder: String) -> Dictionary: + var found := {"csv": "", "summary": ""} + var dir := DirAccess.open(folder) if dir == null: - return + return found for file_name in dir.get_files(): - dir.remove(file_name) - DirAccess.remove_absolute(FOLDER) + var text := FileAccess.get_file_as_string(folder.path_join(file_name)) + found["summary" if file_name.ends_with("-summary.txt") else "csv"] = text + return found func run() -> void: clean() @@ -34,8 +54,13 @@ func run() -> void: check(is_equal_approx(BoothSoak.minutes_from(PackedStringArray(["--soak=480"])), 480.0), "--soak sets the minutes") check(BoothSoak.minutes_from(PackedStringArray(["--soak=0"])) == 0.0 - and BoothSoak.minutes_from(PackedStringArray(["--soak=long"])) == 0.0, - "A zero or non-numeric --soak runs no soak") + and BoothSoak.minutes_from(PackedStringArray(["--soak=long"])) == 0.0 + and BoothSoak.minutes_from(PackedStringArray(["--soak=1e999"])) == 0.0, + "A zero, non-numeric or infinite --soak runs no soak") + var endless := BoothSoak.new(10.0, PackedStringArray(["--soak-dwell=1e999"])) + check(endless.dwell == BoothSoak.DEFAULT_DWELL, "An infinite --soak-dwell keeps the default") + var short := BoothSoak.new(10.0, PackedStringArray(["--soak-dwell=0.6"])) + check(is_equal_approx(short.settle, 0.3), "A short dwell settles for half of it") var histogram := PackedInt32Array() histogram.resize(BoothSoak.BUCKETS + 1) @@ -44,8 +69,15 @@ func run() -> void: check(is_equal_approx(BoothSoak.percentile(histogram, 100, 0.5), 17.0) and is_equal_approx(BoothSoak.percentile(histogram, 100, 0.95), 40.5), "Percentiles come from the frame-time histogram") - check(is_equal_approx(BoothSoak.slower_than(histogram, 100, 33.3), 0.1), - "The share of frames slower than 33.3 ms is counted") + histogram[BoothSoak.BUCKETS] = 900 # over 100 ms + check(BoothSoak.percentile(histogram, 1000, 0.99) == INF, + "A percentile in the overflow bucket has no upper edge (the caller caps it at the worst)") + short._count(16.6) + short._count(16.8) + short._count(40.0) + check(short.stats[""].slow == [2, 1], "Slow frames are counted exactly against 16.7 and 33.3 ms") + endless.free() + short.free() var steady: Array[Dictionary] = [counts(400), counts(69), counts(70), counts(69)] check(BoothSoak.growth(steady) == "", "Counts that hold steady pass (the first visit is ignored)") @@ -54,35 +86,45 @@ func run() -> void: var memory: Array[Dictionary] = [counts(69, 300.0), counts(69, 300.0), counts(69, 420.0)] check(BoothSoak.growth(memory).begins_with("static_mb 300.0 -> 420.0"), "Static memory that keeps growing fails when the build reports it") + var single: Array[Dictionary] = [counts(69)] + check(BoothSoak.growth(single) == "", "One snapshot is too few to compare") - var child: Dictionary = await ChildGame.run(self, ["--fixed-fps", "60", "--", "--soak=0.8", - "--soak-dwell=1.5", "--soak-log=" + ProjectSettings.globalize_path(FOLDER)], 300.0) - var text_out: String = child.log - check(child.code == 0, "A short soak exits 0 (exit %d)" % child.code) - var routes: Array = root.get_node("AppRouter").ROUTES.keys() + var args: Array[String] = ["--"] + args.append_array(FULL) + args.append("--soak-log=" + ProjectSettings.globalize_path(FOLDER)) + var clean_run: Dictionary = await ChildGame.run(self, args, 300.0) + check(clean_run.code == 0, "A soak over every route exits 0 (exit %d)" % clean_run.code) var missing := [] - for route: String in routes: - if not RegEx.create_from_string("(?m)^SOAK %s +\\d+" % route).search(text_out): + for route: String in root.get_node("AppRouter").ROUTES.keys(): + if not RegEx.create_from_string("(?m)^SOAK %s +\\d+" % route).search(clean_run.log): missing.append(route) check(missing.is_empty(), "The frame-rate table has a row for every route (missing %s)" % [missing]) - check(text_out.contains("SOAK verdict: steady"), "Three or more hub visits are judged steady") - var csv := "" - var summary := "" - var dir := DirAccess.open(FOLDER) - if dir != null: - for file_name in dir.get_files(): - var text := FileAccess.get_file_as_string(FOLDER.path_join(file_name)) - if file_name.ends_with("-summary.txt"): - summary = text - elif file_name.ends_with(".csv"): - csv = text - var rows := csv.strip_edges().split("\n") + var written := results(FOLDER) + var rows: PackedStringArray = String(written.csv).strip_edges().split("\n") check(rows.size() > 3 and rows[0] == ",".join(BoothSoak.COLUMNS), "The CSV has the documented columns and a row per sample") - check(summary.contains("SOAK verdict: steady") and summary.contains("SOAK worst load hitch"), + check(String(written.summary).contains("SOAK verdict: ") + and String(written.summary).contains("SOAK worst load hitch"), "The summary file holds the table and the verdict") + var short_args: Array[String] = ["--"] + short_args.append_array(SHORT) + short_args.append("--soak-log=" + ProjectSettings.globalize_path(SHORT_FOLDER)) + var short_run: Dictionary = await ChildGame.run(self, short_args, 300.0) + check(short_run.code == 0 and short_run.log.contains("SOAK hub 3 at") + and short_run.log.contains("SOAK verdict: steady") + and not RegEx.create_from_string("(?m)^SOAK runner_game +\\d+").search(short_run.log), + "--soak-routes keeps to its routes, announces hub visits and judges them steady") + + var leak_args: Array[String] = ["--script", "res://tests/support/soak_leak.gd", "--"] + leak_args.append_array(SHORT) + leak_args.append("--soak-log=" + ProjectSettings.globalize_path(LEAK_FOLDER)) + var leaky: Dictionary = await ChildGame.run(self, leak_args, 300.0) + check(leaky.code == 1 and leaky.log.contains("SOAK verdict: GROWING: ") + and leaky.log.contains("orphan_nodes"), + "A soak next to a node leak judges it growing and exits 1 (exit %d)" % leaky.code) + clean() await root.get_node("AudioService").settle() print("Booth soak failures: ", failures) diff --git a/hoppys-adventure-arcade/tests/support/soak_leak.gd b/hoppys-adventure-arcade/tests/support/soak_leak.gd new file mode 100644 index 00000000..d2c57391 --- /dev/null +++ b/hoppys-adventure-arcade/tests/support/soak_leak.gd @@ -0,0 +1,10 @@ +extends SceneTree +## Child process for tests/booth_soak.gd, skipped as a suite in tools/tests/suites.toml. It runs +## while a soak does (pass --soak after --) and leaks an orphan node every frame, so the soak's leak +## check has something real to catch and must exit 1. +## Usage: --script res://tests/support/soak_leak.gd -- --soak= [--soak-dwell=...] +var leaked: Array[Node] = [] + +func _process(_delta: float) -> bool: + leaked.append(Node.new()) + return false diff --git a/hoppys-adventure-arcade/tests/support/soak_leak.gd.uid b/hoppys-adventure-arcade/tests/support/soak_leak.gd.uid new file mode 100644 index 00000000..4a187fb5 --- /dev/null +++ b/hoppys-adventure-arcade/tests/support/soak_leak.gd.uid @@ -0,0 +1 @@ +uid://yr1c2a1oped1 diff --git a/tools/booth/soak.py b/tools/booth/soak.py index ad2e8b48..d56d1b11 100644 --- a/tools/booth/soak.py +++ b/tools/booth/soak.py @@ -6,26 +6,32 @@ The game runs with --soak= (hoppys-adventure-arcade/app/booth_soak.gd). It visits every route in turn, writes frame times and engine counts to a CSV, prints a frame-rate table per route -and a leak check, and exits 0 (steady) or 1 (counts kept growing). Release builds can't report -their own memory, so this wrapper samples the process's resident memory with `ps` into rss.csv. -The first pass over the routes loads everything once, so memory is compared from the start of the -second pass (the game prints "SOAK cycle 2") to the end, and only once a third pass has begun. The -run fails when it grew by more than --max-rss-growth percent. A run that outlasts --minutes by ---grace minutes is stopped and fails. -Everything lands in --out: the game's CSV and summary, game.log and rss.csv. macOS and Linux. -Standard library only. +and a leak check, and exits 0 (steady), 1 (counts kept growing) or 2 (a route or its results +failed). Release builds can't report their own memory, so this wrapper samples the process's +resident memory with `ps`: every --rss-every seconds into rss.csv, and each time the game prints +"SOAK hub ", the same point of every pass over the routes. The first pass loads everything +once, so the check compares the second hub visit with the last, needs three, and fails the run +above --max-rss-growth percent. A run that outlasts --minutes by --grace minutes is stopped, and a +game that never prints its verdict fails. Each run gets its own folder under --out, holding the +game's CSV and summary, game.log and rss.csv. macOS and Linux. Standard library only. """ from __future__ import annotations import argparse +import math +import os import re import subprocess import sys import time +from collections.abc import Callable from pathlib import Path PROJECT = Path(__file__).resolve().parents[2] / "hoppys-adventure-arcade" -CYCLE = re.compile(r"^SOAK cycle (\d+)\b") +HUB = re.compile(r"^SOAK hub (\d+)\b") +VERDICT = "SOAK verdict: " +# The soak options the wrapper sets; any already in a game command are dropped. +OWN_OPTIONS = ("--soak=", "--soak-dwell=", "--soak-log=") def rss_mb(pid: int) -> float | None: @@ -40,29 +46,33 @@ def rss_mb(pid: int) -> float | None: def game_command(args: argparse.Namespace, out: Path) -> list[str]: - """The game's command line, with the soak's user arguments after its "--".""" + """The game's command line, with the wrapper's soak options after its "--".""" command = [args.godot, "--path", str(PROJECT)] if args.godot else list(args.command) + command = [arg for arg in command if not arg.startswith(OWN_OPTIONS)] if "--" not in command[1:]: command.append("--") command += [f"--soak={args.minutes:g}", f"--soak-dwell={args.dwell:g}", f"--soak-log={out.resolve()}"] return command -def rss_verdict(samples: list[tuple[float, float]], cycles: dict[int, float], limit: float) -> tuple[str, bool]: - """Compare memory when the second pass began with the last sample: (message, grew too much). - `cycles` maps each pass the game announced to the run time it began at.""" - if 3 not in cycles: - return f"RSS: {len(cycles)} pass(es) over the routes, needs 3 to judge", False - after = [rss for elapsed, rss in samples if elapsed >= cycles[2]] - if len(after) < 2: - return f"RSS: {len(after)} sample(s) after the first pass, too few to judge", False - reference, last = after[0], after[-1] +def rss_verdict(hub_rss: dict[int, float], limit: float) -> tuple[str, bool]: + """Compare memory at the second hub visit with the last: (message, grew too much).""" + if len(hub_rss) < 3 or 2 not in hub_rss: + return f"RSS: {len(hub_rss)} hub visit(s) measured, needs 3 to judge", False + reference, last = hub_rss[2], hub_rss[max(hub_rss)] growth = 100.0 * (last - reference) / reference - message = f"RSS: {reference:.0f} MB -> {last:.0f} MB ({growth:+.1f}%, limit {limit:g}%)" + message = f"RSS: {reference:.0f} MB -> {last:.0f} MB (hub visits 2 -> {max(hub_rss)}, {growth:+.1f}%, limit {limit:g}%)" return message, growth > limit -def main(argv: list[str] | None = None) -> int: +def run_folder(out: Path) -> Path: + """A new folder for this run under `out`, so two runs never share files.""" + folder = out / f"{time.strftime('%Y-%m-%dT%H-%M-%S')}-{os.getpid()}" + folder.mkdir(parents=True, exist_ok=False) + return folder + + +def main(argv: list[str] | None = None, sample: Callable[[int], float | None] = rss_mb) -> int: parser = argparse.ArgumentParser(description=__doc__.splitlines()[0], usage="%(prog)s --minutes M [options] (--godot GODOT | -- GAME [ARGS ...])") parser.add_argument("--minutes", type=float, required=True, help="how long the game soaks") @@ -77,53 +87,72 @@ def main(argv: list[str] | None = None) -> int: split = argv.index("--") if "--" in argv else len(argv) args = parser.parse_args(argv[:split]) args.command = argv[split + 1:] + numbers = {"--minutes": args.minutes, "--dwell": args.dwell, "--rss-every": args.rss_every, + "--max-rss-growth": args.max_rss_growth, "--grace": args.grace} + for name, value in numbers.items(): + if not math.isfinite(value): + parser.error(f"{name} must be a finite number") if args.minutes <= 0 or args.dwell <= 0 or args.rss_every <= 0: parser.error("--minutes, --dwell and --rss-every must be positive") + if args.grace < 0 or args.max_rss_growth < 0: + parser.error("--grace and --max-rss-growth can't be negative") if bool(args.godot) == bool(args.command): parser.error("pass either --godot or a game command after --") - args.out.mkdir(parents=True, exist_ok=True) - command = game_command(args, args.out) + + out = run_folder(args.out) + command = game_command(args, out) print("soak: " + " ".join(command)) deadline = time.monotonic() + (args.minutes + args.grace) * 60.0 - samples: list[tuple[float, float]] = [] - cycles: dict[int, float] = {} + hub_rss: dict[int, float] = {} pending = "" - with (args.out / "game.log").open("w", encoding="utf-8") as log, (args.out / "rss.csv").open("w", encoding="utf-8") as rss, \ - (args.out / "game.log").open(encoding="utf-8", errors="replace") as tail: + timed_out = False + + def read_new(tail) -> None: + """Take in the game's new whole lines; measure memory at each hub visit it announces.""" + nonlocal pending + pending += tail.read() + *lines, pending = pending.split("\n") + for line in lines: + match = HUB.match(line) + if match and game.poll() is None: + memory = sample(game.pid) + if memory is not None: + hub_rss.setdefault(int(match.group(1)), memory) + + with (out / "game.log").open("w", encoding="utf-8") as log, (out / "rss.csv").open("w", encoding="utf-8") as rss, \ + (out / "game.log").open(encoding="utf-8", errors="replace") as tail: rss.write("elapsed_s,rss_mb\n") try: game = subprocess.Popen(command, stdout=log, stderr=subprocess.STDOUT) except OSError as error: print(f"soak: cannot start the game: {error}", file=sys.stderr) return 2 - started = time.monotonic() - next_sample = started - timed_out = False - while game.poll() is None: - now = time.monotonic() - if now >= deadline: - timed_out = True + try: + started = time.monotonic() + next_sample = started + while game.poll() is None: + now = time.monotonic() + if now >= deadline: + timed_out = True + break + read_new(tail) + if now >= next_sample: + memory = sample(game.pid) + if memory is not None: + rss.write(f"{now - started:.1f},{memory:.1f}\n") + rss.flush() + next_sample = now + args.rss_every + time.sleep(min(0.2, args.rss_every)) + finally: + # Whatever happened above, never leave the game running behind the wrapper. + if game.poll() is None: game.kill() - game.wait() - break - # Whole lines only: a read can stop partway through one. - pending += tail.read() - *lines, pending = pending.split("\n") - for line in lines: - if match := CYCLE.match(line): - cycles.setdefault(int(match.group(1)), now - started) - if now >= next_sample: - memory = rss_mb(game.pid) - if memory is not None: - samples.append((now - started, memory)) - rss.write(f"{now - started:.1f},{memory:.1f}\n") - rss.flush() - next_sample = now + args.rss_every - time.sleep(min(0.2, args.rss_every)) - report = [line for line in (args.out / "game.log").read_text(encoding="utf-8", errors="replace").splitlines() - if line.startswith("SOAK ")] + game.wait() + read_new(tail) + log_text = (out / "game.log").read_text(encoding="utf-8", errors="replace") + report = [line for line in log_text.splitlines() if line.startswith("SOAK ")] print("\n".join(report) if report else "soak: the game printed no SOAK lines; see game.log") - message, grew = rss_verdict(samples, cycles, args.max_rss_growth) + message, grew = rss_verdict(hub_rss, args.max_rss_growth) print(f"soak: {message}") if timed_out: print(f"soak: the game ran past {args.minutes:g} + {args.grace:g} minutes and was stopped", file=sys.stderr) @@ -131,10 +160,13 @@ def main(argv: list[str] | None = None) -> int: if game.returncode != 0: print(f"soak: the game exited with status {game.returncode}", file=sys.stderr) return 1 + if not any(line.startswith(VERDICT) for line in report): + print("soak: the game exited without a soak verdict; is it a build that knows --soak?", file=sys.stderr) + return 1 if grew: print("soak: resident memory kept growing", file=sys.stderr) return 1 - print(f"soak: passed; results in {args.out}") + print(f"soak: passed; results in {out}") return 0 diff --git a/tools/booth/test_soak.py b/tools/booth/test_soak.py index c460c527..a2a3e6f5 100644 --- a/tools/booth/test_soak.py +++ b/tools/booth/test_soak.py @@ -3,6 +3,7 @@ import io import json +import os import sys import tempfile import unittest @@ -12,36 +13,28 @@ sys.path.insert(0, str(Path(__file__).resolve().parent)) import soak # noqa: E402 -# Records its arguments, announces passes over the routes like the game, then behaves as its first -# argument says. "grow" and "warmup" add 8 MB at a time, touched so it counts as resident memory. +# Records its arguments, then announces hub visits like the game, writing the visit number to a +# state file just before each announcement and holding it for longer than the wrapper's poll. The +# tests' memory sampler reads that file, so each hub visit gets a fixed memory value. FAKE_GAME = r""" -import json, sys, time -mode = sys.argv[1] -with open(sys.argv[2], "w") as record: - json.dump(sys.argv[3:], record) -hold = [] -def grow(blocks): - for _ in range(blocks): - hold.append(bytearray(8 * 1024 * 1024)) - hold[-1][::4096] = b"x" * len(hold[-1][::4096]) - time.sleep(0.05) +import json, os, sys, time +mode, record, state = sys.argv[1], sys.argv[2], sys.argv[3] +with open(record, "w") as handle: + json.dump(sys.argv[4:], handle) +with open(record + ".pid", "w") as handle: + handle.write(str(os.getpid())) +def visit(n): + with open(state, "w") as handle: + handle.write(str(n)) + print(f"SOAK hub {n} at {n * 10.0:.1f} s", flush=True) + time.sleep(0.6) if mode == "hang": time.sleep(1000) -print("SOAK cycle 1 at 0.0 s", flush=True) -if mode == "short": - grow(12) - time.sleep(0.6) - sys.exit(0) -grow(12 if mode == "warmup" else 0) # loading everything once is not a leak -time.sleep(0.4) -print("SOAK cycle 2 at 30.0 s", flush=True) -time.sleep(0.4) -print("SOAK cycle 3 at 60.0", end="", flush=True) # a line split across reads -time.sleep(0.3) -print(" s", flush=True) -grow(12 if mode == "grow" else 0) -time.sleep(0.6) -print("SOAK verdict: steady", flush=True) +visits = 2 if mode == "short" else 3 +for n in range(1, visits + 1): + visit(n) +if mode != "silent": + print("SOAK verdict: steady", flush=True) sys.exit(1 if mode == "leaky" else 0) """ @@ -54,47 +47,72 @@ def setUp(self) -> None: self.fake = self.dir / "fake_game.py" self.fake.write_text(FAKE_GAME, encoding="utf-8") self.args_file = self.dir / "args.json" + self.state = self.dir / "state" self.out = self.dir / "results" - def run_soak(self, mode: str, *options: str, game_args: tuple[str, ...] = ("--", "--booth")) -> tuple[int, str, str]: + def sampler(self, by_visit: dict[int, float]): + """Memory for the hub visit the fake game last announced (100 MB before the first).""" + def sample(_pid: int) -> float: + text = self.state.read_text() if self.state.exists() else "" + return by_visit.get(int(text), 100.0) if text else 100.0 + return sample + + def run_soak(self, mode: str, *options: str, memory: dict[int, float] | None = None, + game_args: tuple[str, ...] = ("--", "--booth")) -> tuple[int, str, str]: argv = ["--minutes", "0.05", "--dwell", "2", "--out", str(self.out), "--rss-every", "0.1", *options, - "--", sys.executable, str(self.fake), mode, str(self.args_file), *game_args] + "--", sys.executable, str(self.fake), mode, str(self.args_file), str(self.state), *game_args] with redirect_stdout(io.StringIO()) as out, redirect_stderr(io.StringIO()) as err: - code = soak.main(argv) + code = soak.main(argv, sample=self.sampler(memory or {})) return code, out.getvalue(), err.getvalue() + def run_folder(self) -> Path: + folders = list(self.out.iterdir()) + self.assertEqual(len(folders), 1) + return folders[0] + def test_passes_the_soak_arguments_after_the_games_separator(self) -> None: - code, out, _ = self.run_soak("steady") + code, out, _ = self.run_soak("steady", game_args=("--", "--booth", "--soak=999", "--soak-dwell=1")) self.assertEqual(code, 0, out) self.assertEqual(json.loads(self.args_file.read_text()), - ["--", "--booth", "--soak=0.05", "--soak-dwell=2", f"--soak-log={self.out.resolve()}"]) - self.assertIn("SOAK verdict: steady", out) + ["--", "--booth", "--soak=0.05", "--soak-dwell=2", f"--soak-log={self.run_folder().resolve()}"], + "the wrapper's soak options replace any already in the command") self.assertIn("soak: passed", out) def test_adds_a_separator_when_the_game_has_none(self) -> None: self.run_soak("steady", game_args=()) self.assertEqual(json.loads(self.args_file.read_text())[0], "--") - def test_samples_resident_memory(self) -> None: + def test_each_run_gets_its_own_folder(self) -> None: self.run_soak("steady") - rows = (self.out / "rss.csv").read_text().splitlines() + self.run_soak("steady") + folders = sorted(self.out.iterdir()) + self.assertEqual(len(folders), 2) + for folder in folders: + self.assertTrue((folder / "game.log").is_file() and (folder / "rss.csv").is_file()) + + def test_samples_resident_memory_with_ps(self) -> None: + argv = ["--minutes", "0.05", "--out", str(self.out), "--rss-every", "0.1", + "--", sys.executable, str(self.fake), "steady", str(self.args_file), str(self.state)] + with redirect_stdout(io.StringIO()): + soak.main(argv) # the real sampler + rows = (self.run_folder() / "rss.csv").read_text().splitlines() self.assertEqual(rows[0], "elapsed_s,rss_mb") self.assertGreaterEqual(len(rows), 4) self.assertTrue(all(float(row.split(",")[1]) > 0 for row in rows[1:])) - self.assertIn("SOAK verdict: steady", (self.out / "game.log").read_text()) - def test_fails_when_resident_memory_keeps_growing(self) -> None: - code, out, err = self.run_soak("grow", "--max-rss-growth", "20") + def test_fails_when_memory_grows_between_hub_visits(self) -> None: + code, out, err = self.run_soak("steady", "--max-rss-growth", "20", memory={1: 100.0, 2: 100.0, 3: 300.0}) self.assertEqual(code, 1, out + err) + self.assertIn("hub visits 2 -> 3", out) self.assertIn("resident memory kept growing", err) - def test_growth_during_the_first_pass_is_warm_up(self) -> None: - code, out, err = self.run_soak("warmup", "--max-rss-growth", "20") + def test_growth_before_the_second_hub_visit_is_warm_up(self) -> None: + code, out, err = self.run_soak("steady", "--max-rss-growth", "20", memory={1: 50.0, 2: 300.0, 3: 305.0}) self.assertEqual(code, 0, out + err) self.assertIn("soak: passed", out) - def test_needs_three_passes_to_judge_memory(self) -> None: - code, out, _ = self.run_soak("short", "--max-rss-growth", "20") + def test_needs_three_hub_visits_to_judge_memory(self) -> None: + code, out, _ = self.run_soak("short", "--max-rss-growth", "20", memory={1: 100.0, 2: 900.0}) self.assertEqual(code, 0) self.assertIn("needs 3 to judge", out) @@ -103,11 +121,31 @@ def test_fails_when_the_game_reports_growth(self) -> None: self.assertEqual(code, 1) self.assertIn("exited with status 1", err) + def test_fails_when_the_game_never_gives_a_verdict(self) -> None: + code, _, err = self.run_soak("silent") + self.assertEqual(code, 1) + self.assertIn("without a soak verdict", err) + def test_stops_a_game_that_outlasts_its_time(self) -> None: code, _, err = self.run_soak("hang", "--grace", "0.02") self.assertEqual(code, 2) self.assertIn("was stopped", err) + def test_reaps_the_game_when_monitoring_fails(self) -> None: + pid_file = Path(f"{self.args_file}.pid") + + def broken(_pid: int) -> float: + if not pid_file.exists(): + return 100.0 # break only once the game is up and has said who it is + raise RuntimeError("sampler broke") + argv = ["--minutes", "0.05", "--out", str(self.out), "--rss-every", "0.1", + "--", sys.executable, str(self.fake), "hang", str(self.args_file), str(self.state)] + with redirect_stdout(io.StringIO()), self.assertRaises(RuntimeError): + soak.main(argv, sample=broken) + pid = int(pid_file.read_text()) + with self.assertRaises(ProcessLookupError, msg="the hanging game was killed and reaped"): + os.kill(pid, 0) + def test_godot_mode_runs_this_checkouts_project(self) -> None: args = soak.argparse.Namespace(godot="/opt/godot", command=[], minutes=480.0, dwell=30.0) self.assertEqual(soak.game_command(args, Path("out")), @@ -115,22 +153,22 @@ def test_godot_mode_runs_this_checkouts_project(self) -> None: f"--soak-log={Path('out').resolve()}"]) def test_rss_verdict(self) -> None: - passes = {1: 0.0, 2: 100.0, 3: 200.0} - self.assertFalse(soak.rss_verdict([(0, 100.0)], {1: 0.0, 2: 100.0}, 25)[1]) - warmup_then_steady = [(t, 100.0 if t < 100 else 300.0 + t / 100) for t in range(0, 400, 40)] - self.assertFalse(soak.rss_verdict(warmup_then_steady, passes, 25)[1]) - growing = [(t, 100.0 + t) for t in range(0, 400, 40)] - message, grew = soak.rss_verdict(growing, passes, 25) + self.assertFalse(soak.rss_verdict({1: 100.0, 2: 100.0}, 25)[1]) + self.assertFalse(soak.rss_verdict({1: 50.0, 2: 300.0, 3: 310.0}, 25)[1]) + message, grew = soak.rss_verdict({1: 100.0, 2: 100.0, 3: 120.0, 4: 200.0}, 25) self.assertTrue(grew) - self.assertIn("limit 25%", message) - self.assertIn("too few", soak.rss_verdict([(10, 100.0), (150, 120.0)], passes, 25)[0]) + self.assertIn("hub visits 2 -> 4", message) + self.assertIn("needs 3", soak.rss_verdict({1: 100.0, 3: 100.0, 4: 100.0}, 25)[0]) def test_rejects_bad_usage(self) -> None: for argv in (["--minutes", "1"], ["--minutes", "0", "--", "game"], - ["--minutes", "1", "--godot", "g", "--", "game"]): + ["--minutes", "1", "--godot", "g", "--", "game"], + ["--minutes", "inf", "--", "game"], ["--minutes", "1", "--grace", "nan", "--", "game"], + ["--minutes", "1", "--max-rss-growth", "-5", "--", "game"]): with redirect_stderr(io.StringIO()), self.assertRaises(SystemExit) as stop: soak.main(argv) self.assertEqual(stop.exception.code, 2, argv) + self.assertFalse(self.out.exists(), "a refused run creates no folder") def test_missing_game_is_an_error(self) -> None: with redirect_stdout(io.StringIO()), redirect_stderr(io.StringIO()) as err: diff --git a/tools/tests/suites.toml b/tools/tests/suites.toml index ec9681c7..b6d27c03 100644 --- a/tools/tests/suites.toml +++ b/tools/tests/suites.toml @@ -14,6 +14,7 @@ menu_hoppy_smoke = "Drives the menu with pointer hover, which a headless run nev capture_code_city_bosses = "Writes the Code City boss stills into docs/previews/; a graphical run only." exit_leak = "Needs a --scenario per process; CI runs every scenario through tools/checks/exit_leak.py." "support/session_log_quit" = "Child process for booth_session_log: it quits through AppRouter on purpose." +"support/soak_leak" = "Child process for booth_soak: it leaks nodes on purpose so the soak must fail." # Suites with wall-clock budgets, or that occupy every core, run alone after the parallel # batch, so CPU contention from other suites can't fail them (or them, the others). From dac69c856c6dff9c3ab3ea6a129df13e6aa0db1a Mon Sep 17 00:00:00 2001 From: Erik Thorelli Date: Thu, 15 Oct 2026 19:30:25 -0700 Subject: [PATCH 3/4] fix(booth): end soaks by pass count in tests and keep a failed route's result [Agent: Claude Code | Model: Opus 5.5 | Thinking: High | Acting on behalf of: Erik | Skill: none] - CI failed booth_soak: a fixed 24-second soak didn't reach every route on a loaded 2-core runner. --soak-cycles= ends a soak after n full passes (the minutes remain a backstop), so the suite's runs no longer depend on how fast routes load: one pass over every route, and three passes over hub and platformer for the steady and leaking verdicts. It also makes a quick one-pass frame-rate probe. - Addresses CodeRabbit review 5542177191 on #83: a route that fails while the deadline hits is recorded before the finished guard, and _finish() waits for the change under way before judging, so the failure exits 2. A hub visit is counted once even when it ends a pass. --- docs/builds.md | 2 +- hoppys-adventure-arcade/app/booth_soak.gd | 33 +++++++++++++++++---- hoppys-adventure-arcade/tests/booth_soak.gd | 19 ++++++------ 3 files changed, 38 insertions(+), 16 deletions(-) diff --git a/docs/builds.md b/docs/builds.md index 5446a81f..853c8862 100644 --- a/docs/builds.md +++ b/docs/builds.md @@ -56,7 +56,7 @@ python3 tools/booth/soak.py --minutes 600 -- "/Applications/Hoppy’s Adventure python3 tools/booth/soak.py --minutes 10 --godot "$GODOT" # a quick run of this checkout's project ``` -- **The soak.** The game runs with `--soak=` (wall-clock time). It visits every route in turn and stays `--soak-dwell=` (default 30) on each with nobody playing, counted from when the route has opened. `--soak-routes=hub,heroes_vs_villains` keeps it to those routes; the hub is always included. A soak turns off the idle return and the game-over card, ignores `--route`, and writes no session log, so its visits never count as booth sessions. +- **The soak.** The game runs with `--soak=` (wall-clock time). It visits every route in turn and stays `--soak-dwell=` (default 30) on each with nobody playing, counted from when the route has opened. `--soak-routes=hub,heroes_vs_villains` keeps it to those routes; the hub is always included. `--soak-cycles=` ends it after n full passes, if that comes first: `--soak=30 --soak-cycles=1` is a quick frame-rate probe of every route. A soak turns off the idle return and the game-over card, ignores `--route`, and writes no session log, so its visits never count as booth sessions. - **Frame rate.** Every 5 seconds the game appends a CSV row for the current route: frames per second, median, 99th-percentile and worst frame times, and the engine's memory and object counts. At the end it prints a table per route: the share of frames slower than 16.7 ms (60 fps) and 33.3 ms (30 fps), percentiles capped at the worst frame, and the worst loading hitch. Run it fullscreen (`--booth`) on the booth hardware to measure at the booth resolution; headless frame times mean nothing. - **Leak check.** At the end of each hub visit the game records its object, node, orphan-node and resource counts and prints `SOAK hub `. It compares the second visit with the last, since the first warms caches. Debug builds also compare static memory, which release builds don't report. Growth beyond small limits makes the game exit 1. A route that won't open, or results that can't be written, make it exit 2. - **Resident memory.** `soak.py` samples the process's memory with `ps` every 30 seconds (`--rss-every`) into `rss.csv`, and again at each `SOAK hub ` line. It compares the second hub visit with the last, once there are three, and fails above 25% growth (`--max-rss-growth`). It also fails a game that exits without a verdict, and stops a run that outlasts its time by 10 minutes (`--grace`). Each run gets its own folder under `soak-results/` (`--out`), holding the game's CSV and summary, `game.log` and `rss.csv`. macOS and Linux. diff --git a/hoppys-adventure-arcade/app/booth_soak.gd b/hoppys-adventure-arcade/app/booth_soak.gd index 33fcca09..42f89a8e 100644 --- a/hoppys-adventure-arcade/app/booth_soak.gd +++ b/hoppys-adventure-arcade/app/booth_soak.gd @@ -6,7 +6,8 @@ extends Node ## the end it prints a frame-rate table per route and a leak check, writes both next to the CSV in ## `--soak-log=` (default user://soak), and quits: 0 when the counts held steady, 1 when ## they kept growing, 2 when a route failed to open or the results couldn't be written. -## `--soak-routes=hub,heroes_vs_villains` limits the soak to those routes (the hub is always one). +## `--soak-routes=hub,heroes_vs_villains` limits the soak to those routes (the hub is always one), +## and `--soak-cycles=` ends it after n full passes if that comes before the minutes run out. ## Run it rendered and fullscreen on the booth machine for frame rates at the booth resolution; ## headless runs measure only the leak check. tools/booth/soak.py wraps a run and adds the ## process's resident memory, which release builds can't report from inside; it reads the @@ -15,6 +16,7 @@ const MINUTES_PREFIX := "--soak=" const DWELL_PREFIX := "--soak-dwell=" const FOLDER_PREFIX := "--soak-log=" const ROUTES_PREFIX := "--soak-routes=" +const CYCLES_PREFIX := "--soak-cycles=" const DEFAULT_DWELL := 30.0 const MIN_DWELL := 0.2 const DEFAULT_FOLDER := "user://soak" @@ -41,6 +43,8 @@ var settle := SETTLE_SECONDS var folder := DEFAULT_FOLDER ## The routes named by --soak-routes, or empty for all of them. var only: PackedStringArray = [] +## Full passes after which the soak ends (--soak-cycles), or 0 for no limit. +var max_cycles := 0 var csv_path := "" var summary_path := "" var router: Node @@ -61,6 +65,8 @@ var stats := {} var load_hitch := {"ms": 0.0, "route": ""} ## Engine counts at the end of each settled hub visit, for the leak check. var hub_snapshots: Array[Dictionary] = [] +## Whether this visit to the hub has been counted already. +var hub_counted := false ## Why the soak can't be trusted, if anything went wrong: a route that didn't open, or results ## that couldn't be written. Either makes the exit status 2. var failure := "" @@ -94,6 +100,12 @@ func _init(soak_minutes: float, args: PackedStringArray) -> void: folder = arg.trim_prefix(FOLDER_PREFIX) elif arg.begins_with(ROUTES_PREFIX): only = arg.trim_prefix(ROUTES_PREFIX).split(",", false) + elif arg.begins_with(CYCLES_PREFIX): + var value := arg.trim_prefix(CYCLES_PREFIX) + if value.is_valid_int() and value.to_int() > 0: + max_cycles = value.to_int() + else: + push_warning("--soak-cycles needs a whole number above 0, not %s; no limit" % value) settle = minf(SETTLE_SECONDS, dwell * 0.5) func _ready() -> void: @@ -150,21 +162,26 @@ func _route() -> String: ## Open the next route and wait for it. The dwell starts once the scene is there; a route that ## doesn't open ends the soak, since its samples would carry the wrong label. func _next_route() -> void: + if index == routes.size() - 1 and max_cycles > 0 and cycle >= max_cycles: + _finish() + return index = (index + 1) % routes.size() if index == 0: cycle += 1 print("SOAK cycle %d at %.1f s" % [cycle, elapsed]) var route := routes[index] on_route = 0.0 + hub_counted = false window.clear() changing = true var opened: bool = await router.go(route) changing = false var scene := get_tree().current_scene - if finished: - return - if not opened or scene == null or scene.scene_file_path != router.ROUTES[route]: + # Record a failed route before anything else: _finish() may already be waiting on this change. + var failed: bool = not opened or scene == null or scene.scene_file_path != router.ROUTES[route] + if failed and failure == "": failure = "route %s did not open" % route + if failed and not finished: _finish() func _hitch(span: float) -> void: @@ -188,6 +205,9 @@ func _count(span: float) -> void: entry.slow[i] += 1 func _snapshot_hub() -> void: + if hub_counted: + return + hub_counted = true hub_snapshots.append(_counts()) # tools/booth/soak.py samples resident memory when it reads this line. print("SOAK hub %d at %.1f s" % [hub_snapshots.size(), elapsed]) @@ -296,6 +316,9 @@ func _finish() -> void: if finished: return finished = true + # A route change under way decides whether the soak failed; let it land first. + while changing or router.busy: + await get_tree().process_frame if not window.is_empty(): _sample() if _route() == "hub" and not changing and not router.busy and on_route >= dwell: @@ -310,8 +333,6 @@ func _finish() -> void: file.close() print(text) print("SOAK summary at %s" % ProjectSettings.globalize_path(summary_path)) - if router.busy: - await get_tree().create_timer(1.0, true).timeout router.go("hub") await get_tree().create_timer(1.0, true).timeout get_tree().unload_current_scene() diff --git a/hoppys-adventure-arcade/tests/booth_soak.gd b/hoppys-adventure-arcade/tests/booth_soak.gd index f6aa9ed9..fc35bc03 100644 --- a/hoppys-adventure-arcade/tests/booth_soak.gd +++ b/hoppys-adventure-arcade/tests/booth_soak.gd @@ -10,10 +10,10 @@ const ChildGame := preload("res://tests/support/child_game.gd") const FOLDER := "user://test_soak" const SHORT_FOLDER := "user://test_soak_short" const LEAK_FOLDER := "user://test_soak_leak" -## Every route at least once, even on a slow CI runner. -const FULL := ["--soak=0.4", "--soak-dwell=0.6"] -## Two light routes: three settled hub visits in seconds. -const SHORT := ["--soak=0.2", "--soak-dwell=0.6", "--soak-routes=hub,platformer"] +## One pass over every route, however slowly a CI runner loads them (the minutes are a backstop). +const FULL := ["--soak=4", "--soak-cycles=1", "--soak-dwell=0.6"] +## Three passes over two light routes: exactly three settled hub visits. +const SHORT := ["--soak=4", "--soak-cycles=3", "--soak-dwell=0.6", "--soak-routes=hub,platformer"] var failures := 0 func _initialize() -> void: @@ -59,8 +59,9 @@ func run() -> void: "A zero, non-numeric or infinite --soak runs no soak") var endless := BoothSoak.new(10.0, PackedStringArray(["--soak-dwell=1e999"])) check(endless.dwell == BoothSoak.DEFAULT_DWELL, "An infinite --soak-dwell keeps the default") - var short := BoothSoak.new(10.0, PackedStringArray(["--soak-dwell=0.6"])) - check(is_equal_approx(short.settle, 0.3), "A short dwell settles for half of it") + var short := BoothSoak.new(10.0, PackedStringArray(["--soak-dwell=0.6", "--soak-cycles=3"])) + check(is_equal_approx(short.settle, 0.3) and short.max_cycles == 3, + "A short dwell settles for half of it, and --soak-cycles caps the passes") var histogram := PackedInt32Array() histogram.resize(BoothSoak.BUCKETS + 1) @@ -102,8 +103,8 @@ func run() -> void: "The frame-rate table has a row for every route (missing %s)" % [missing]) var written := results(FOLDER) var rows: PackedStringArray = String(written.csv).strip_edges().split("\n") - check(rows.size() > 3 and rows[0] == ",".join(BoothSoak.COLUMNS), - "The CSV has the documented columns and a row per sample") + check(rows.size() >= 2 and rows[0] == ",".join(BoothSoak.COLUMNS), + "The CSV has the documented columns and sample rows") check(String(written.summary).contains("SOAK verdict: ") and String(written.summary).contains("SOAK worst load hitch"), "The summary file holds the table and the verdict") @@ -113,7 +114,7 @@ func run() -> void: short_args.append("--soak-log=" + ProjectSettings.globalize_path(SHORT_FOLDER)) var short_run: Dictionary = await ChildGame.run(self, short_args, 300.0) check(short_run.code == 0 and short_run.log.contains("SOAK hub 3 at") - and short_run.log.contains("SOAK verdict: steady") + and not short_run.log.contains("SOAK hub 4 at") and short_run.log.contains("SOAK verdict: steady") and not RegEx.create_from_string("(?m)^SOAK runner_game +\\d+").search(short_run.log), "--soak-routes keeps to its routes, announces hub visits and judges them steady") From 3d1b91af1cee6503429d9a09c1e571fe56a481da Mon Sep 17 00:00:00 2001 From: Erik Thorelli Date: Thu, 15 Oct 2026 19:41:47 -0700 Subject: [PATCH 4/4] test(booth): let the pass count, not the deadline, end the suite's soaks [Agent: Claude Code | Model: Opus 5.5 | Thinking: High | Acting on behalf of: Erik | Skill: none] Addresses CodeRabbit review 5542359308 on #83: the soaks' in-game deadline is now 60 minutes, far beyond the 300-second child timeout (CHILD_SECONDS), so --soak-cycles always ends them and the child timeout is the hard bound. --- hoppys-adventure-arcade/tests/booth_soak.gd | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/hoppys-adventure-arcade/tests/booth_soak.gd b/hoppys-adventure-arcade/tests/booth_soak.gd index fc35bc03..615e3661 100644 --- a/hoppys-adventure-arcade/tests/booth_soak.gd +++ b/hoppys-adventure-arcade/tests/booth_soak.gd @@ -10,10 +10,12 @@ const ChildGame := preload("res://tests/support/child_game.gd") const FOLDER := "user://test_soak" const SHORT_FOLDER := "user://test_soak_short" const LEAK_FOLDER := "user://test_soak_leak" -## One pass over every route, however slowly a CI runner loads them (the minutes are a backstop). -const FULL := ["--soak=4", "--soak-cycles=1", "--soak-dwell=0.6"] +## One pass over every route, however slowly a CI runner loads them. The pass count ends these +## runs: the in-game deadline is far beyond CHILD_SECONDS, which is the hard bound. +const FULL := ["--soak=60", "--soak-cycles=1", "--soak-dwell=0.6"] ## Three passes over two light routes: exactly three settled hub visits. -const SHORT := ["--soak=4", "--soak-cycles=3", "--soak-dwell=0.6", "--soak-routes=hub,platformer"] +const SHORT := ["--soak=60", "--soak-cycles=3", "--soak-dwell=0.6", "--soak-routes=hub,platformer"] +const CHILD_SECONDS := 300.0 var failures := 0 func _initialize() -> void: @@ -93,7 +95,7 @@ func run() -> void: var args: Array[String] = ["--"] args.append_array(FULL) args.append("--soak-log=" + ProjectSettings.globalize_path(FOLDER)) - var clean_run: Dictionary = await ChildGame.run(self, args, 300.0) + var clean_run: Dictionary = await ChildGame.run(self, args, CHILD_SECONDS) check(clean_run.code == 0, "A soak over every route exits 0 (exit %d)" % clean_run.code) var missing := [] for route: String in root.get_node("AppRouter").ROUTES.keys(): @@ -112,7 +114,7 @@ func run() -> void: var short_args: Array[String] = ["--"] short_args.append_array(SHORT) short_args.append("--soak-log=" + ProjectSettings.globalize_path(SHORT_FOLDER)) - var short_run: Dictionary = await ChildGame.run(self, short_args, 300.0) + var short_run: Dictionary = await ChildGame.run(self, short_args, CHILD_SECONDS) check(short_run.code == 0 and short_run.log.contains("SOAK hub 3 at") and not short_run.log.contains("SOAK hub 4 at") and short_run.log.contains("SOAK verdict: steady") and not RegEx.create_from_string("(?m)^SOAK runner_game +\\d+").search(short_run.log), @@ -121,7 +123,7 @@ func run() -> void: var leak_args: Array[String] = ["--script", "res://tests/support/soak_leak.gd", "--"] leak_args.append_array(SHORT) leak_args.append("--soak-log=" + ProjectSettings.globalize_path(LEAK_FOLDER)) - var leaky: Dictionary = await ChildGame.run(self, leak_args, 300.0) + var leaky: Dictionary = await ChildGame.run(self, leak_args, CHILD_SECONDS) check(leaky.code == 1 and leaky.log.contains("SOAK verdict: GROWING: ") and leaky.log.contains("orphan_nodes"), "A soak next to a node leak judges it growing and exits 1 (exit %d)" % leaky.code)