Merge pull request #22303 from hrydgard/headless-timeout-split

Headless timeout: Split into game-time timeout and wall-time timeout

Core/CmdLine.cpp

@@ -206,7 +206,10 @@ static const CommandLineParam g_autoParams[] = {
 	{POFF(screenshotFilenameSave), CmdParamType::String, "screenshot-save", '\0', "Save rendered screenshot to specified path (PNG if the path ends in .png, BMP otherwise)", CmdLineMode::Headless},
 	{POFF(screenshotFilenameDiff), CmdParamType::String, "screenshot-diff", '\0', "Save a visual comparison image to FILE when comparing screenshots", CmdLineMode::Headless},
 	{POFF(screenshotSaveKeepAlpha), CmdParamType::Bool, "screenshot-keep-alpha", '\0', "Preserve the alpha channel when saving PNG screenshots (default: alpha is forced to 255)", CmdLineMode::Headless},
-	{POFF(timeout), CmdParamType::Double, "timeout", '\0', "Set the timeout value", CmdLineMode::Headless},
+	{POFF(timeoutWall), CmdParamType::Double, "timeout-wall", '\0', "Stop the run after this many real seconds", CmdLineMode::Headless},
+	{POFF(timeoutEmulated), CmdParamType::Double, "timeout-emulated", '\0', "Stop the run after this many emulated seconds", CmdLineMode::Headless},
+	// The old name for --timeout-wall, kept working because it's in a lot of scripts.
+	{POFF(timeoutWall), CmdParamType::Double, "timeout", '\0', "Alias for --timeout-wall", CmdLineMode::Headless},
 	{POFF(maxScreenshotError), CmdParamType::Double, "max-mse", '\0', "Maximum allowed MSE error for screenshot comparison", CmdLineMode::Headless},
 	{POFF(mountIso), CmdParamType::String, "mount", 'm', "Mount ISO/CSO on umd1:", CmdLineMode::Headless},
 	{POFF(unpackUpdater), CmdParamType::String, "unpack-updater", '\0', "Unpack the firmware in an updater EBOOT.PBP into DIR and exit", CmdLineMode::Headless},

Core/CmdLine.h

@@ -158,7 +158,12 @@ struct CommandLineOptions {
 	std::optional<bool> compare;
 	std::optional<bool> bench;
 	std::optional<bool> verbose;
-	std::optional<double> timeout;
+	// Two independent limits on a headless run, either or both may be set - whichever is reached
+	// first stops it. Wall-clock is what CI wants (a test that hangs must not hang the machine);
+	// emulated is what you want when the question is "has the game had long enough", since a
+	// heavy scene can run tens of times slower than real time and a near-idle one much faster.
+	std::optional<double> timeoutWall;
+	std::optional<double> timeoutEmulated;
 	std::optional<bool> printEqualLines;
 
 	std::optional<std::string> screenshotFilename;

docs/debugging.md

@@ -47,16 +47,24 @@ platforms. Where arch is x64 or ARM64.
 A working invocation, and the traps around it:
 
 ```bash
-./Windows/x64/Debug/PPSSPPHeadless.exe -i --debugger=34567 --timeout=100000 --graphics=software --log \
+./Windows/x64/Debug/PPSSPPHeadless.exe -i --debugger=34567 --timeout-wall=100000 --graphics=software --log \
     --root pspautotests/tests/../ pspautotests/tests/cpu/cpu_alu/cpu_alu.prx > hl.log 2>&1 &
 # wait for "Listening on port" in hl.log, then:
 ./Tools/wsdbg/target/release/wsdbg.exe 34567 --sync --sync-timeout 15 < script.txt
 ```
 
-- **`--timeout` is wall-clock seconds for the whole session**, not per test - the default is infinity, but as soon as
-  you pass one it applies to your whole interactive debugging session too. Pass something huge (`--timeout=100000`);
-  otherwise the process prints `TIMEOUT` and exits out from under you mid-session. (There's an escape hatch: the
-  deadline check is skipped while `IsDebuggerPresent()`, i.e. under a native debugger.)
+- **The timeouts apply to the whole session**, not per test. `--timeout-wall=N` is real seconds and
+  `--timeout-emulated=N` is emulated ones; both default to infinity, both can be set at once, and whichever
+  is reached first ends the run (`TIMEOUT` or `TIMEOUT (emulated)`). `--timeout` is the old name for
+  `--timeout-wall`. As soon as you pass one it applies to your whole interactive debugging session too, so
+  pass something huge (`--timeout-wall=100000`) or the process exits out from under you mid-session. The
+  wall-clock check is skipped while `IsDebuggerPresent()`; the emulated one doesn't need that escape hatch,
+  since sitting at a native breakpoint burns no emulated time.
+- **Which one you want depends on the question.** Wall-clock is what stops a hang from hanging the machine.
+  Emulated is what you want for "has the game had long enough to get somewhere" - a heavy scene runs many
+  times slower than real time and a near-idle one much faster, so the same wall-clock budget means very
+  different amounts of game time. Booting a firmware VSH to its XMB is a good example: 10 emulated seconds
+  is about 25 real ones on 6.61 and about 7 on 2.00.
 - **Prefer `--debugger=0` and scrape `Listening on port N` from that run's own log** over hardcoding a port. Also
   `taskkill //F //IM PPSSPPHeadless.exe` between runs for hygiene (Git Bash here has no `pkill`) - leftover
   instances are easy to accumulate when a script leaves the CPU stopped at a breakpoint.
@@ -112,7 +120,7 @@ A working invocation, and the traps around it:
 - **Exception and crash messages do not reach the log in headless.** It registers its own debug-output listener
   (`SendDebugOutput` in `headless/Headless.cpp`) that `fwrite`s to stdout, which is block-buffered when you
   redirect it to a file - so the output sits in the CRT buffer while the process runs, and `taskkill //F` throws
-  it away rather than flushing. To actually read a crash trace, give that run a short `--timeout` and `wait` for
+  it away rather than flushing. To actually read a crash trace, give that run a short `--timeout-wall` and `wait` for
   the process to exit on its own.
 - **`0xFFFFFFFF` is not an invalid instruction** - it decodes to `vflush`, a real Allegrex VFPU op, so writing it
   over code to test illegal-instruction handling just runs it. Check what an encoding actually is with

docs/pspautotests.md

@@ -45,7 +45,7 @@ Make sure Python is available. On Windows the Microsoft Store alias may interfer
 ### Direct headless invocation
 
 ```
-Windows/x64/Debug/PPSSPPHeadless.exe --root pspautotests/tests/../ --compare --timeout=5 --graphics=software pspautotests/tests/audio/atrac/addstreamdata.prx
+Windows/x64/Debug/PPSSPPHeadless.exe --root pspautotests/tests/../ --compare --timeout-wall=5 --graphics=software pspautotests/tests/audio/atrac/addstreamdata.prx
 ```
 
 Instead of a single PRX, you can pass a directory (e.g. `pspautotests/tests/threads/mbx/...`) to run all tests under it, recursively.
@@ -53,7 +53,8 @@ Instead of a single PRX, you can pass a directory (e.g. `pspautotests/tests/thre
 **Key flags:**
 - `--root` — points to the directory above `tests/` so the headless can find the expected directory layout.
 - `--compare` — enables output comparison against `.expected` files.
-- `--timeout=N` — seconds per test before killing it (default 5).
+- `--timeout-wall=N` — real seconds per test before killing it (default 5). `--timeout-emulated=N` is the
+  same idea in emulated time, and both can be set at once. `--timeout` is the old name for `--timeout-wall`.
 - `--graphics=software` — uses software GPU backend (required for headless; no real GPU available).
 
 ### What you'll see
@@ -138,7 +139,7 @@ returns. Don't go hunting for a wrong value; there isn't one.
 - The diff output compares the full text output line-by-line. To see PPSSPP's raw output
   without the diff overlay, omit `--compare`:
   ```
-  Windows/x64/Debug/PPSSPPHeadless.exe --root pspautotests/tests/../ --timeout=5 --graphics=software path/to/test.prx
+  Windows/x64/Debug/PPSSPPHeadless.exe --root pspautotests/tests/../ --timeout-wall=5 --graphics=software path/to/test.prx
   ```
   There's another trick too, --print-equal-lines, which prints matching lines with a '=' prefix, so you can see the full output with context.
 - Tests can show contradictory expected outputs at first glance. For example, the mbx/send

headless/Headless.cpp

@@ -4,7 +4,7 @@
 // To build on non-windows systems, just run CMake in the SDL directory, it will build both a normal ppsspp and the headless version.
 //
 // Example command line to run a test in the VS debugger (useful to debug failures):
-// > --root pspautotests/tests/../ --compare --timeout=5 --graphics=software pspautotests/tests/cpu/cpu_alu/cpu_alu.prx
+// > --root pspautotests/tests/../ --compare --timeout-wall=5 --graphics=software pspautotests/tests/cpu/cpu_alu/cpu_alu.prx
 // Example command line for taking screenshots from a frame dump:
 // > -l --graphics=vulkan --screenshot-save=vt_ref.bmp "D:\PSP ISO\dump\Depth\11578 Virtua Tennis pause menu ULES00126_0002.zip" --resolution-scale=2
 // Example command line for messing with the vsh:
@@ -317,7 +317,9 @@ static bool BootTargetIsHomebrewExecutable(const std::string &filename) {
 }
 
 struct AutoTestOptions {
-	double timeout;
+	// Both in effect at once; whichever is reached first ends the run. Infinity means "no limit".
+	double timeoutWall;
+	double timeoutEmulated;
 	double maxScreenshotError;
 	bool compare;
 	bool verbose;
@@ -376,16 +378,37 @@ static bool RunAutoTest(GraphicsContext *graphicsContext, CoreParameter &corePar
 
 	bool passed = true;
 	const double startTime = time_now_d();
-	double deadline = startTime + opt.timeout;
-	// Late enough that the game is past booting, early enough to leave the run some time after.
-	double saveStateAt = startTime + opt.timeout * 0.7;
+	// Emulated time is what you want for "has the game had long enough" - a heavy scene runs many
+	// times slower than real time and a near-idle one much faster, so a wall-clock budget says
+	// something quite different depending on what's on screen. Wall-clock is what stops a hang from
+	// hanging the machine. Either, both or neither may be set.
+	const double wallDeadline = startTime + opt.timeoutWall;
+	// Late enough that the game is past booting, early enough to leave the run some time after -
+	// against whichever limit is actually set, and the earlier of the two if both are.
+	const double wallSaveStateAt = startTime + opt.timeoutWall * 0.7;
+	// Emulated time is accumulated rather than measured from a fixed start, because loading a
+	// savestate sets the emulated clock to whatever it read when the state was written, which can
+	// be a long way either side of where this run is. One iteration of the loop below advances the
+	// clock by 0.1 seconds of emulated time at most, plus whatever an idle skip jumps to the next
+	// scheduled event - bounded in practice by vblank, so tens of milliseconds. A step of a whole
+	// second is therefore the clock being moved rather than time passing, and doesn't count.
+	const double emulatedStepLimit = 1.0;
+	double emulatedElapsed = 0.0;
+	double lastEmulatedTime = CoreTiming::GetGlobalTimeUs() / 1000000.0;
 	coreState = coreParameter.startBreak ? CORE_STEPPING_CPU : CORE_RUNNING_CPU;
 	while (coreState == CORE_RUNNING_CPU || coreState == CORE_STEPPING_CPU) {
 		// Savestate loads/saves are queued and applied here, same as EmuScreen::render does in the
 		// app. Without this, --state silently did nothing at all.
 		SaveState::Process();
 
-		if (!g_stateToSave.empty() && time_now_d() > saveStateAt) {
+		const double emulatedNow = CoreTiming::GetGlobalTimeUs() / 1000000.0;
+		const double emulatedStep = emulatedNow - lastEmulatedTime;
+		lastEmulatedTime = emulatedNow;
+		if (emulatedStep > 0.0 && emulatedStep < emulatedStepLimit) {
+			emulatedElapsed += emulatedStep;
+		}
+
+		if (!g_stateToSave.empty() && (time_now_d() > wallSaveStateAt || emulatedElapsed > opt.timeoutEmulated * 0.7)) {
 			const std::string filename = g_stateToSave;
 			g_stateToSave.clear();
 			SaveState::Save(Path(filename), -1, [](SaveState::Status status, std::string_view message, std::string_view) {
@@ -417,13 +440,18 @@ static bool RunAutoTest(GraphicsContext *graphicsContext, CoreParameter &corePar
 		if (IsDebuggerPresent())
 			debugger = true;
 #endif
-		if (time_now_d() > deadline && !debugger) {
+		// The debugger exemption is only for the wall-clock limit: sitting at a native breakpoint
+		// burns real seconds but no emulated ones, so the emulated limit can't misfire that way.
+		const bool wallTimedOut = time_now_d() > wallDeadline && !debugger;
+		const bool emulatedTimedOut = emulatedElapsed > opt.timeoutEmulated;
+		if (wallTimedOut || emulatedTimedOut) {
 			// Don't compare, print the output at least up to this point, and bail.
 			if (!opt.bench) {
 				printf("%s", output.c_str());
 
-				SendDebugOutput(DebugOutputChannel::Debug, "TIMEOUT\n");
-				GitHubActionsPrint("error", "Test timeout for %s", currentTestName.c_str());
+				SendDebugOutput(DebugOutputChannel::Debug, wallTimedOut ? "TIMEOUT\n" : "TIMEOUT (emulated)\n");
+				GitHubActionsPrint("error", "Test %s timeout for %s",
+					wallTimedOut ? "wall-clock" : "emulated-time", currentTestName.c_str());
 			}
 
 			passed = false;
@@ -541,7 +569,9 @@ int RunTests(GraphicsContext *graphicsContext, CoreParameter &coreParameter, con
 		const bool passed = RunAutoTest(graphicsContext, coreParameter, testOptions);
 		if (testOptions.bench) {
 			double st = time_now_d();
-			double deadline = st + testOptions.timeout;
+			// Benchmarking repeats the run, so budget it in real seconds regardless of what the run
+			// itself is limited by.
+			double deadline = st + testOptions.timeoutWall;
 			double runs = 0.0;
 			for (int i = 0; i < 100; ++i) {
 				RunAutoTest(graphicsContext, coreParameter, testOptions);
@@ -633,7 +663,8 @@ int main(int argc, const char* argv[]) {
 	AutoTestOptions testOptions{};
 	testOptions.compare = cmdLineOptions.compare.value_or(false);
 	testOptions.bench = cmdLineOptions.bench.value_or(false);
-	testOptions.timeout = cmdLineOptions.timeout.value_or(std::numeric_limits<double>::infinity());
+	testOptions.timeoutWall = cmdLineOptions.timeoutWall.value_or(std::numeric_limits<double>::infinity());
+	testOptions.timeoutEmulated = cmdLineOptions.timeoutEmulated.value_or(std::numeric_limits<double>::infinity());
 	testOptions.verbose = cmdLineOptions.verbose.value_or(false);
 	testOptions.printEqualLines = cmdLineOptions.printEqualLines.value_or(false);
 	testOptions.maxScreenshotError = cmdLineOptions.maxScreenshotError.value_or(0.0);

test.py

@@ -583,7 +583,7 @@ def run_tests(test_list, args):
 
   if len(test_filenames):
     # TODO: Maybe --compare should detect --graphics?
-    cmdline = [PPSSPP_EXE, '--root', TEST_ROOT + '../', '--compare', '--timeout=' + str(TIMEOUT), '@-']
+    cmdline = [PPSSPP_EXE, '--root', TEST_ROOT + '../', '--compare', '--timeout-wall=' + str(TIMEOUT), '@-']
     cmdline.extend([i for i in args if i not in ['-g', '-m', '-b']])
 
     c = Command(cmdline, '\n'.join(test_filenames))

unittest/UnitTest.cpp

@@ -2907,7 +2907,10 @@ bool TestCmdLine() {
 		EXPECT_EQ_INT((int)options.gpuBackend.value_or((GPUBackend)-1), (int)GPUBackend::DIRECT3D11);
 		EXPECT_TRUE(options.pauseMenuExit.value_or(false));
 	}
-	// --timeout is headless-only (only headless/Headless.cpp reads it), so it must be parsed in Headless mode.
+	// The timeouts are headless-only (only headless/Headless.cpp reads them), so they must be
+	// parsed in Headless mode. --timeout is the old name for --timeout-wall and sets the same
+	// field; --timeout-wall must not be swallowed by it, which is the interesting case since one
+	// name is a prefix of the other.
 	{
 		const char *argv[] = {
 			"ppsspp",
@@ -2917,7 +2920,21 @@ bool TestCmdLine() {
 		int argc = ARRAY_SIZE(argv);
 		CommandLineOptions options;
 		options.Parse(argc, argv, CmdLineMode::Headless);
-		EXPECT_EQ_INT(options.timeout.value_or(0), 3);
+		EXPECT_EQ_INT(options.timeoutWall.value_or(0), 3);
+		EXPECT_FALSE(options.timeoutEmulated.has_value());
+	}
+	{
+		const char *argv[] = {
+			"ppsspp",
+			"--timeout-wall=4",
+			"--timeout-emulated=5",
+			"My_Game.iso"
+		};
+		int argc = ARRAY_SIZE(argv);
+		CommandLineOptions options;
+		options.Parse(argc, argv, CmdLineMode::Headless);
+		EXPECT_EQ_INT(options.timeoutWall.value_or(0), 4);
+		EXPECT_EQ_INT(options.timeoutEmulated.value_or(0), 5);
 	}
 	// Test GL version override
 	{