From 19d25119b41adac21a3908e1fd3531fb02cba71a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Martin=20Sj=C3=B6lund?= Date: Mon, 31 Aug 2026 10:36:46 +0200 Subject: [PATCH] Record the phase times a timed-out model reached omc's alarm now asks the running command to unwind before it kills the process, so a command that runs out of time still reports how far it got. Both watchdogs have to outwait that grace, or they kill omc in the middle of producing the answer: `sendExpressionTimeout`'s own deadline and test.py's outer per-model budget. `shared.alarmGrace` mirrors `SystemImpl__alarm`'s formula. The simulation phase is also recorded on every way out, not just the ones that reach a handler. `sendExpressionTimeout` ends the process itself when omc dies, so the caller's `except TimeoutError` never runs; `runningPhase` covers that, and now takes the results dict so a later runner's own simulation time survives it too. `simElapsed` falls back to the wall clock when omc reports no time of its own, which is what an aborted run does. In the run of 2026-08-30 this was 90 models and 23936 s of wall clock recorded against no phase at all, 34 of them reporting `finalphase=0` with every clock at zero after 300-800 s. The `master` lane, whose simulations are separate processes this script kills itself, had none. The ladder that turns omc's nested stopwatches into per-phase times also had two guards swapped: the backend's own time was computed under `templates != -1` and SimCode's under `simcode != -1`, each testing the clock of the wrong phase. A translation that died in SimCode was recorded as having died in the backend, and the phase before the failure got no time. It is now one ladder over the clock that reads -1, which is both what says how far the translation got and what says which differences can be taken. Assisted-by: Claude Opus 5 --- shared.py | 8 ++++++ test.py | 6 +++-- testmodel.py | 76 +++++++++++++++++++++++++++++----------------------- 3 files changed, 55 insertions(+), 35 deletions(-) diff --git a/shared.py b/shared.py index f8f3a89..967c785 100644 --- a/shared.py +++ b/shared.py @@ -85,6 +85,14 @@ def fixData(data,abortSimulationFlag,alarmFlag,overrideDefaults,defaultCustomCom print("Failed to fix data for: %s with extra args: %s" % (str(data),str((abortSimulationFlag,alarmFlag,defaultCustomCommands)))) raise +def alarmGrace(timeout): + """How long omc keeps running past its own alarm before it kills itself. + + Mirrors SystemImpl__alarm. Waiting it out is what lets a timed-out command + report the phases it did complete. + """ + return min(60, max(5, timeout // 10)) + def modelUlimitExe(conf, modelName): """How long that model may simulate: what its library allows, unless the model is one of the few named in ulimitExeModels.""" diff --git a/test.py b/test.py index 1bc831f..9fc2fec 100755 --- a/test.py +++ b/test.py @@ -16,7 +16,7 @@ from monotonic import monotonic from omcommon import friendlyStr, multiple_replace from natsort import natsorted -from shared import readConfig, getReferenceFileName, simulationAcceptsFlag, isFMPy, modelUlimitExe, simulationFlags +from shared import readConfig, getReferenceFileName, simulationAcceptsFlag, isFMPy, modelUlimitExe, simulationFlags, alarmGrace from platform import processor import shared, resultsdb @@ -1008,7 +1008,9 @@ def expectedExec(c): if customTimeout > 0.0: cmd_res=Parallel(n_jobs=n_jobs, verbose=verbose)(delayed(runScript)(name, customTimeout, data["ulimitMemory"], runverbose) for (model,lib,libName,name,data) in tests) else: - cmd_res=Parallel(n_jobs=n_jobs, verbose=verbose)(delayed(runScript)(name, 2*data["ulimitOmc"]+modelUlimitExe(data, model)+25, data["ulimitMemory"], runverbose) for (model,lib,libName,name,data) in tests) + # Each command that runs out of time keeps running for a grace before it gives + # up; killing testmodel.py during it throws away the phase times. + cmd_res=Parallel(n_jobs=n_jobs, verbose=verbose)(delayed(runScript)(name, 2*(data["ulimitOmc"]+alarmGrace(data["ulimitOmc"]))+modelUlimitExe(data, model)+alarmGrace(modelUlimitExe(data, model))+25, data["ulimitMemory"], runverbose) for (model,lib,libName,name,data) in tests) stop=monotonic() print("Execution time: %s" % friendlyStr(stop-start)) assert(stop-start >= 0.0) diff --git a/testmodel.py b/testmodel.py index d25149a..27cec7b 100755 --- a/testmodel.py +++ b/testmodel.py @@ -51,17 +51,18 @@ class TimeoutError(Exception): pass runningPhase = None -"""What is running now, as (key of execstat, when it started). +"""What is running now, as (results dict, key in it, when it started). A command the watchdog has to kill never returns to its caller - sendExpressionTimeout ends the process itself - so the caller's own timeout handler does not run and the phase reports no time at all. Recording it here -instead covers every way out, because they all write the results first. +instead covers every way out, because they all write the results first. The +dict is None for the model's own results, one runner's when it is its turn. """ -def phaseStarts(key): +def phaseStarts(key, stat=None): global runningPhase - runningPhase = (key, monotonic()) + runningPhase = (stat, key, monotonic()) def phaseEnded(): global runningPhase @@ -69,10 +70,11 @@ def phaseEnded(): def writeResult(): if runningPhase is not None: - (key, started) = runningPhase + (stat, key, started) = runningPhase + target = execstat if stat is None else stat # Only if the phase did not get to report its own time. - if not execstat.get(key): - execstat[key] = monotonic() - started + if not target.get(key): + target[key] = monotonic() - started with open(statFile, 'w') as fp: json.dump(execstat, fp) fp.flush() @@ -143,8 +145,9 @@ def target(res): thread = threading.Thread(target=target, args=(res,), daemon=True) thread.start() # Poll instead of a single join: if omc dies (crash, ulimit, ...) the thread is - # stuck in that receive, and waiting out the whole timeout first buys nothing - deadline = monotonic() + timeout + # stuck in that receive, and waiting out the whole timeout first buys nothing. + # The deadline outwaits omc's own, which aborts the command and answers. + deadline = monotonic() + timeout + shared.alarmGrace(timeout) + 5 while thread.is_alive() and monotonic() < deadline: thread.join(1) status = omc._omc_process.poll() @@ -553,30 +556,29 @@ def simulateCmd(resimulate): omc = quit_omc(omc) print(execTimeTranslateModel,frontend,backend) -if backend != -1: +# The clocks nest, frontend > backend > simcode > templates > buildmodel, each +# reading the time since its own phase started, so a phase's own time is the +# difference to the next one in. -1 is a phase this translation never started. +if backend == -1: + execstat["phase"]=0 + if frontend != -1: + execstat["frontend"]=frontend +elif simcode == -1: + execstat["phase"]=1 execstat["frontend"]=frontend-backend - if templates != -1: - execstat["backend"]=backend-simcode - if simcode != -1: - execstat["simcode"]=simcode-templates - if templates != -1: - execstat["templates"]=templates-max(buildmodel, 0.0) - if res: - execstat["phase"]=4 - else: - execstat["phase"]=3 - else: - execstat["phase"]=3 - execstat["templates"]=templates - else: - execstat["phase"]=2 - execstat["simcode"]=simcode - else: - execstat["phase"]=1 - execstat["backend"]=backend + execstat["backend"]=backend +elif templates == -1: + execstat["phase"]=2 + execstat["frontend"]=frontend-backend + execstat["backend"]=backend-simcode + execstat["simcode"]=simcode else: - execstat["phase"]=0 - execstat["frontend"]=frontend + execstat["frontend"]=frontend-backend + execstat["backend"]=backend-simcode + execstat["simcode"]=simcode-templates + # -1: the translation never got to the build, so there is none to take out. + execstat["templates"]=templates-max(buildmodel, 0.0) + execstat["phase"]=4 if res else 3 with open(errFile, 'a+') as fp: fp.write(err) @@ -733,15 +735,19 @@ def simulateExecutable(name, solverFlags, resFile, simFile): return checkOutputTimeout("(rm -f %s.pipe ; mkfifo %s.pipe ; head -c 1048576 < %s.pipe >> %s & %s > %s.pipe 2>&1)" % (pipe,pipe,pipe,simFile,cmd,pipe), conf["ulimitExe"], conf) def simElapsed(): - # omc's own time: the wall clock here covers the wrong run for these flags + # omc's own time: the wall clock here covers the wrong run for these flags. + # A run omc aborted reports none, and then the wall clock is all there is. if useSimulate or useColdHot or useArtifact: - return (simres or {}).get("timeSimulation") or 0.0 + return (simres or {}).get("timeSimulation") or (monotonic()-start) return monotonic()-start start=monotonic() # Set when the first FMI simulator fails and there are others waiting for the # same FMU, so that its result file is not compared against the reference. firstSimulatorFailed = False +# omc dying on its own alarm ends the run from inside sendExpressionTimeout, so +# the handler below never runs; naming the phase covers that way out too. +phaseStarts("sim") try: # TODO: Timeout more reliably... if conf.get("fmi"): @@ -796,9 +802,11 @@ def simElapsed(): execstat["sim"] = simElapsed() execstat["simwall"] = monotonic()-start execstat["phase"] = 6 + phaseEnded() except TimeoutError as e: execstat["sim"] = monotonic()-start execstat["simwall"] = execstat["sim"] + phaseEnded() # checkOutputTimeout raises TimeoutError for a command that fails as well as # for one that runs out of time, so this covers both. if len(runners) > 1: @@ -939,6 +947,7 @@ def verifyAgainstReference(resFile, prefix, stat): simFileOther = os.path.abspath("../files/%s_%s.sim" % (conf["fileName"], name)).replace('\\','/') other = resultFile(name) start = monotonic() + phaseStarts("sim", stat) try: if useArtifact: res = simulateArtifact(name, command, other, simFileOther) @@ -961,6 +970,7 @@ def verifyAgainstReference(resFile, prefix, stat): stat["simwall"] = stat["sim"] with open(errFile, 'a+') as fp: fp.write("%s timed out simulating the %s\n" % (name, "artifact" if useArtifact else ("model" if solverRunners else "FMU"))) + phaseEnded() writeResult() # quit omc_new: every verification needed it