Heretek-AI/GDevelop
1
0
Fork 0
mirror of https://github.com/Heretek-AI/GDevelop.git synced 2026-08-24 22:31:30 -04:00
Code Issues 2 Packages Projects Releases 2 Wiki Activity

Gameplay tests: exclude loading time from the test timeout, report it as loadingMs (#8947)

Browse Source 
Don't show in changelog
This commit is contained in:
Florian Rival
2026-08-10 22:27:18 +02:00
committed by GitHub
parent 3ed0b92ff9
commit 9b331ac4bc
5 changed files with 207 additions and 43 deletions
Download Patch File Download Diff File Expand all files Collapse all files
GDJS/Runtime/gameplay-tests/gameplay-test-runner.ts
+114 -20
View File
@@ -56,8 +56,13 @@ namespace gdjs {
source: string;
/** Readable state to evaluate on object/behavior snapshots. */
stateInspectors?: GameplayTestStateInspectors;
/** Wall-clock timeout for the whole run. Default: 30000. */
/** Wall-clock timeout for the RUNNING part of the test: the time
* spent waiting for the game to boot or for scene assets to load is
* excluded (bounded separately by `loadingTimeoutMs`). Default: 30000. */
timeoutMs?: number;
/** Wall-clock bound on each loading wait (game boot, scene assets),
* which is excluded from `timeoutMs`. Default: 300000. */
loadingTimeoutMs?: number;
/** Maximum number of frames stepped. Default: 20000. */
maxFrames?: number;
/**
@@ -299,8 +304,13 @@ namespace gdjs {
status: 'passed' | 'failed' | 'error' | 'stopped' | 'timeout';
framesExecuted: integer;
durationMs: number;
/** The wall-clock budget the run had (`durationMs` close to it means
* the test is at risk of timing out on a slower machine). */
/** Time spent waiting for the game to boot and for scene assets to
* load, excluded from the `timeoutMs` budget. `durationMs` includes
* it: `durationMs - loadingMs` is what counted against the budget. */
loadingMs: number;
/** The wall-clock budget the run had, loading excluded
* (`durationMs - loadingMs` close to it means the test is at risk of
* timing out on a slower machine). */
timeoutMs: number;
gameTimeMs: number;
assertions: Array<GameplayTestAssertion>;
@@ -325,6 +335,10 @@ namespace gdjs {
};
const DEFAULT_TIMEOUT_MS = 30000;
/** Loading (game boot, scene assets) is excluded from `timeoutMs` -
* on the web, a first preview can download assets for minutes - but
* still bounded, so a dead network cannot hang a run forever. */
const DEFAULT_LOADING_TIMEOUT_MS = 300000;
const DEFAULT_MAX_FRAMES = 20000;
/** How long frames are stepped before yielding once to the browser:
* the game visibly plays (a rendered frame per refresh), stop/progress
@@ -523,6 +537,10 @@ namespace gdjs {
* result as `profiles`). */
_profiles: Array<GameplayTestProfilingResult> = [];
_timeoutMs: number;
_loadingTimeoutMs: number;
/** Time spent waiting for loading (game boot, scene assets) so far:
* excluded from the `_timeoutMs` budget, reported as `loadingMs`. */
_loadingTimeMs: number = 0;
_maxFrames: integer;
/** Last time the stepping loop yielded to the browser (see
* `_maybeYield`). */
@@ -572,6 +590,8 @@ namespace gdjs {
this._runtimeGame = runtimeGame;
this._payload = payload;
this._timeoutMs = payload.timeoutMs || DEFAULT_TIMEOUT_MS;
this._loadingTimeoutMs =
payload.loadingTimeoutMs || DEFAULT_LOADING_TIMEOUT_MS;
this._maxFrames = payload.maxFrames || DEFAULT_MAX_FRAMES;
this._lastYieldTimeMs = Date.now();
this._paceSpeedFactor = payload.speedFactor
@@ -623,13 +643,58 @@ namespace gdjs {
`The test reached the maximum number of frames (${this._maxFrames}).`
);
}
if (Date.now() - this._startTimeMs > this._timeoutMs) {
if (
Date.now() - this._startTimeMs - this._loadingTimeMs >
this._timeoutMs
) {
throw new GameplayTestTimeoutError(
`The test timed out after ${this._timeoutMs}ms (wall-clock).`
`The test timed out after ${this._timeoutMs}ms ` +
'(wall-clock, loading time excluded).'
);
}
}
/**
* Await a loading promise (game boot, scene assets...) WITHOUT
* counting the wait against the `timeoutMs` budget: the timeout is
* about the running game, not about how long a web preview takes to
* download its resources. The wait is still bounded (by
* `loadingTimeoutMs`) so a dead network cannot hang the run, and
* progress heartbeats keep flowing so the editor knows the run is
* alive.
*/
async _awaitLoading(
loadingPromise: Promise<unknown>,
description: string
): Promise<void> {
const loadingStartTimeMs = Date.now();
const heartbeatIntervalId = setInterval(() => {
if (this._onProgress) this._onProgress(this._framesExecuted);
}, 1000);
let loadingTimeoutId: any = null;
try {
await Promise.race([
loadingPromise,
new Promise<never>((_, reject) => {
loadingTimeoutId = setTimeout(
() =>
reject(
new Error(
`${description} did not finish loading within ` +
`${this._loadingTimeoutMs}ms.`
)
),
this._loadingTimeoutMs
);
}),
]);
} finally {
clearInterval(heartbeatIntervalId);
if (loadingTimeoutId) clearTimeout(loadingTimeoutId);
this._loadingTimeMs += Date.now() - loadingStartTimeMs;
}
}
private _recordEvent(event: GameplayTestEvent): void {
if (this._eventLog.length >= MAX_EVENT_LOG_ENTRIES) return;
this._eventLog.push(event);
@@ -835,7 +900,13 @@ namespace gdjs {
);
}
if (!this._runtimeGame.areSceneAssetsReady(sceneName)) {
await this._runtimeGame.loadSceneAssets(sceneName);
// On the web, this can download assets for a long time (notably
// the first run of a preview): waited for as loading, outside of
// the `timeoutMs` budget.
await this._awaitLoading(
this._runtimeGame.loadSceneAssets(sceneName),
`The assets of the scene "${sceneName}"`
);
}
this._checkGuards();
this._runtimeGame
@@ -2721,6 +2792,7 @@ namespace gdjs {
status,
framesExecuted: this._framesExecuted,
durationMs: this._startTimeMs ? Date.now() - this._startTimeMs : 0,
loadingMs: Math.round(this._loadingTimeMs),
timeoutMs: this._timeoutMs,
gameTimeMs: Math.round(this._gameTimeMs),
assertions: this._assertions,
@@ -2833,7 +2905,13 @@ namespace gdjs {
// create scenes before asynchronously loaded libraries (Jolt
// physics...) are ready, or the startup could push the game's first
// scene in the middle of the test.
const bootDeadlineMs = Date.now() + harness._timeoutMs;
// This wait is loading: excluded from the `timeoutMs` budget (counted
// in `loadingMs` instead), bounded by `loadingTimeoutMs`, with
// progress heartbeats so the editor knows the run is alive.
harness._startTimeMs = Date.now();
const bootWaitStartTimeMs = Date.now();
const bootDeadlineMs = bootWaitStartTimeMs + harness._loadingTimeoutMs;
let lastBootHeartbeatTimeMs = 0;
while (runtimeGame.isStartingUp()) {
if (harness._stopped) {
currentlyRunningHarness = null;
@@ -2841,13 +2919,23 @@ namespace gdjs {
}
if (Date.now() > bootDeadlineMs) {
currentlyRunningHarness = null;
harness._loadingTimeMs += Date.now() - bootWaitStartTimeMs;
return harness._makeResult('error', [
`The game did not finish starting within ${harness._timeoutMs}ms ` +
'(the first scene was never created).',
`The game did not finish starting within ` +
`${harness._loadingTimeoutMs}ms (the first scene was never ` +
'created).',
]);
}
if (
harness._onProgress &&
Date.now() - lastBootHeartbeatTimeMs > 1000
) {
lastBootHeartbeatTimeMs = Date.now();
harness._onProgress(0);
}
await new Promise((resolve) => setTimeout(resolve, 20));
}
harness._loadingTimeMs += Date.now() - bootWaitStartTimeMs;
const inputManager = runtimeGame.getInputManager();
const wasPaused = runtimeGame.isPaused();
@@ -2911,23 +2999,29 @@ namespace gdjs {
},
};
harness._startTimeMs = Date.now();
let result: GameplayTestResult;
try {
// A wall-clock watchdog, in case the script awaits something that
// never resolves. A synchronous infinite loop can NOT be interrupted
// (this is a limit of running in the same thread as the game).
let watchdogTimeoutId: any = null;
// never resolves. Checked periodically (not a one-shot timer) so
// the time spent loading - which grows `_loadingTimeMs` - stays
// excluded from the budget. A synchronous infinite loop can NOT be
// interrupted (this is a limit of running in the same thread as
// the game).
let watchdogIntervalId: any = null;
const watchdog = new Promise<never>((_, reject) => {
watchdogTimeoutId = setTimeout(
() =>
watchdogIntervalId = setInterval(() => {
if (
Date.now() - harness._startTimeMs - harness._loadingTimeMs >
harness._timeoutMs + 1000
) {
reject(
new GameplayTestTimeoutError(
`The test timed out after ${harness._timeoutMs}ms (wall-clock).`
`The test timed out after ${harness._timeoutMs}ms ` +
'(wall-clock, loading time excluded).'
)
),
harness._timeoutMs + 1000
);
);
}
}, 250);
});
// A stop rejects this promise, interrupting the script even when
// it awaits something else than the harness (a timer, a fetch...).
@@ -2944,7 +3038,7 @@ namespace gdjs {
stopSignal,
]);
} finally {
if (watchdogTimeoutId) clearTimeout(watchdogTimeoutId);
if (watchdogIntervalId) clearInterval(watchdogIntervalId);
harness._rejectOnStop = null;
}
GDJS/tests/tests/gameplaytestharness.js
+51 -2
View File
@@ -138,6 +138,7 @@ describe('gdjs.gameplayTests', () => {
expect(result.status).to.be('passed');
expect(result.timeoutMs).to.be(5000);
expect(typeof result.loadingMs).to.be('number');
expect(result.framesExecuted).to.be(6); // 1 (goToScene) + 5.
expect(result.assertions.length).to.be(1);
expect(result.assertions[0].passed).to.be(true);
@@ -421,10 +422,15 @@ describe('gdjs.gameplayTests', () => {
harness.getSceneName() === 'Scene 2',
'The first scene of the game is running'
);
`
`,
// A budget smaller than the startup delay: the wait for the game to
// finish starting is loading, excluded from the timeout budget.
{ timeoutMs: 50 }
);
expect(result.status).to.be('passed');
// The startup wait is measured and reported as loading time.
expect(result.loadingMs >= 90).to.be(true);
});
it('fails with a clear error when a started game never finishes starting', async () => {
@@ -433,13 +439,56 @@ describe('gdjs.gameplayTests', () => {
const result = await runTestScript(
runtimeGame,
'await harness.stepFrames(1);',
{ timeoutMs: 300 }
// The bound on this wait is the LOADING timeout, not the test budget.
{ timeoutMs: 5000, loadingTimeoutMs: 300 }
);
expect(result.status).to.be('error');
expect(result.errors[0]).to.contain('did not finish starting');
}).timeout(10000);
it('excludes slow scene-asset loading from the timeout budget', async () => {
const runtimeGame = makeRuntimeGame();
// Simulate scene assets that take longer to load than the whole test
// budget (like the first run of a web preview downloading resources).
const anyRuntimeGame = /** @type {any} */ (runtimeGame);
let slowLoadDone = false;
anyRuntimeGame.areSceneAssetsReady = () => slowLoadDone;
anyRuntimeGame.loadSceneAssets = async () => {
await new Promise((resolve) => setTimeout(resolve, 300));
slowLoadDone = true;
};
const result = await runTestScript(
runtimeGame,
`
await harness.goToScene('Scene 1');
await harness.stepFrames(2);
harness.assert(harness.getSceneName() === 'Scene 1', 'Scene is running');
`,
{ timeoutMs: 200 }
);
expect(result.status).to.be('passed');
expect(result.loadingMs >= 280).to.be(true);
// The wall-clock duration includes the loading time.
expect(result.durationMs >= result.loadingMs).to.be(true);
}).timeout(10000);
it('fails with a clear error when scene assets never finish loading', async () => {
const runtimeGame = makeRuntimeGame();
const anyRuntimeGame = /** @type {any} */ (runtimeGame);
anyRuntimeGame.areSceneAssetsReady = () => false;
anyRuntimeGame.loadSceneAssets = () => new Promise(() => {});
const result = await runTestScript(
runtimeGame,
`await harness.goToScene('Scene 1');`,
{ timeoutMs: 5000, loadingTimeoutMs: 200 }
);
expect(result.status).to.be('error');
expect(result.errors[0]).to.contain('did not finish loading');
}).timeout(10000);
it('gives the camera state and camera/heading-relative positions', async () => {
const runtimeGame = makeRuntimeGame();
const result = await runTestScript(
newIDE/app/src/GameplayTests/GameplayTestRunner.js
+30 -13
View File
@@ -40,8 +40,12 @@ export type GameplayTestResult = {
status: 'passed' | 'failed' | 'error' | 'stopped' | 'timeout',
framesExecuted: number,
durationMs: number,
// The wall-clock budget the run had (a duration close to it means the
// test is at risk of timing out on a slower machine).
// Time spent waiting for the game to boot and for scene assets to load,
// excluded from the `timeoutMs` budget (`durationMs` includes it).
loadingMs: number,
// The wall-clock budget the run had, loading excluded
// (`durationMs - loadingMs` close to it means the test is at risk of
// timing out on a slower machine).
timeoutMs: number,
gameTimeMs: number,
assertions: Array<GameplayTestAssertion>,
@@ -154,6 +158,7 @@ const makeResultWithoutRun = (
status,
framesExecuted: 0,
durationMs: 0,
loadingMs: 0,
timeoutMs: 0,
gameTimeMs: 0,
assertions: [],
@@ -182,6 +187,7 @@ export const makeGameplayTestResultReadableOutput = (
testName: result.testName,
framesExecuted: result.framesExecuted,
durationMs: result.durationMs,
loadingMs: result.loadingMs,
timeoutMs: result.timeoutMs,
gameTimeMs: result.gameTimeMs,
assertions: result.assertions,
@@ -345,6 +351,10 @@ const runSingleTest = async ({
if (parsedMessage.messageId !== messageId) return;
if (parsedMessage.command === 'gameplayTest.progress') {
// The game is alive (stepping frames, or heartbeating while it
// loads assets - loading is not counted against the test
// timeout): give it a full budget again.
armWatchdog();
if (onProgress && parsedMessage.payload) {
onProgress(test, parsedMessage.payload.frame || 0);
}
@@ -365,17 +375,24 @@ const runSingleTest = async ({
resolve(result);
};
// An editor-side watchdog, in case the game dies without sending
// its result.
watchdogTimeoutId = setTimeout(() => {
finish(
makeErrorResult(
test.testName,
`No result received from the game after ${timeoutMs +
RESULT_EXTRA_TIMEOUT_MS}ms - the game may have crashed or been closed.`
)
);
}, timeoutMs + RESULT_EXTRA_TIMEOUT_MS);
// An editor-side watchdog, in case the game dies without sending its
// result. Re-armed by every progress message: a game legitimately
// spends long over its own timeout while loading assets (loading is
// excluded from the test budget), but it heartbeats while doing so - a
// full silence is what means it crashed.
const armWatchdog = () => {
if (watchdogTimeoutId !== null) clearTimeout(watchdogTimeoutId);
watchdogTimeoutId = setTimeout(() => {
finish(
makeErrorResult(
test.testName,
`No result nor progress received from the game after ${timeoutMs +
RESULT_EXTRA_TIMEOUT_MS}ms - the game may have crashed or been closed.`
)
);
}, timeoutMs + RESULT_EXTRA_TIMEOUT_MS);
};
armWatchdog();
const payload: Object = {
testName: test.testName,
newIDE/app/src/MainFrame/LocalCliCommandRunner.js
+11 -8
View File
@@ -239,9 +239,16 @@ const runners: { [commandName: string]: CliCommandRunner } = {
for (const result of results) {
const passed = result.status === 'passed';
if (!passed) failedCount++;
// Loading (game boot, scene assets) is excluded from the timeout
// budget: only the running time counts against it.
const loadingMs = result.loadingMs || 0;
const runningMs = Math.max(0, result.durationMs - loadingMs);
const loadingText = loadingMs
? ` + ${(loadingMs / 1000).toFixed(1)}s loading`
: '';
const budgetText = result.timeoutMs
? `, ${(result.durationMs / 1000).toFixed(1)}s / ${result.timeoutMs /
1000}s budget`
? `, ${(runningMs / 1000).toFixed(1)}s / ${result.timeoutMs /
1000}s budget${loadingText}`
: '';
console.info(
`[CLI] ${passed ? 'PASSED' : 'FAILED'} (${result.status}): ${
@@ -250,14 +257,10 @@ const runners: { [commandName: string]: CliCommandRunner } = {
result.errors.length ? ' - ' + result.errors.join(' | ') : ''
}`
);
if (
passed &&
result.timeoutMs &&
result.durationMs >= 0.8 * result.timeoutMs
) {
if (passed && result.timeoutMs && runningMs >= 0.8 * result.timeoutMs) {
console.warn(
`[CLI] WARNING: "${result.testName}" used ${Math.round(
(100 * result.durationMs) / result.timeoutMs
(100 * runningMs) / result.timeoutMs
)}% of its wall-clock budget - it is at risk of timing out on a slower machine. Shorten it or raise its timeout.`
);
}
newIDE/app/src/stories/componentStories/GameplayTests/GameplayTestProperties.stories.js
+1
View File
@@ -73,6 +73,7 @@ const makeResult = (
status: 'passed',
framesExecuted: 0,
durationMs: 0,
loadingMs: 0,
timeoutMs: 0,
gameTimeMs: 0,
assertions: [],