From e8fa4e3f56ff83cd583a6250681514205e5c9a93 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Henrik=20Rydg=C3=A5rd?= Date: Thu, 10 Sep 2026 15:08:35 -0600 Subject: [PATCH] headless: split --timeout into --timeout-wall and --timeout-emulated --timeout was wall-clock seconds, which is what CI wants but not what you want when the question is whether the game has 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 budget means very different amounts of game time. Booting a firmware VSH is a good example - 10 emulated seconds is about 25 real ones on 6.61 and about 7 on 2.00, and judging those two by the same wall-clock number makes a working shell look stuck. Both limits can be set at once and whichever is reached first ends the run, which also says which one it was. --timeout still works as the old name for --timeout-wall. The IsDebuggerPresent() exemption stays on the wall-clock check only; the emulated one doesn't need it, since sitting at a native breakpoint burns no emulated time. Co-Authored-By: Claude Opus 5 (1M context) --- Core/CmdLine.cpp | 5 ++++- Core/CmdLine.h | 7 ++++++- docs/debugging.md | 20 ++++++++++++++------ docs/pspautotests.md | 7 ++++--- headless/Headless.cpp | 41 ++++++++++++++++++++++++++++++----------- test.py | 2 +- unittest/UnitTest.cpp | 21 +++++++++++++++++++-- 7 files changed, 78 insertions(+), 25 deletions(-) diff --git a/Core/CmdLine.cpp b/Core/CmdLine.cpp index ff8345744c..692be4b3c3 100644 --- a/Core/CmdLine.cpp +++ b/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}, diff --git a/Core/CmdLine.h b/Core/CmdLine.h index b5c32ad835..0ae02fe088 100644 --- a/Core/CmdLine.h +++ b/Core/CmdLine.h @@ -158,7 +158,12 @@ struct CommandLineOptions { std::optional compare; std::optional bench; std::optional verbose; - std::optional 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 timeoutWall; + std::optional timeoutEmulated; std::optional printEqualLines; std::optional screenshotFilename; diff --git a/docs/debugging.md b/docs/debugging.md index 6336551329..04e57cc5e8 100644 --- a/docs/debugging.md +++ b/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 diff --git a/docs/pspautotests.md b/docs/pspautotests.md index 6dca31b9ec..24134285fc 100644 --- a/docs/pspautotests.md +++ b/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 diff --git a/headless/Headless.cpp b/headless/Headless.cpp index fec6dce58e..86d74fb94a 100644 --- a/headless/Headless.cpp +++ b/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,25 @@ 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; + const double startEmulatedTime = CoreTiming::GetGlobalTimeUs() / 1000000.0; + // 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; + const double emulatedDeadline = startEmulatedTime + opt.timeoutEmulated; + // 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; + const double emulatedSaveStateAt = startEmulatedTime + opt.timeoutEmulated * 0.7; 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; + if (!g_stateToSave.empty() && (time_now_d() > wallSaveStateAt || emulatedNow > emulatedSaveStateAt)) { 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 +428,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 = CoreTiming::GetGlobalTimeUs() / 1000000.0 > emulatedDeadline; + 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 +557,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 +651,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::infinity()); + testOptions.timeoutWall = cmdLineOptions.timeoutWall.value_or(std::numeric_limits::infinity()); + testOptions.timeoutEmulated = cmdLineOptions.timeoutEmulated.value_or(std::numeric_limits::infinity()); testOptions.verbose = cmdLineOptions.verbose.value_or(false); testOptions.printEqualLines = cmdLineOptions.printEqualLines.value_or(false); testOptions.maxScreenshotError = cmdLineOptions.maxScreenshotError.value_or(0.0); diff --git a/test.py b/test.py index 62a540448d..1246f5ed54 100755 --- a/test.py +++ b/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)) diff --git a/unittest/UnitTest.cpp b/unittest/UnitTest.cpp index cf93941494..df11db0120 100644 --- a/unittest/UnitTest.cpp +++ b/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 {