Track the runtime of PROCESS regression tests

process/caller.py

@@ -8,12 +8,12 @@
 from tabulate import tabulate
 
 import process.constraints as constraints
-from process import data_structure
+from process import constants, data_structure
 from process.final import finalise
 from process.io.mfile import MFile
 from process.iteration_variables import set_scaled_iteration_variable
 from process.objectives import objective_function
-from process.process_output import OutputFileManager
+from process.process_output import OutputFileManager, ovarre
 
 if TYPE_CHECKING:
     from process.main import Models
@@ -357,7 +357,9 @@ def _call_models_once(self, xc: np.ndarray) -> None:
         # FISPACT and LOCA model (not used)- removed
 
 
-def write_output_files(models: Models, ifail: int) -> None:
+def write_output_files(
+    models: Models, ifail: int, *, runtime: float | None = None
+) -> None:
     """Evaluate models and write output files (OUT.DAT and MFILE.DAT).
 
     :param models: physics and engineering models
@@ -369,6 +371,13 @@ def write_output_files(models: Models, ifail: int) -> None:
     x = data_structure.numerics.xcm[:n]
     # Call models, ensuring output mfiles are fully idempotent
     caller = Caller(models)
+    if runtime is not None:
+        ovarre(
+            constants.MFILE,
+            "Runtime of PROCESS in seconds",
+            "(process_runtime)",
+            runtime,
+        )
     caller.call_models_and_write_output(
         xc=x,
         ifail=ifail,

process/scan.py

@@ -1,4 +1,5 @@
 import logging
+import time
 from dataclasses import astuple, dataclass
 
 import numpy as np
@@ -167,8 +168,11 @@ def run_scan(self):
         if scan_variables.isweep == 0:
             # Solve single problem, rather than an array of problems (scan)
             # doopt() can also run just an evaluation
+            start_time = time.time()
             ifail = self.doopt()
-            write_output_files(models=self.models, ifail=ifail)
+            write_output_files(
+                models=self.models, ifail=ifail, runtime=time.time() - start_time
+            )
             show_errors(constants.NOUT)
             return
 
@@ -758,9 +762,12 @@ def scan_1d(self):
 
         for iscan in range(1, scan_variables.isweep + 1):
             self.scan_1d_write_point_header(iscan)
+            start_time = time.time()
             ifail = self.doopt()
             scan_1d_ifail_dict[iscan] = ifail
-            write_output_files(models=self.models, ifail=ifail)
+            write_output_files(
+                models=self.models, ifail=ifail, runtime=time.time() - start_time
+            )
 
             show_errors(constants.NOUT)
             logging_model_handler.clear_logs()
@@ -813,9 +820,11 @@ def scan_2d(self):
         for iscan_1 in range(1, scan_variables.isweep + 1):
             for iscan_2 in range(1, scan_variables.isweep_2 + 1):
                 self.scan_2d_write_point_header(iscan, iscan_1, iscan_2)
+                start_time = time.time()
                 ifail = self.doopt()
-
-                write_output_files(models=self.models, ifail=ifail)
+                write_output_files(
+                    models=self.models, ifail=ifail, runtime=time.time() - start_time
+                )
 
                 show_errors(constants.NOUT)
                 logging_model_handler.clear_logs()

tests/regression/test_process_input_files.py

@@ -32,6 +32,7 @@
     r"sig_tf_r_max\(1\)",  # weird value, flips between 0 and very low?
     r"normres[0-9]+",
     r"nitvar[0-9]+",
+    "process_runtime",
 }
 
 

tracking/tracking_data.py

@@ -62,6 +62,7 @@
 logger = logging.getLogger("PROCESS Tracker")
 
 DEFAULT_TRACKING_VARIABLES = {
+    "Metadata.process_runtime",
     "CurrentDrive.p_hcd_primary_extra_heat_mw",
     "CurrentDrive.f_c_plasma_bootstrap",
     "CurrentDrive.p_hcd_injected_total_mw",