fix(metrics): report counters Python can actually observe
get_metrics() returned 0 for draw_calls, ui_elements, visible_elements and every grid counter. Two distinct defects behind one symptom. Ordering. draw_calls/ui_elements/visible_elements WERE incremented, in PyScene::render() -- but render runs at step 6 of the frame, after every Python callback, while the counters were zeroed at step 1. A script calling get_metrics() from a timer or scene update was structurally incapable of ever observing a nonzero value. Dead code. grid_cells_rendered, entities_rendered, total_entities, grid_render_time and entity_render_time were never incremented ANYWHERE in src/ -- the increments were lost in the GridView/chunk refactor and only fovOverlayTime survived. They are re-instrumented in UIGridView::render(). Fix both by splitting the metrics along the seam that actually exists: rendering is orthogonal to simulation and costs zero clock time (a screenshot draws arbitrary state without advancing time). So render counters are cleared and published by the render pass (beginRender/endRender, in both doFrame and the on-demand renderScene), and simulation timings by the sim pass (beginSimFrame/endSimFrame). get_metrics() reads the published values, so a step()-only run cannot wipe the counters from the last render, and a render cannot disturb the clock. Riders found while in here: - ScopedTimer ASSIGNS, so with two grid views on screen the second view's time silently replaced the first's. Added ScopedAccumTimer for per-frame totals accumulated across objects; fovOverlayTime had this bug already. - fps was inflated for the first 60 frames: frameTimeHistory is zero-filled but the mean always divided by the full 60. Now divides by frames actually seen. - frame_time is milliseconds; the docstring said seconds. Fixed the docstring, not the value -- the Gauntlet already reads it as ms. closes #341
This commit is contained in:
parent
464af6a549
commit
c72ab22999
7 changed files with 332 additions and 34 deletions
File diff suppressed because one or more lines are too long
|
|
@ -394,8 +394,9 @@ void GameEngine::run()
|
|||
|
||||
void GameEngine::doFrame()
|
||||
{
|
||||
// Reset per-frame metrics
|
||||
metrics.resetPerFrame();
|
||||
// #341: simulation metrics belong to this frame's sim pass; render counters are
|
||||
// cleared/published around the render pass below.
|
||||
metrics.beginSimFrame();
|
||||
|
||||
currentScene()->update();
|
||||
testTimers();
|
||||
|
|
@ -426,6 +427,8 @@ void GameEngine::doFrame()
|
|||
{
|
||||
}
|
||||
|
||||
metrics.beginRender(); // #341
|
||||
|
||||
// Handle scene transitions
|
||||
if (transition.type != TransitionType::None)
|
||||
{
|
||||
|
|
@ -453,6 +456,8 @@ void GameEngine::doFrame()
|
|||
currentScene()->render();
|
||||
}
|
||||
|
||||
metrics.endRender(); // #341: publish this frame's counters for get_metrics()
|
||||
|
||||
// Update and render profiler overlay (if enabled)
|
||||
if (profilerOverlay && !headless) {
|
||||
profilerOverlay->update(metrics);
|
||||
|
|
@ -923,12 +928,20 @@ float GameEngine::step(float dt) {
|
|||
simulation_time += static_cast<int>(dt * 1000.0f); // Convert seconds to ms
|
||||
}
|
||||
|
||||
// Update animations with the dt in seconds
|
||||
if (actual_dt > 0.0f && actual_dt < 10.0f) { // Sanity check
|
||||
AnimationManager::getInstance().update(actual_dt);
|
||||
}
|
||||
// #350: step() is a full SIMULATION frame -- everything doFrame() does except
|
||||
// render and input, which are deliberately not on the clock (render costs zero
|
||||
// simulation time; see renderScene()). Previously step() advanced only animations
|
||||
// and timers, so under step() a Scene.update() override never fired, scene
|
||||
// transitions never progressed or completed, and current_frame never advanced --
|
||||
// headless behaved measurably differently from a real frame.
|
||||
metrics.beginSimFrame();
|
||||
|
||||
// Test timers with the new simulation time
|
||||
// C++ scene update
|
||||
currentScene()->update();
|
||||
|
||||
// Test timers with the new simulation time.
|
||||
// Kept on simulation_time (not runtime): step() is the deterministic headless
|
||||
// clock, which is the whole point of driving time explicitly from a test.
|
||||
auto it = timers.begin();
|
||||
while (it != timers.end()) {
|
||||
auto timer = it->second;
|
||||
|
|
@ -946,13 +959,46 @@ float GameEngine::step(float dt) {
|
|||
}
|
||||
}
|
||||
|
||||
// Python Scene.update(dt) hook -- the originally-filed omission
|
||||
{
|
||||
ScopedTimer pyTimer(metrics.pythonScriptTime);
|
||||
McRFPy_API::updatePythonScenes(actual_dt);
|
||||
}
|
||||
|
||||
// Update animations with the dt in seconds
|
||||
if (actual_dt > 0.0f && actual_dt < 10.0f) { // Sanity check
|
||||
ScopedTimer animTimer(metrics.animationTime);
|
||||
AnimationManager::getInstance().update(actual_dt);
|
||||
}
|
||||
|
||||
// Advance scene transitions, and finalize them when complete. Without this a
|
||||
// transition started headlessly would never end, and the scene never changed.
|
||||
if (transition.type != TransitionType::None) {
|
||||
transition.update(actual_dt);
|
||||
if (transition.isComplete()) {
|
||||
scene = transition.toScene;
|
||||
transition.type = TransitionType::None;
|
||||
McRFPy_API::triggerSceneChange(transition.fromScene, transition.toScene);
|
||||
}
|
||||
}
|
||||
|
||||
metrics.endSimFrame();
|
||||
metrics.updateFrameTime(actual_dt * 1000.0f); // ms
|
||||
currentFrame++;
|
||||
|
||||
return actual_dt;
|
||||
}
|
||||
|
||||
// #153 - Force render the current scene (for synchronous screenshots)
|
||||
// Render the current state on demand, advancing NO simulation time (#341/#350).
|
||||
// Rendering is orthogonal to the clock: any state can be drawn at any moment. This is
|
||||
// the path a screenshot takes, and -- since step() deliberately never renders -- it is
|
||||
// how a headless script gets real render metrics without the clock moving.
|
||||
void GameEngine::renderScene() {
|
||||
if (!render_target) return;
|
||||
|
||||
metrics.beginRender();
|
||||
|
||||
// Handle scene transitions
|
||||
if (transition.type != TransitionType::None) {
|
||||
transition.update(0); // Don't advance transition time, just render current state
|
||||
|
|
@ -963,6 +1009,8 @@ void GameEngine::renderScene() {
|
|||
currentScene()->render();
|
||||
}
|
||||
|
||||
metrics.endRender();
|
||||
|
||||
// For RenderTexture (headless), we need to call display()
|
||||
if (headless && headless_renderer) {
|
||||
headless_renderer->display();
|
||||
|
|
|
|||
|
|
@ -53,37 +53,90 @@ struct ProfilingMetrics {
|
|||
static constexpr int HISTORY_SIZE = 60;
|
||||
float frameTimeHistory[HISTORY_SIZE] = {0};
|
||||
int historyIndex = 0;
|
||||
int historyCount = 0; // #341: frames recorded so far, capped at HISTORY_SIZE
|
||||
|
||||
/**
|
||||
* @brief Per-frame values from the last COMPLETED frame (#341).
|
||||
*
|
||||
* The counters above are live accumulators: they are zeroed at the top of the
|
||||
* frame and filled during render(), which runs AFTER every Python callback.
|
||||
* A script calling get_metrics() therefore always read zeros. These published
|
||||
* copies hold the previous frame's totals, which is what Python should see.
|
||||
*
|
||||
* In-engine consumers that run after render() (ProfilerOverlay, BenchmarkLogger)
|
||||
* keep reading the live values -- they are fresher and already correct there.
|
||||
*/
|
||||
struct PublishedFrame {
|
||||
int drawCalls = 0;
|
||||
int uiElements = 0;
|
||||
int visibleElements = 0;
|
||||
int gridCellsRendered = 0;
|
||||
int entitiesRendered = 0;
|
||||
int totalEntities = 0;
|
||||
float gridRenderTime = 0.0f;
|
||||
float entityRenderTime = 0.0f;
|
||||
float fovOverlayTime = 0.0f;
|
||||
float pythonScriptTime = 0.0f;
|
||||
float animationTime = 0.0f;
|
||||
} published;
|
||||
|
||||
void updateFrameTime(float deltaMs) {
|
||||
frameTime = deltaMs;
|
||||
frameTimeHistory[historyIndex] = deltaMs;
|
||||
historyIndex = (historyIndex + 1) % HISTORY_SIZE;
|
||||
if (historyCount < HISTORY_SIZE) ++historyCount;
|
||||
|
||||
// Calculate average
|
||||
// Average over frames actually recorded. Dividing by the full HISTORY_SIZE
|
||||
// while the zero-initialized buffer is still filling diluted the average and
|
||||
// reported a wildly inflated FPS for the first 60 frames (#341).
|
||||
float sum = 0.0f;
|
||||
for (int i = 0; i < HISTORY_SIZE; ++i) {
|
||||
for (int i = 0; i < historyCount; ++i) {
|
||||
sum += frameTimeHistory[i];
|
||||
}
|
||||
avgFrameTime = sum / HISTORY_SIZE;
|
||||
avgFrameTime = historyCount > 0 ? sum / historyCount : 0.0f;
|
||||
fps = avgFrameTime > 0 ? static_cast<int>(1000.0f / avgFrameTime) : 0;
|
||||
}
|
||||
|
||||
void resetPerFrame() {
|
||||
// #341/#350: simulation and rendering are separate passes with separate metrics.
|
||||
//
|
||||
// Rendering costs zero simulation time and can happen at any moment (a screenshot
|
||||
// renders arbitrary state without advancing the clock), so the render counters are
|
||||
// owned by the render pass and the simulation timings by the step/frame pass.
|
||||
// Keeping them separate means a step() cannot wipe the counters from the last
|
||||
// render, and a render cannot disturb the simulation clock.
|
||||
|
||||
void beginRender() {
|
||||
drawCalls = 0;
|
||||
uiElements = 0;
|
||||
visibleElements = 0;
|
||||
|
||||
// Reset per-frame timing metrics
|
||||
gridRenderTime = 0.0f;
|
||||
entityRenderTime = 0.0f;
|
||||
fovOverlayTime = 0.0f;
|
||||
pythonScriptTime = 0.0f;
|
||||
animationTime = 0.0f;
|
||||
|
||||
// Reset per-frame counters
|
||||
gridCellsRendered = 0;
|
||||
entitiesRendered = 0;
|
||||
totalEntities = 0;
|
||||
gridRenderTime = 0.0f;
|
||||
entityRenderTime = 0.0f;
|
||||
fovOverlayTime = 0.0f;
|
||||
}
|
||||
|
||||
void endRender() {
|
||||
published.drawCalls = drawCalls;
|
||||
published.uiElements = uiElements;
|
||||
published.visibleElements = visibleElements;
|
||||
published.gridCellsRendered = gridCellsRendered;
|
||||
published.entitiesRendered = entitiesRendered;
|
||||
published.totalEntities = totalEntities;
|
||||
published.gridRenderTime = gridRenderTime;
|
||||
published.entityRenderTime = entityRenderTime;
|
||||
published.fovOverlayTime = fovOverlayTime;
|
||||
}
|
||||
|
||||
void beginSimFrame() {
|
||||
pythonScriptTime = 0.0f;
|
||||
animationTime = 0.0f;
|
||||
}
|
||||
|
||||
void endSimFrame() {
|
||||
published.pythonScriptTime = pythonScriptTime;
|
||||
published.animationTime = animationTime;
|
||||
}
|
||||
};
|
||||
|
||||
|
|
|
|||
|
|
@ -378,7 +378,10 @@ static PyMethodDef mcrfpyMethods[] = {
|
|||
MCRF_METHOD(mcrfpy, get_metrics,
|
||||
MCRF_SIG("()", "dict"),
|
||||
MCRF_DESC("Get current performance metrics."),
|
||||
MCRF_RETURNS("dict: Performance data with keys: frame_time (last frame duration in seconds), avg_frame_time (average frame time), fps (frames per second), draw_calls (number of draw calls), ui_elements (total UI element count), visible_elements (visible element count), current_frame (frame counter), runtime (total runtime in seconds), grid_render_time (grid rendering time in ms), entity_render_time (entity rendering time in ms), fov_overlay_time (FOV overlay rendering time in ms), python_time (Python script execution time in ms), animation_time (animation processing time in ms), grid_cells_rendered (number of grid cells rendered this frame), entities_rendered (number of entities rendered this frame), total_entities (total entity count across all grids)")
|
||||
MCRF_RETURNS("dict: Performance data with keys: frame_time (last frame duration in MILLISECONDS), avg_frame_time (rolling mean frame time over the last 60 frames, in milliseconds), fps (frames per second, derived from avg_frame_time -- a rolling average, not an instantaneous rate), draw_calls (number of draw calls), ui_elements (total UI element count), visible_elements (visible element count), current_frame (frame counter), runtime (total runtime in seconds), grid_render_time (grid rendering time in ms), entity_render_time (entity rendering time in ms), fov_overlay_time (FOV overlay rendering time in ms), python_time (Python script execution time in ms), animation_time (animation processing time in ms), grid_cells_rendered (grid cell draws this frame, counted per layer), entities_rendered (number of entities drawn this frame), total_entities (total entity count across all rendered grids)")
|
||||
MCRF_NOTE("All per-frame counters and timing breakdowns describe the last COMPLETED frame. "
|
||||
"Python callbacks run before the frame is rendered, so the in-progress frame's "
|
||||
"values are not available yet; frame_time, fps, runtime and current_frame are live.")
|
||||
)},
|
||||
|
||||
{"set_dev_console", McRFPy_API::_setDevConsole, METH_VARARGS,
|
||||
|
|
@ -1871,22 +1874,27 @@ PyObject* McRFPy_API::_getMetrics(PyObject* self, PyObject* args) {
|
|||
PyDict_SetItemString(dict, "avg_frame_time", PyFloat_FromDouble(game->metrics.avgFrameTime));
|
||||
PyDict_SetItemString(dict, "fps", PyLong_FromLong(game->metrics.fps));
|
||||
|
||||
// #341: report the last COMPLETED frame's per-frame values, not the live
|
||||
// accumulators. Python callbacks run before render(), and the accumulators are
|
||||
// zeroed at the top of the frame -- so reading them live always returned 0.
|
||||
const auto& pub = game->metrics.published;
|
||||
|
||||
// Add draw call metrics
|
||||
PyDict_SetItemString(dict, "draw_calls", PyLong_FromLong(game->metrics.drawCalls));
|
||||
PyDict_SetItemString(dict, "ui_elements", PyLong_FromLong(game->metrics.uiElements));
|
||||
PyDict_SetItemString(dict, "visible_elements", PyLong_FromLong(game->metrics.visibleElements));
|
||||
PyDict_SetItemString(dict, "draw_calls", PyLong_FromLong(pub.drawCalls));
|
||||
PyDict_SetItemString(dict, "ui_elements", PyLong_FromLong(pub.uiElements));
|
||||
PyDict_SetItemString(dict, "visible_elements", PyLong_FromLong(pub.visibleElements));
|
||||
|
||||
// #144 - Add detailed timing breakdown (in milliseconds)
|
||||
PyDict_SetItemString(dict, "grid_render_time", PyFloat_FromDouble(game->metrics.gridRenderTime));
|
||||
PyDict_SetItemString(dict, "entity_render_time", PyFloat_FromDouble(game->metrics.entityRenderTime));
|
||||
PyDict_SetItemString(dict, "fov_overlay_time", PyFloat_FromDouble(game->metrics.fovOverlayTime));
|
||||
PyDict_SetItemString(dict, "python_time", PyFloat_FromDouble(game->metrics.pythonScriptTime));
|
||||
PyDict_SetItemString(dict, "animation_time", PyFloat_FromDouble(game->metrics.animationTime));
|
||||
PyDict_SetItemString(dict, "grid_render_time", PyFloat_FromDouble(pub.gridRenderTime));
|
||||
PyDict_SetItemString(dict, "entity_render_time", PyFloat_FromDouble(pub.entityRenderTime));
|
||||
PyDict_SetItemString(dict, "fov_overlay_time", PyFloat_FromDouble(pub.fovOverlayTime));
|
||||
PyDict_SetItemString(dict, "python_time", PyFloat_FromDouble(pub.pythonScriptTime));
|
||||
PyDict_SetItemString(dict, "animation_time", PyFloat_FromDouble(pub.animationTime));
|
||||
|
||||
// #144 - Add grid-specific metrics
|
||||
PyDict_SetItemString(dict, "grid_cells_rendered", PyLong_FromLong(game->metrics.gridCellsRendered));
|
||||
PyDict_SetItemString(dict, "entities_rendered", PyLong_FromLong(game->metrics.entitiesRendered));
|
||||
PyDict_SetItemString(dict, "total_entities", PyLong_FromLong(game->metrics.totalEntities));
|
||||
PyDict_SetItemString(dict, "grid_cells_rendered", PyLong_FromLong(pub.gridCellsRendered));
|
||||
PyDict_SetItemString(dict, "entities_rendered", PyLong_FromLong(pub.entitiesRendered));
|
||||
PyDict_SetItemString(dict, "total_entities", PyLong_FromLong(pub.totalEntities));
|
||||
|
||||
// Add general metrics
|
||||
PyDict_SetItemString(dict, "current_frame", PyLong_FromLong(game->getFrame()));
|
||||
|
|
|
|||
|
|
@ -44,6 +44,38 @@ public:
|
|||
ScopedTimer& operator=(const ScopedTimer&) = delete;
|
||||
};
|
||||
|
||||
/**
|
||||
* @brief Like ScopedTimer, but ADDS its elapsed time to the target (#341).
|
||||
*
|
||||
* ScopedTimer assigns, which is correct for a metric measured once per frame
|
||||
* (workTime, pythonScriptTime). It is wrong for anything measured once per
|
||||
* *object* per frame -- with two grid views on screen, assignment means the
|
||||
* second view's time overwrites the first's rather than summing. Use this for
|
||||
* any per-frame total accumulated across multiple call sites.
|
||||
*
|
||||
* The target must be zeroed once per frame (ProfilingMetrics::resetPerFrame).
|
||||
*/
|
||||
class ScopedAccumTimer {
|
||||
private:
|
||||
std::chrono::high_resolution_clock::time_point start;
|
||||
float& target_ms;
|
||||
|
||||
public:
|
||||
explicit ScopedAccumTimer(float& target)
|
||||
: target_ms(target)
|
||||
{
|
||||
start = std::chrono::high_resolution_clock::now();
|
||||
}
|
||||
|
||||
~ScopedAccumTimer() {
|
||||
auto end = std::chrono::high_resolution_clock::now();
|
||||
target_ms += std::chrono::duration<float, std::milli>(end - start).count();
|
||||
}
|
||||
|
||||
ScopedAccumTimer(const ScopedAccumTimer&) = delete;
|
||||
ScopedAccumTimer& operator=(const ScopedAccumTimer&) = delete;
|
||||
};
|
||||
|
||||
/**
|
||||
* @brief Accumulating timer that adds elapsed time to existing value
|
||||
*
|
||||
|
|
|
|||
|
|
@ -289,16 +289,33 @@ void UIGridView::render(sf::Vector2f offset, sf::RenderTarget& target)
|
|||
int y_limit = top_edge + height_sq + 2;
|
||||
if (y_limit > grid_data->grid_h) y_limit = grid_data->grid_h;
|
||||
|
||||
// #341: re-instrument the grid render counters. These were declared and reset
|
||||
// every frame but never incremented anywhere -- the increments were lost in the
|
||||
// GridView/chunk refactor, so grid_cells_rendered/entities_rendered/
|
||||
// grid_render_time have read 0 ever since. Accumulating (not assigning) so that
|
||||
// two views over one map sum rather than clobber each other.
|
||||
auto& metrics = Resources::game->metrics;
|
||||
ScopedAccumTimer gridTimer(metrics.gridRenderTime);
|
||||
|
||||
// Cells actually inside the viewport window, per layer drawn.
|
||||
const int x_start = std::max(0, static_cast<int>(left_edge));
|
||||
const int y_start = std::max(0, static_cast<int>(top_edge));
|
||||
const int visible_cells = std::max(0, x_limit - x_start) * std::max(0, y_limit - y_start);
|
||||
|
||||
// Render layers below entities (z_index <= 0)
|
||||
grid_data->sortLayers();
|
||||
int layers_drawn = 0;
|
||||
for (auto& layer : grid_data->layers) {
|
||||
if (layer->z_index > 0) break; // #257: z_index=0 is ground level (below entities)
|
||||
layer->render(*activeTexture, left_spritepixels, top_spritepixels,
|
||||
left_edge, top_edge, x_limit, y_limit, zoom, cell_width, cell_height);
|
||||
++layers_drawn;
|
||||
}
|
||||
|
||||
// Render entities
|
||||
if (grid_data->entities) {
|
||||
ScopedAccumTimer entityTimer(metrics.entityRenderTime);
|
||||
metrics.totalEntities += static_cast<int>(grid_data->entities->size());
|
||||
for (auto& e : *grid_data->entities) {
|
||||
if (e->position.x < left_edge - 2 || e->position.x >= left_edge + width_sq + 2 ||
|
||||
e->position.y < top_edge - 2 || e->position.y >= top_edge + height_sq + 2) {
|
||||
|
|
@ -310,6 +327,7 @@ void UIGridView::render(sf::Vector2f offset, sf::RenderTarget& target)
|
|||
(e->position.x*cell_width - left_spritepixels + e->sprite_offset.x) * zoom,
|
||||
(e->position.y*cell_height - top_spritepixels + e->sprite_offset.y) * zoom);
|
||||
drawent.render(pixel_pos, *activeTexture);
|
||||
++metrics.entitiesRendered;
|
||||
}
|
||||
}
|
||||
|
||||
|
|
@ -318,8 +336,12 @@ void UIGridView::render(sf::Vector2f offset, sf::RenderTarget& target)
|
|||
if (layer->z_index <= 0) continue; // #257: skip ground-level and below
|
||||
layer->render(*activeTexture, left_spritepixels, top_spritepixels,
|
||||
left_edge, top_edge, x_limit, y_limit, zoom, cell_width, cell_height);
|
||||
++layers_drawn;
|
||||
}
|
||||
|
||||
// One "cell rendered" per cell per layer drawn -- i.e. cell draw operations.
|
||||
metrics.gridCellsRendered += visible_cells * layers_drawn;
|
||||
|
||||
// Children (grid-world pixel coordinates; owned by this view -- #364)
|
||||
if (children && !children->empty()) {
|
||||
if (children_need_sort) {
|
||||
|
|
@ -343,7 +365,9 @@ void UIGridView::render(sf::Vector2f offset, sf::RenderTarget& target)
|
|||
|
||||
// Perspective overlay (#355: state owned by the view -- see get/set_perspective)
|
||||
if (perspective_enabled) {
|
||||
ScopedTimer fovTimer(Resources::game->metrics.fovOverlayTime);
|
||||
// #341: accumulate -- with two perspective views on screen, assignment made
|
||||
// the second view's time silently replace the first's.
|
||||
ScopedAccumTimer fovTimer(Resources::game->metrics.fovOverlayTime);
|
||||
auto entity = perspective_entity.lock();
|
||||
sf::RectangleShape overlay;
|
||||
overlay.setSize(sf::Vector2f(cell_width * zoom, cell_height * zoom));
|
||||
|
|
|
|||
133
tests/regression/issue_341_metrics_counters_test.py
Normal file
133
tests/regression/issue_341_metrics_counters_test.py
Normal file
|
|
@ -0,0 +1,133 @@
|
|||
"""
|
||||
Regression test for issue #341.
|
||||
|
||||
get_metrics() reported 0 for every render counter:
|
||||
|
||||
* draw_calls / ui_elements / visible_elements WERE incremented -- but only inside
|
||||
render(), which runs after every Python callback, while the counters were zeroed
|
||||
at the top of the frame. Python was structurally unable to observe a nonzero
|
||||
value. Render counters are now published at the end of the render pass.
|
||||
|
||||
* grid_cells_rendered / entities_rendered / total_entities / grid_render_time /
|
||||
entity_render_time were never incremented ANYWHERE -- dead code since the
|
||||
GridView refactor. Re-instrumented in UIGridView::render().
|
||||
|
||||
Also locks two riders: frame_time is milliseconds (the docstring claimed seconds),
|
||||
and fps is no longer inflated by the zero-filled history buffer on early frames.
|
||||
|
||||
Model under test (#350): step() is the clock and never renders; rendering is
|
||||
orthogonal and costs zero simulation time. So we drive time with step() and force a
|
||||
render with a screenshot, then read the metrics that render published.
|
||||
"""
|
||||
import mcrfpy
|
||||
from mcrfpy import automation
|
||||
import sys
|
||||
import os
|
||||
import tempfile
|
||||
|
||||
failures = []
|
||||
|
||||
|
||||
def check(label, condition, detail=""):
|
||||
if condition:
|
||||
print(f" PASS: {label}")
|
||||
else:
|
||||
print(f" FAIL: {label} {detail}")
|
||||
failures.append(label)
|
||||
|
||||
|
||||
scene = mcrfpy.Scene("issue341")
|
||||
ui = scene.children
|
||||
|
||||
# A grid with a layer + entities, so the grid counters have something to count.
|
||||
grid = mcrfpy.Grid(grid_size=(20, 20), pos=(0, 0), size=(320, 320))
|
||||
layer = mcrfpy.TileLayer("ground", 0)
|
||||
grid.add_layer(layer)
|
||||
for x in range(20):
|
||||
for y in range(20):
|
||||
layer.set((x, y), 0)
|
||||
|
||||
for i in range(6):
|
||||
grid.entities.append(mcrfpy.Entity(grid_pos=(i, i)))
|
||||
|
||||
ui.append(grid)
|
||||
|
||||
# Plain UI elements, so ui_elements / draw_calls have something to count.
|
||||
for i in range(4):
|
||||
ui.append(mcrfpy.Frame(pos=(400 + i * 20, 10), size=(15, 15)))
|
||||
ui.append(mcrfpy.Caption(pos=(400, 200), text="metrics"))
|
||||
|
||||
mcrfpy.current_scene = scene
|
||||
|
||||
# Advance the clock a few times. step() must NOT render, so this alone must leave
|
||||
# the render counters untouched.
|
||||
for _ in range(5):
|
||||
mcrfpy.step(0.016)
|
||||
|
||||
print("1. step() advances the sim clock but renders nothing")
|
||||
m = mcrfpy.get_metrics()
|
||||
check("current_frame advanced under step()", m["current_frame"] >= 5,
|
||||
f"got {m['current_frame']}")
|
||||
check("frame_time is set by step()", m["frame_time"] > 0, f"got {m['frame_time']}")
|
||||
check("draw_calls still 0 (step does not render)", m["draw_calls"] == 0,
|
||||
f"got {m['draw_calls']}")
|
||||
|
||||
# Force a render. This costs zero simulation time and publishes the render counters.
|
||||
shot = os.path.join(tempfile.gettempdir(), "issue341_metrics.png")
|
||||
frame_before = mcrfpy.get_metrics()["current_frame"]
|
||||
automation.screenshot(shot)
|
||||
m = mcrfpy.get_metrics()
|
||||
|
||||
print("2. Rendering costs zero simulation time")
|
||||
check("current_frame did not advance from rendering",
|
||||
m["current_frame"] == frame_before,
|
||||
f"{frame_before} -> {m['current_frame']}")
|
||||
|
||||
print("3. Render counters are observable from Python (were always 0)")
|
||||
check("draw_calls > 0", m["draw_calls"] > 0, f"got {m['draw_calls']}")
|
||||
check("ui_elements > 0", m["ui_elements"] > 0, f"got {m['ui_elements']}")
|
||||
check("visible_elements > 0", m["visible_elements"] > 0, f"got {m['visible_elements']}")
|
||||
|
||||
print("4. Grid counters are re-instrumented (were dead code)")
|
||||
check("grid_cells_rendered > 0", m["grid_cells_rendered"] > 0,
|
||||
f"got {m['grid_cells_rendered']}")
|
||||
check("entities_rendered > 0", m["entities_rendered"] > 0,
|
||||
f"got {m['entities_rendered']}")
|
||||
check("total_entities == 6", m["total_entities"] == 6, f"got {m['total_entities']}")
|
||||
check("entities_rendered <= total_entities",
|
||||
m["entities_rendered"] <= m["total_entities"])
|
||||
# A cell "render" is counted per cell per layer drawn: the 20x20 grid is fully on
|
||||
# screen, so it is exactly 400 * (number of layers).
|
||||
expected_cells = 400 * len(grid.layers)
|
||||
check(f"grid_cells_rendered == 400 * {len(grid.layers)} layers",
|
||||
m["grid_cells_rendered"] == expected_cells,
|
||||
f"got {m['grid_cells_rendered']}, expected {expected_cells}")
|
||||
|
||||
print("5. frame_time is in milliseconds, not seconds")
|
||||
ft = m["frame_time"]
|
||||
# step(0.016) -> 16ms. In seconds this would read 0.016 and fail the lower bound.
|
||||
check("frame_time ~= 16ms for step(0.016)", 10.0 <= ft <= 25.0, f"got {ft}")
|
||||
|
||||
print("6. fps is sane on early frames (was inflated by the zero-filled history)")
|
||||
fps = m["fps"]
|
||||
check("fps > 0", fps > 0, f"got {fps}")
|
||||
# Pre-fix, dividing by a mostly-zero 60-slot buffer inflated this enormously.
|
||||
# step(0.016) is 62.5 fps; allow slack but nothing absurd.
|
||||
check("fps is not absurdly inflated", fps < 1000, f"got {fps}")
|
||||
|
||||
print("7. Timing breakdowns are present")
|
||||
check("grid_render_time >= 0", m["grid_render_time"] >= 0.0)
|
||||
check("entity_render_time >= 0", m["entity_render_time"] >= 0.0)
|
||||
|
||||
if os.path.exists(shot):
|
||||
os.remove(shot)
|
||||
|
||||
print()
|
||||
if failures:
|
||||
print(f"FAIL - {len(failures)} check(s) failed:")
|
||||
for f in failures:
|
||||
print(f" - {f}")
|
||||
sys.exit(1)
|
||||
|
||||
print("PASS")
|
||||
sys.exit(0)
|
||||
Loading…
Add table
Add a link
Reference in a new issue