Merge pull request #3198 from shermanjasonaf/fix-pyros-subsolver-time…

…-limits

Updates to PyROS Solver Timing System

doc/OnlineDocs/contributed_packages/pyros.rst

@@ -903,10 +903,10 @@ Observe that the log contains the following information:
    :linenos:
 
    ==============================================================================
-   PyROS: The Pyomo Robust Optimization Solver, v1.2.9.
-          Pyomo version: 6.7.0
+   PyROS: The Pyomo Robust Optimization Solver, v1.2.11.
+          Pyomo version: 6.7.2
           Commit hash: unknown
-          Invoked at UTC 2023-12-16T00:00:00.000000
+          Invoked at UTC 2024-03-28T00:00:00.000000
 
    Developed by: Natalie M. Isenberg (1), Jason A. F. Sherman (1),
                  John D. Siirola (2), Chrysanthos E. Gounaris (1)
@@ -926,6 +926,7 @@ Observe that the log contains the following information:
     keepfiles=False
     tee=False
     load_solution=True
+    symbolic_solver_labels=False
     objective_focus=<ObjectiveType.worst_case: 1>
     nominal_uncertain_param_vals=[0.13248000000000001, 4.97, 4.97, 1800]
     decision_rule_order=1

pyomo/contrib/pyros/CHANGELOG.txt

@@ -2,6 +2,17 @@
 PyROS CHANGELOG
 ===============
 
+-------------------------------------------------------------------------------
+PyROS 1.2.11    17 Mar 2024
+-------------------------------------------------------------------------------
+- Standardize calls to subordinate solvers across all PyROS subproblem types
+- Account for user-specified subsolver time limits when automatically
+  adjusting subsolver time limits
+- Add support for automatic adjustment of SCIP subsolver time limit
+- Move start point of main PyROS solver timer to just before argument
+  validation begins
+
+
 -------------------------------------------------------------------------------
 PyROS 1.2.10    07 Feb 2024
 -------------------------------------------------------------------------------

pyomo/contrib/pyros/config.py

@@ -503,6 +503,21 @@ def pyros_config():
             ),
         ),
     )
+    CONFIG.declare(
+        'symbolic_solver_labels',
+        ConfigValue(
+            default=False,
+            domain=bool,
+            description=(
+                """
+                True to ensure the component names given to the
+                subordinate solvers for every subproblem reflect
+                the names of the corresponding Pyomo modeling components,
+                False otherwise.
+                """
+            ),
+        ),
+    )
 
     # ================================================
     # === Required User Inputs

pyomo/contrib/pyros/master_problem_methods.py

