Repository navigation
A model that fails records no time for the phase it failed in #308
Description
A model that fails in a phase records no time for that phase, so the work it did disappears from every report. Only exectime still counts it, and nothing displays exectime per phase.
Three models of BuildingSystems in the last master run:
model total parse fe be sc tpl comp finalphase
BuildingSystems.Buildings.Zones.Examples.SingleZo... 666 3 0 0 0 0 0 0
BuildingSystems.Buildings.Zones.Examples.SingleZo... 666 3 0 0 0 0 0 0
BuildingSystems.Buildings.Zones.Examples.SingleZo... 666 3 0 0 0 0 0 0
Eleven minutes each, reported as zero seconds everywhere. The .err file says what really happened - and it is not an error, it is a timeout:
translateModel(BuildingSystems.Buildings.Zones.Examples.SingleZoneThermal3x3x3, ...) [Timeout 660]
Thread is still alive.
Aborted the command.
[Calling os._exit(0), Time elapsed: 665.8362961709499]
660 seconds is ulimitOmc, the budget for translating a model. They spend all of it, are killed, and are recorded as having spent nothing.
Why
testmodel.py reads the timers after translateModel and only assigns a phase its time when the following timer has a value:
if backend != -1:
execstat["frontend"] = frontend - backend
if templates != -1:
execstat["backend"] = backend - simcode
...
else:
execstat["phase"] = 0
execstat["frontend"] = frontendThe last branch does set frontend, but frontend is timerTock(RT_CLOCK_FRONTEND), which is -1 when the front end never finished - so a model that dies there stores -1 or 0, not the eleven minutes it spent. The same holds one level down for the back end.
How much
Summed over the last master run, 19566 models, 82.5 hours of exectime:
| hours | |
|---|---|
| accounted for by the phase columns | 77.6 |
| attributed to no phase at all | 4.9 |
and by how far the model got:
| finalphase | models | hours | of which unattributed |
|---|---|---|---|
| 7 Verify | 10016 | 34.9 | 2.0 |
| 0 Failed | 881 | 5.0 | 1.5 |
| 6 Simulate | 7605 | 28.4 | 1.3 |
| 1 FrontEnd | 301 | 1.3 | 0.1 |
| 5 Compile | 588 | 12.1 | 0.1 |
So 881 models cost five hours of every run and produce nothing, and a third of that time is not visible in any phase. The rest of the unattributed time is process start-up, loading the result file and so on, spread thinly over the models that succeed.
Those 881 are two different things, and the reports cannot tell them apart either:
| models | hours | |
|---|---|---|
| fail quickly | 878 | 4.5 |
time out in translateModel (>600 s) |
3 | 0.6 |
The 878 average eighteen seconds each, most of which is loading the library before failing - they are cheap individually and add up only because there are so many. The three are BuildingSystems models that consume the full 660 second budget every single run.
What to do
Record what a phase cost even when it fails. The wall clock is available - testmodel.py already measures exectime around the whole run of a model - so a failing phase can be charged with the time between entering it and giving up, rather than with nothing.
The .err file of a failing model already holds the diagnosis, and it is published beside the results, so a report that says "these models fail and cost this much" can link straight to it. Today one has to know the model failed, find its page, and open the file.
Worth deciding as part of it:
- whether a failed phase's time belongs in the same column as a successful one, or in a column of its own. The same column is more useful for "where does the run go"; a separate one keeps "how long does the front end take when it works" clean.
- whether the reports should show it. A row saying 881 models spent 5 hours failing in the front end is worth more than the same 5 hours spread invisibly over
exectime.
Why it matters
It came up while looking at where a master run spends its 82.5 hours, and the answer was distorted by exactly this. Anyone doing that investigation reaches for the phase columns, and they quietly under-report the models that fail - which are the models most likely to be worth looking at.
Generated by Claude Code.
Activity
adrpo commentedon Aug 12, 2026
Correcting this: the diagnosis in the description is wrong. A model that fails in a phase does record that phase's time, in the two cases the issue named. Measured on the
masterrun of 2026-08-12:The
timerTockvalues are elapsed times of clocks that are still running, so a phase that never finished still reports how long it had been going. The code reads them correctly and the earlier reading of it was wrong.The hours in the tables are real, though. Where the time actually goes:
1. Models killed by the watchdog record nothing — 15 models, 1.34 h. They are the 15 of the 867 in the table above with no front end time, and they are what the three
BuildingSystemsmodels in the description really are. The caller does try to account for it:but that handler never runs, because
sendExpressionTimeoutkills the command and callswriteResultAndExititself, from inside, before raising. The process is gone before the caller sees the exception, so the results written are whateverexecstatheld when the command started. Same for the path where omc dies mid-command.2. The remaining ~3.8 h is per-model overhead, spread thin. Starting python and omc, reading the configuration, writing the files, tearing down: about 0.7 s per model over 19650 models. It is 5–6% on a model that succeeds and proportionally much larger on one that fails quickly, which is what made failures look mis-accounted. It belongs to no phase because it genuinely is not one.
So there is one bug here, not the one described, and it is worth fixing because a timed-out model is exactly the kind you want to find: it costs the most and produces nothing.
The open question in the description — whether a failed phase's time belongs in the same column as a successful one — is settled by this: it already goes in the same column, and has done all along.
Generated by Claude Code.
Record what a command killed by the watchdog cost (#310)
adrpo commentedon Aug 12, 2026
Closing this: the one real bug behind it is fixed, and the rest turned out not to be a bug.
The description's diagnosis — that a model failing in a phase records no time for that
phase — is wrong, as corrected above.
timerTockreports the elapsed time of a clock that is still running, so a phase thatnever finished still reports how long it had been going; 851 of 867 front-end failures
and all 301 back-end failures in the
masterrun of 2026-08-12 did record their time.What the three
BuildingSystemsmodels in the description actually were is models killedby the watchdog, and those genuinely recorded nothing:
sendExpressionTimeoutcalledwriteResultAndExitfrom inside the timeout path, so the process was gone before thecaller's
except TimeoutErrorhandler could attribute the elapsed time. 15 models,1.34 hours in that run. Fixed by #310.
The ~3.8 hours still attributed to no phase is per-model overhead — starting python and
omc, reading the configuration, writing the files, tearing down — about 0.7 s across
19650 models. It belongs to no phase because it is not one.
generated by Claude Code