Ecru GamesDevlog › When the profiler lies

When the profiler lies

Cotton Tycoon is a browser tycoon game that grew far past the size I designed it for. Real saves now hold thousands of fields and hundreds of vehicles. Every performance fix in the last month started with a measurement, and roughly half of those measurements were wrong in a way that pointed me at the wrong file.

Ecru Games developer

There is a failure mode I did not have a name for until it had cost me several nights: the diagnostic tool runs, returns a number, and the number is real. It is just the answer to a different question than the one I asked. A crash is honest. A tool that reports fps: 0 when the connection dropped, or console clean when the game is dead, sends you somewhere else entirely and lets you spend an evening there.

All five cases below are from the same game and the same six weeks. I am writing them down because the shape repeats, and because the fix in each case is cheap once you know it exists.

1. An empty reading is not a zero

The frame-rate probe drove a headless browser over the debugging protocol, evaluated an expression in the page and wrote the result into a table. When a call did not come back in time, the evaluation returned undefined, and the table printed a clean, confident 0.

So the table said the game was rendering zero frames per second in a configuration where it was, in fact, rendering fine. I went looking for a rendering stall that did not exist.

An absent reading means no answer. It does not mean zero. The probe now retries, and a reading that never arrives is printed as a dash rather than a digit. The same rule shows up in the game's own admin panel, where a metric a game does not report has to render as an em space and not a zero, because a wrong number is worse than a blank cell: you look at it and make a decision.

2. The game quietly undid my experiment

To find out how much the crop rendering cost, I set every field's visibility to false and measured again. The result came back identical, so I crossed fields off the suspect list.

Fields were not innocent. The game runs a culling pass roughly ten times a second that rewrites the visibility flag on every field from scratch. My experiment survived for about a tenth of a second, then the game put everything back. I was measuring an experiment that had never been applied.

Any single-shot change to state the game rewrites on a timer needs to be re-applied faster than that timer, or held by a flag the loop respects. Before trusting the result, check that the thing you changed is still changed at the moment you read the number.

3. The world moved during the measurement

This is the one that wasted the most time, because the readings looked like noise rather than a bug. Four baseline measurements, same save file, same camera position, taken minutes apart:

RunDraw calls
11,079
21,298
32,434
49,292

A factor of 8.6 between runs that were supposed to be identical. In a preview build the game is genuinely running: crops grow, vehicles drive, the day advances, a scripted camera move may not have finished. Two measurements taken at different moments are two different worlds, and no A/B comparison across them means anything.

The fix was a debug hook that freezes the simulation and locks the camera while the renderer keeps drawing at full cost, plus a world signature the tool reads before and after each run. If the signature changed, the tool rejects its own measurement. Two consecutive runs after that: 9,160 and 9,174, a spread of 0.15%.

Within-run A/B is trustworthy, across-run is not. The same fixture gave baselines of 25 and 37 fps on two different launches, because the crop growth state settles differently while the save loads. Run the experiment and its control in the same session, and print the control's return to baseline. If it does not return, throw the run away.

4. The tool watched the wrong channel

A save-loading regression shipped past a probe whose job was to catch exactly that. The probe listened for console errors, found none and reported a clean console. The game was dead on screen at that moment: the failure line it printed was an info-level log, not an error.

The same probe had a second problem. Large save fixtures settle slowly, because storage buildings arrive as their models finish downloading. Reading too early gave a capacity of 34,100 with 3 silos, where the settled world had 481,293 with 56. In one session that made me diagnose three working buttons as dead.

Console scanning now takes every level. Anything that loads a save waits for a value that is specific to that save, not for a generic sign of life. Waiting for "the game booted" is useless when the boot world also satisfies it.

5. The tool measured its own residue

An automated purchase system was tested with a sequence of scenarios sharing one world. The scenario that asked "does it actually buy anything" ran into 409 million units of cargo left in flight by the previous scenario, so the robot correctly declined to buy more, and the tool reported that as a fault.

A later probe hit the same shape from the other side: it looked for a "last order" field, found one, and treated it as fresh. It was left over from the previous run.

Consecutive scenarios sharing a world have to set up their own preconditions, and any field that persists needs its timestamp checked before it is treated as new.

The check that catches all five

Every one of these was caught by the same thing, and never by reading the tool's source code: run the diagnostic against a known-good state first. If it does not report green on a case you are certain is fine, the tool is the broken component, not the code under test.

That control run costs a minute. In the round where I skipped it, a balance change went out with a transport window that was wrong by a factor of four, and it was not caught by me, by the syntax check or by the save verifier. It was caught by a player, on their screen, the next morning.

The general form is worth stating plainly, because it covers cases I have not hit yet: a tool can answer a question you did not ask, and the answer will look exactly like the answer you wanted. The tools that produced these five numbers were all working correctly. They were measuring an unapplied experiment, a moving world, the wrong log level, a half-loaded save and their own leftovers. Nothing in the output said so.

What it bought

Once the measurements were stable, the fixes came quickly and several were the opposite of what I expected. Shadows and resolution turned out to cost nothing on the frames players complained about. Freezing 26,349 static objects' matrix updates gained exactly zero. Lowering the geometry of a single decorative element gained around a quarter of the frame. None of those conclusions would have survived a measurement that drifted by a factor of eight.

That story is in the next post.

Play Cotton Tycoon