@@ -27,6 +27,7 @@
 from pyomo.core.expr import value
 from pyomo.core.base.set_types import NonNegativeIntegers, NonNegativeReals
 from pyomo.contrib.pyros.util import (
+    call_solver,
     selective_clone,
     ObjectiveType,
     pyrosTerminationCondition,
@@ -239,31 +240,18 @@ def solve_master_feasibility_problem(model_data, config):
     else:
         solver = config.local_solver
 
-    timer = TicTocTimer()
-    orig_setting, custom_setting_present = adjust_solver_time_settings(
-        model_data.timing, solver, config
-    )
-    model_data.timing.start_timer("main.master_feasibility")
-    timer.tic(msg=None)
-    try:
-        results = solver.solve(model, tee=config.tee, load_solutions=False)
-    except ApplicationError:
-        # account for possible external subsolver errors
-        # (such as segmentation faults, function evaluation
-        # errors, etc.)
-        config.progress_logger.error(
+    results = call_solver(
+        model=model,
+        solver=solver,
+        config=config,
+        timing_obj=model_data.timing,
+        timer_name="main.master_feasibility",
+        err_msg=(
             f"Optimizer {repr(solver)} encountered exception "
             "attempting to solve master feasibility problem in iteration "
             f"{model_data.iteration}."
-        )
-        raise
-    else:
-        setattr(results.solver, TIC_TOC_SOLVE_TIME_ATTR, timer.toc(msg=None))
-        model_data.timing.stop_timer("main.master_feasibility")
-    finally:
-        revert_solver_max_time_adjustment(
-            solver, orig_setting, custom_setting_present, config
-        )
+        ),
+    )
 
     feasible_terminations = {
         tc.optimal,
@@ -482,28 +470,18 @@ def minimize_dr_vars(model_data, config):
     config.progress_logger.debug(f" Initial DR norm: {value(polishing_obj)}")
 
     # === Solve the polishing model
-    timer = TicTocTimer()
-    orig_setting, custom_setting_present = adjust_solver_time_settings(
-        model_data.timing, solver, config
-    )
-    model_data.timing.start_timer("main.dr_polishing")
-    timer.tic(msg=None)
-    try:
-        results = solver.solve(polishing_model, tee=config.tee, load_solutions=False)
-    except ApplicationError:
-        config.progress_logger.error(
+    results = call_solver(
+        model=polishing_model,
+        solver=solver,
+        config=config,
+        timing_obj=model_data.timing,
+        timer_name="main.dr_polishing",
+        err_msg=(
             f"Optimizer {repr(solver)} encountered an exception "
             "attempting to solve decision rule polishing problem "
             f"in iteration {model_data.iteration}"
-        )
-        raise
-    else:
-        setattr(results.solver, TIC_TOC_SOLVE_TIME_ATTR, timer.toc(msg=None))
-        model_data.timing.stop_timer("main.dr_polishing")
-    finally:
-        revert_solver_max_time_adjustment(
-            solver, orig_setting, custom_setting_present, config
-        )
+        ),
+    )
 
     # interested in the time and termination status for debugging
     # purposes
@@ -726,43 +704,25 @@ def solver_call_master(model_data, config, solver, solve_data):
     solve_mode = "global" if config.solve_master_globally else "local"
     config.progress_logger.debug("Solving master problem")
 
-    timer = TicTocTimer()
     for idx, opt in enumerate(solvers):
         if idx > 0:
             config.progress_logger.warning(
                 f"Invoking backup solver {opt!r} "
                 f"(solver {idx + 1} of {len(solvers)}) for "
                 f"master problem of iteration {model_data.iteration}."
             )
-        orig_setting, custom_setting_present = adjust_solver_time_settings(
-            model_data.timing, opt, config
-        )
-        model_data.timing.start_timer("main.master")
-        timer.tic(msg=None)
-        try:
-            results = opt.solve(
-                nlp_model,
-                tee=config.tee,
-                load_solutions=False,
-                symbolic_solver_labels=True,
-            )
-        except ApplicationError:
-            # account for possible external subsolver errors
-            # (such as segmentation faults, function evaluation
-            # errors, etc.)
-            config.progress_logger.error(
+        results = call_solver(
+            model=nlp_model,
+            solver=opt,
+            config=config,
+            timing_obj=model_data.timing,
+            timer_name="main.master",
+            err_msg=(
                 f"Optimizer {repr(opt)} ({idx + 1} of {len(solvers)}) "
                 "encountered exception attempting to "
                 f"solve master problem in iteration {model_data.iteration}"
-            )
-            raise
-        else:
-            setattr(results.solver, TIC_TOC_SOLVE_TIME_ATTR, timer.toc(msg=None))
-            model_data.timing.stop_timer("main.master")
-        finally:
-            revert_solver_max_time_adjustment(
-                solver, orig_setting, custom_setting_present, config
-            )
+            ),
+        )
 
         optimal_termination = check_optimal_termination(results)
         infeasible = results.solver.termination_condition == tc.infeasible

pyomo/contrib/pyros/pyros.py

@@ -12,15 +12,14 @@
 # pyros.py: Generalized Robust Cutting-Set Algorithm for Pyomo
 import logging
 from pyomo.common.config import document_kwargs_from_configdict
-from pyomo.common.collections import Bunch
 from pyomo.core.base.block import Block
 from pyomo.core.expr import value
 from pyomo.core.base.var import Var
 from pyomo.core.base.objective import Objective
 from pyomo.contrib.pyros.util import time_code
 from pyomo.common.modeling import unique_component_name
 from pyomo.opt import SolverFactory
-from pyomo.contrib.pyros.config import pyros_config
+from pyomo.contrib.pyros.config import pyros_config, logger_domain
 from pyomo.contrib.pyros.util import (
     recast_to_min_obj,
     add_decision_rule_constraints,
@@ -44,7 +43,7 @@
 from datetime import datetime
 
 
-__version__ = "1.2.10"
+__version__ = "1.2.11"
 
 
 default_pyros_solver_logger = setup_pyros_logger()
@@ -330,32 +329,41 @@ def solve(
             Summary of PyROS termination outcome.
 
         """
-        kwds.update(
-            dict(
-                first_stage_variables=first_stage_variables,
-                second_stage_variables=second_stage_variables,
-                uncertain_params=uncertain_params,
-                uncertainty_set=uncertainty_set,
-                local_solver=local_solver,
-                global_solver=global_solver,
-            )
-        )
-        config, state_vars = self._resolve_and_validate_pyros_args(model, **kwds)
-
-        # === Create data containers
         model_data = ROSolveResults()
-        model_data.timing = Bunch()
-
-        # === Start timer, run the algorithm
         model_data.timing = TimingData()
         with time_code(
             timing_data_obj=model_data.timing,
             code_block_name="main",
             is_main_timer=True,
         ):
-            # output intro and disclaimer
-            self._log_intro(logger=config.progress_logger, level=logging.INFO)
-            self._log_disclaimer(logger=config.progress_logger, level=logging.INFO)
+            kwds.update(
+                dict(
+                    first_stage_variables=first_stage_variables,
+                    second_stage_variables=second_stage_variables,
+                    uncertain_params=uncertain_params,
+                    uncertainty_set=uncertainty_set,
+                    local_solver=local_solver,
+                    global_solver=global_solver,
+                )
+            )
+
+            # we want to log the intro and disclaimer in
+            # advance of assembling the config.
+            # this helps clarify to the user that any
+            # messages logged during assembly of the config
+            # were, in fact, logged after PyROS was initiated
+            progress_logger = logger_domain(
+                kwds.get(
+                    "progress_logger",
+                    kwds.get("options", dict()).get(
+                        "progress_logger", default_pyros_solver_logger
+                    ),
+                )
+            )
+            self._log_intro(logger=progress_logger, level=logging.INFO)
+            self._log_disclaimer(logger=progress_logger, level=logging.INFO)
+
+            config, state_vars = self._resolve_and_validate_pyros_args(model, **kwds)
             self._log_config(
                 logger=config.progress_logger,
                 config=config,

pyomo/contrib/pyros/separation_problem_methods.py

@@ -18,7 +18,6 @@
 from pyomo.core.base import Var, Param
 from pyomo.common.collections import ComponentSet, ComponentMap
 from pyomo.common.dependencies import numpy as np
-from pyomo.contrib.pyros.util import ObjectiveType, get_time_from_solver
 from pyomo.contrib.pyros.solve_data import (
     DiscreteSeparationSolveCallResults,
     SeparationSolveCallResults,
@@ -37,9 +36,11 @@
 from pyomo.contrib.pyros.util import ABS_CON_CHECK_FEAS_TOL
 from pyomo.common.timing import TicTocTimer
 from pyomo.contrib.pyros.util import (
-    TIC_TOC_SOLVE_TIME_ATTR,
     adjust_solver_time_settings,
+    call_solver,
+    ObjectiveType,
     revert_solver_max_time_adjustment,
+    TIC_TOC_SOLVE_TIME_ATTR,
 )
 import os
 from copy import deepcopy
@@ -1070,14 +1071,14 @@ def solver_call_separation(
 
     separation_obj.activate()
 
+    solve_mode_adverb = "globally" if solve_globally else "locally"
     solve_call_results = SeparationSolveCallResults(
         solved_globally=solve_globally,
         time_out=False,
         results_list=[],
         found_violation=False,
         subsolver_error=False,
     )
-    timer = TicTocTimer()
     for idx, opt in enumerate(solvers):
         if idx > 0:
             config.progress_logger.warning(
@@ -1086,37 +1087,19 @@ def solver_call_separation(
                 f"separation of performance constraint {con_name_repr} "
                 f"in iteration {model_data.iteration}."
             )
-        orig_setting, custom_setting_present = adjust_solver_time_settings(
-            model_data.timing, opt, config
-        )
-        model_data.timing.start_timer(f"main.{solve_mode}_separation")
-        timer.tic(msg=None)
-        try:
-            results = opt.solve(
-                nlp_model,
-                tee=config.tee,
-                load_solutions=False,
-                symbolic_solver_labels=True,
-            )
-        except ApplicationError:
-            # account for possible external subsolver errors
-            # (such as segmentation faults, function evaluation
-            # errors, etc.)
-            adverb = "globally" if solve_globally else "locally"
-            config.progress_logger.error(
+        results = call_solver(
+            model=nlp_model,
+            solver=opt,
+            config=config,
+            timing_obj=model_data.timing,
+            timer_name=f"main.{solve_mode}_separation",
+            err_msg=(
                 f"Optimizer {repr(opt)} ({idx + 1} of {len(solvers)}) "
                 f"encountered exception attempting "
-                f"to {adverb} solve separation problem for constraint "
+                f"to {solve_mode_adverb} solve separation problem for constraint "
                 f"{con_name_repr} in iteration {model_data.iteration}."
-            )
-            raise
-        else:
-            setattr(results.solver, TIC_TOC_SOLVE_TIME_ATTR, timer.toc(msg=None))
-            model_data.timing.stop_timer(f"main.{solve_mode}_separation")
-        finally:
-            revert_solver_max_time_adjustment(
-                opt, orig_setting, custom_setting_present, config
-            )
+            ),
+        )
 
         # record termination condition for this particular solver
         solver_status_dict[str(opt)] = results.solver.termination_condition