From a445b9307b9d5d1926a4fbc76e08d0c7b5c1dc1c Mon Sep 17 00:00:00 2001
From: Adrian Pop <adrian.pop@liu.se>
Date: Wed, 12 Aug 2026 18:03:54 +0200
Subject: [PATCH] Record what a command killed by the watchdog cost

A model whose command runs out of time reports nothing for the phase it was in,
so the time disappears from every phase column and only `exectime` still counts
it. In the master run of 2026-08-12 that is 15 models and 1.34 hours, including
three BuildingSystems models that spend the full 660 second budget in
translateModel and are recorded as having spent three seconds parsing and
nothing else.

The caller does try to account for it:

    except TimeoutError as e:
      execstat["frontend"]=monotonic()-start

but that handler never runs. `sendExpressionTimeout` kills the command and calls
`writeResultAndExit` itself, from inside, so the process is gone before the
exception is raised - the results written are whatever `execstat` held when the
command started.

Recording it where the results are written covers every way out instead of the
one path that remembered to. A phase now says when it started, `writeResult`
charges it if it never reported a time of its own, and a phase that ends
normally still reports exactly what it did before.

Which phase a killed command belongs to cannot be known - the timers of omc are
gone with it - so it is charged to what the command itself is: building an FMU
to the build, simulating to the simulation, translating to the front end, which
is also the phase such a model is reported as having failed in.

Verified on Modelica.Fluid.Examples.HeatExchanger.HeatExchangerSimulation with
ulimitOmc=1, which the watchdog kills:

    before   {'parsing': 1.73}
    after    {'parsing': 1.65, 'frontend': 3.01}

and on Modelica.Blocks.Examples.PID_Controller, which succeeds, where every
phase is unchanged.

Part of #308.
---
 testmodel.py | 33 ++++++++++++++++++++++++++++++++-
 1 file changed, 32 insertions(+), 1 deletion(-)

diff --git a/testmodel.py b/testmodel.py
index dba4b3b..bd89869 100755
--- a/testmodel.py
+++ b/testmodel.py
@@ -50,7 +50,29 @@
 class TimeoutError(Exception):
   pass
 
+runningPhase = None
+"""What is running now, as (key of execstat, 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.
+"""
+
+def phaseStarts(key):
+  global runningPhase
+  runningPhase = (key, monotonic())
+
+def phaseEnded():
+  global runningPhase
+  runningPhase = None
+
 def writeResult():
+  if runningPhase is not None:
+    (key, started) = runningPhase
+    # Only if the phase did not get to report its own time.
+    if not execstat.get(key):
+      execstat[key] = monotonic() - started
   with open(statFile, 'w') as fp:
     json.dump(execstat, fp)
     fp.flush()
@@ -447,19 +469,28 @@ def simulateCmd(resimulate):
 total_before = omc.sendExpression("OpenModelica.Scripting.Internal.Time.timerTock(OpenModelica.Scripting.Internal.Time.RT_CLOCK_SIMULATE_TOTAL)")
 start=monotonic()
 timeout = conf["ulimitOmc"]
+# If the command has to be killed there is no way to tell which phase it was in,
+# so its time is charged to what the command itself is: building an FMU to the
+# build, simulating to the simulation, translating to the front end - which is
+# also the phase such a model is reported as having failed in.
 if conf.get("fmi"):
   cmd='"" <> buildModelFMU(%s,fileNamePrefix="%s",fmuType="%s",version="%s",platforms={"static"})' % (conf["modelName"],conf["fileName"].replace(".","_"),conf["fmuType"],conf["fmi"])
+  timedPhase = "build"
 elif useSimulate:
   cmd=simulateCmd(resimulate=False)
   timeout = conf["ulimitOmc"] + conf["ulimitExe"]
+  timedPhase = "sim"
 else:
   cmd='translateModel(%s,tolerance=%g,outputFormat="%s",numberOfIntervals=%d,variableFilter="%s",fileNamePrefix="%s")' % (conf["modelName"],tolerance,outputFormat,numberOfIntervals,variableFilter,conf["fileName"])
+  timedPhase = "frontend"
 with open(errFile, 'a+') as fp:
   fp.write("Running command: %s\n"%(cmd))
 try:
+  phaseStarts(timedPhase)
   res=sendExpressionTimeout(omc, cmd, timeout)
+  phaseEnded()
 except TimeoutError as e:
-  execstat["frontend"]=monotonic()-start
+  execstat[timedPhase]=monotonic()-start
 
   with open(errFile, 'a+') as fp:
     fp.write("Timeout error for cmd: %s\n%s"%(cmd,str(e)))