diff --git a/doc/OnlineDocs/contributed_packages/pyros.rst b/doc/OnlineDocs/contributed_packages/pyros.rst index 4ef57fbf26c..23ec60f2e20 100644 --- a/doc/OnlineDocs/contributed_packages/pyros.rst +++ b/doc/OnlineDocs/contributed_packages/pyros.rst @@ -538,12 +538,16 @@ correspond to first-stage degrees of freedom. ... solve_master_globally=True, ... load_solution=False, ... ) - =========================================================================================== - PyROS: Pyomo Robust Optimization Solver ... - =========================================================================================== + ============================================================================== + PyROS: The Pyomo Robust Optimization Solver. ... - INFO: Robust optimal solution identified. Exiting PyROS. - + ------------------------------------------------------------------------------ + Robust optimal solution identified. + ------------------------------------------------------------------------------ + ... + ------------------------------------------------------------------------------ + All done. Exiting PyROS. + ============================================================================== >>> # === Query results === >>> time = results_1.time >>> iterations = results_1.iterations @@ -604,6 +608,8 @@ optional keyword argument ``decision_rule_order`` to the PyROS In this example, we select affine decision rules by setting ``decision_rule_order=1``: +.. _example-two-stg: + .. doctest:: :skipif: not (baron.available() and baron.license_is_valid()) @@ -625,11 +631,16 @@ In this example, we select affine decision rules by setting ... solve_master_globally=True, ... decision_rule_order=1, ... ) - =========================================================================================== - PyROS: Pyomo Robust Optimization Solver ... + ============================================================================== + PyROS: The Pyomo Robust Optimization Solver... ... - INFO: Robust optimal solution identified. Exiting PyROS. - + ------------------------------------------------------------------------------ + Robust optimal solution identified. + ------------------------------------------------------------------------------ + ... + ------------------------------------------------------------------------------ + All done. Exiting PyROS. + ============================================================================== >>> # === Compare final objective to the single-stage solution >>> two_stage_final_objective = round( ... pyo.value(results_2.final_objective_value), @@ -733,7 +744,289 @@ set size on the robust optimal objective function value and demonstrates the ease of implementing a price of robustness study for a given optimization problem under uncertainty. -.. note:: +PyROS Solver Log Output +------------------------------- + +The PyROS solver log output is controlled through the optional +``progress_logger`` argument, itself cast to +a standard Python logger (:py:class:`logging.Logger`) object +at the outset of a :meth:`~pyomo.contrib.pyros.PyROS.solve` call. +The level of detail of the solver log output +can be adjusted by adjusting the level of the +logger object; see :ref:`the following table `. +Note that by default, ``progress_logger`` is cast to a logger of level +:py:obj:`logging.INFO`. + +We refer the reader to the +:doc:`official Python logging library documentation ` +for customization of Python logger objects; +for a basic tutorial, see the :doc:`logging HOWTO `. + +.. _table-logging-levels: + +.. list-table:: PyROS solver log output at the various standard Python :py:mod:`logging` levels. + :widths: 10 50 + :header-rows: 1 + + * - Logging Level + - Output Messages + * - :py:obj:`logging.ERROR` + - * Information on the subproblem for which an exception was raised + by a subordinate solver + * Details about failure of the PyROS coefficient matching routine + * - :py:obj:`logging.WARNING` + - * Information about a subproblem not solved to an acceptable status + by the user-provided subordinate optimizers + * Invocation of a backup solver for a particular subproblem + * Caution about solution robustness guarantees in event that + user passes ``bypass_global_separation=True`` + * - :py:obj:`logging.INFO` + - * PyROS version, author, and disclaimer information + * Summary of user options + * Breakdown of model component statistics + * Iteration log table + * Termination details: message, timing breakdown, summary of statistics + * - :py:obj:`logging.DEBUG` + - * Termination outcomes and summary of statistics for + every master feasility, master, and DR polishing problem + * Progress updates for the separation procedure + * Separation subproblem initial point infeasibilities + * Summary of separation loop outcomes: performance constraints + violated, uncertain parameter scenario added to the + master problem + * Uncertain parameter scenarios added to the master problem + thus far + +An example of an output log produced through the default PyROS +progress logger is shown in +:ref:`the snippet that follows `. +Observe that the log contains the following information: + + +* **Introductory information** (lines 1--18). + Includes the version number, author + information, (UTC) time at which the solver was invoked, + and, if available, information on the local Git branch and + commit hash. +* **Summary of solver options** (lines 19--38). +* **Preprocessing information** (lines 39--41). + Wall time required for preprocessing + the deterministic model and associated components, + i.e. standardizing model components and adding the decision rule + variables and equations. +* **Model component statistics** (lines 42--58). + Breakdown of model component statistics. + Includes components added by PyROS, such as the decision rule variables + and equations. +* **Iteration log table** (lines 59--69). + Summary information on the problem iterates and subproblem outcomes. + The constituent columns are defined in detail in + :ref:`the table following the snippet `. +* **Termination message** (lines 70--71). Very brief summary of the termination outcome. +* **Timing statistics** (lines 72--88). + Tabulated breakdown of the solver timing statistics, based on a + :class:`pyomo.common.timing.HierarchicalTimer` printout. + The identifiers are as follows: + + * ``main``: Total time elapsed by the solver. + * ``main.dr_polishing``: Total time elapsed by the subordinate solvers + on polishing of the decision rules. + * ``main.global_separation``: Total time elapsed by the subordinate solvers + on global separation subproblems. + * ``main.local_separation``: Total time elapsed by the subordinate solvers + on local separation subproblems. + * ``main.master``: Total time elapsed by the subordinate solvers on + the master problems. + * ``main.master_feasibility``: Total time elapsed by the subordinate solvers + on the master feasibility problems. + * ``main.preprocessing``: Total preprocessing time. + * ``main.other``: Total overhead time. + +* **Termination statistics** (lines 89--94). Summary of statistics related to the + iterate at which PyROS terminates. +* **Exit message** (lines 95--96). + + +.. _solver-log-snippet: + +.. code-block:: text + :caption: PyROS solver output log for the :ref:`two-stage problem example `. + :linenos: + + ============================================================================== + PyROS: The Pyomo Robust Optimization Solver, v1.2.8. + Pyomo version: 6.7.0 + Commit hash: unknown + Invoked at UTC 2023-11-03T04:27:42.954101 + + Developed by: Natalie M. Isenberg (1), Jason A. F. Sherman (1), + John D. Siirola (2), Chrysanthos E. Gounaris (1) + (1) Carnegie Mellon University, Department of Chemical Engineering + (2) Sandia National Laboratories, Center for Computing Research + + The developers gratefully acknowledge support from the U.S. Department + of Energy's Institute for the Design of Advanced Energy Systems (IDAES). + ============================================================================== + ================================= DISCLAIMER ================================= + PyROS is still under development. + Please provide feedback and/or report any issues by creating a ticket at + https://github.com/Pyomo/pyomo/issues/new/choose + ============================================================================== + Solver options: + time_limit=None + keepfiles=False + tee=False + load_solution=True + objective_focus= + nominal_uncertain_param_vals=[0.13248000000000001, 4.97, 4.97, 1800] + decision_rule_order=1 + solve_master_globally=True + max_iter=-1 + robust_feasibility_tolerance=0.0001 + separation_priority_order={} + progress_logger= + backup_local_solvers=[] + backup_global_solvers=[] + subproblem_file_directory=None + bypass_local_separation=False + bypass_global_separation=False + p_robustness={} + ------------------------------------------------------------------------------ + Preprocessing... + Done preprocessing; required wall time of 0.175s. + ------------------------------------------------------------------------------ + Model statistics: + Number of variables : 62 + Epigraph variable : 1 + First-stage variables : 7 + Second-stage variables : 6 + State variables : 18 + Decision rule variables : 30 + Number of uncertain parameters : 4 + Number of constraints : 81 + Equality constraints : 24 + Coefficient matching constraints : 0 + Decision rule equations : 6 + All other equality constraints : 18 + Inequality constraints : 57 + First-stage inequalities (incl. certain var bounds) : 10 + Performance constraints (incl. var bounds) : 47 + ------------------------------------------------------------------------------ + Itn Objective 1-Stg Shift DR Shift #CViol Max Viol Wall Time (s) + ------------------------------------------------------------------------------ + 0 3.5838e+07 - - 5 1.8832e+04 1.198 + 1 3.5838e+07 7.4506e-09 1.6105e+03 7 3.7766e+04 2.893 + 2 3.6116e+07 2.7803e+05 1.2918e+03 8 1.3466e+06 4.732 + 3 3.6285e+07 1.6957e+05 5.8386e+03 6 4.8734e+03 6.740 + 4 3.6285e+07 1.4901e-08 3.3097e+03 1 3.5036e+01 9.099 + 5 3.6285e+07 2.9786e-10 3.3597e+03 6 2.9103e+00 11.588 + 6 3.6285e+07 7.4506e-07 8.7228e+02 5 4.1726e-01 14.360 + 7 3.6285e+07 7.4506e-07 8.1995e+02 0 9.3279e-10g 21.597 + ------------------------------------------------------------------------------ + Robust optimal solution identified. + ------------------------------------------------------------------------------ + Timing breakdown: + + Identifier ncalls cumtime percall % + ----------------------------------------------------------- + main 1 21.598 21.598 100.0 + ------------------------------------------------------ + dr_polishing 7 1.502 0.215 7.0 + global_separation 47 1.300 0.028 6.0 + local_separation 376 9.779 0.026 45.3 + master 8 5.385 0.673 24.9 + master_feasibility 7 0.531 0.076 2.5 + preprocessing 1 0.175 0.175 0.8 + other n/a 2.926 n/a 13.5 + ====================================================== + =========================================================== + + ------------------------------------------------------------------------------ + Termination stats: + Iterations : 8 + Solve time (wall s) : 21.598 + Final objective value : 3.6285e+07 + Termination condition : pyrosTerminationCondition.robust_optimal + ------------------------------------------------------------------------------ + All done. Exiting PyROS. + ============================================================================== + + +The iteration log table is designed to provide, in a concise manner, +important information about the progress of the iterative algorithm for +the problem of interest. +The constituent columns are defined in the +:ref:`table that follows `. + +.. _table-iteration-log-columns: + +.. list-table:: PyROS iteration log table columns. + :widths: 10 50 + :header-rows: 1 - Please provide feedback and/or report any problems by opening an issue on - the `Pyomo GitHub page `_. + * - Column Name + - Definition + * - Itn + - Iteration number. + * - Objective + - Master solution objective function value. + If the objective of the deterministic model provided + has a maximization sense, + then the negative of the objective function value is displayed. + Expect this value to trend upward as the iteration number + increases. + If the master problems are solved globally + (by passing ``solve_master_globally=True``), + then after the iteration number exceeds the number of uncertain parameters, + this value should be monotonically nondecreasing + as the iteration number is increased. + A dash ("-") is produced in lieu of a value if the master + problem of the current iteration is not solved successfully. + * - 1-Stg Shift + - Infinity norm of the difference between the first-stage + variable vectors of the master solutions of the current + and previous iterations. Expect this value to trend + downward as the iteration number increases. + A dash ("-") is produced in lieu of a value + if the current iteration number is 0, + there are no first-stage variables, + or the master problem of the current iteration is not solved successfully. + * - DR Shift + - Infinity norm of the difference between the decision rule + variable vectors of the master solutions of the current + and previous iterations. + Expect this value to trend downward as the iteration number increases. + An asterisk ("*") is appended to this value if the decision rules are + not successfully polished. + A dash ("-") is produced in lieu of a value + if the current iteration number is 0, + there are no decision rule variables, + or the master problem of the current iteration is not solved successfully. + * - #CViol + - Number of performance constraints found to be violated during + the separation step of the current iteration. + Unless a custom prioritization of the model's performance constraints + is specified (through the ``separation_priority_order`` argument), + expect this number to trend downward as the iteration number increases. + A "+" is appended if not all of the separation problems + were solved successfully, either due to custom prioritization, a time out, + or an issue encountered by the subordinate optimizers. + A dash ("-") is produced in lieu of a value if the separation + routine is not invoked during the current iteration. + * - Max Viol + - Maximum scaled performance constraint violation. + Expect this value to trend downward as the iteration number increases. + A 'g' is appended to the value if the separation problems were solved + globally during the current iteration. + A dash ("-") is produced in lieu of a value if the separation + routine is not invoked during the current iteration, or if there are + no performance constraints. + * - Wall time (s) + - Total time elapsed by the solver, in seconds, up to the end of the + current iteration. + + +Feedback and Reporting Issues +------------------------------- +Please provide feedback and/or report any problems by opening an issue on +the `Pyomo GitHub page `_. diff --git a/pyomo/contrib/pyros/CHANGELOG.txt b/pyomo/contrib/pyros/CHANGELOG.txt index b1866ed955c..7977c37fb95 100644 --- a/pyomo/contrib/pyros/CHANGELOG.txt +++ b/pyomo/contrib/pyros/CHANGELOG.txt @@ -2,6 +2,18 @@ PyROS CHANGELOG =============== +------------------------------------------------------------------------------- +PyROS 1.2.8 12 Oct 2023 +------------------------------------------------------------------------------- +- Refactor PyROS separation routine, fix scenario selection heuristic +- Add efficiency for discrete uncertainty set separation +- Fix coefficient matching routine +- Fix subproblem timers and time accumulators +- Update and document PyROS solver logging system +- Fix iteration overcounting in event of `max_iter` termination status +- Fixes to (assembly of) PyROS `ROSolveResults` object + + ------------------------------------------------------------------------------- PyROS 1.2.7 26 Apr 2023 ------------------------------------------------------------------------------- diff --git a/pyomo/contrib/pyros/master_problem_methods.py b/pyomo/contrib/pyros/master_problem_methods.py index a0e2245cab1..dc4b6b957bb 100644 --- a/pyomo/contrib/pyros/master_problem_methods.py +++ b/pyomo/contrib/pyros/master_problem_methods.py @@ -22,7 +22,6 @@ adjust_solver_time_settings, revert_solver_max_time_adjustment, get_main_elapsed_time, - output_logger, ) from pyomo.contrib.pyros.solve_data import MasterProblemData, MasterResult from pyomo.opt.results import check_optimal_termination @@ -236,6 +235,13 @@ def solve_master_feasibility_problem(model_data, config): """ model = construct_master_feasibility_problem(model_data, config) + active_obj = next(model.component_data_objects(Objective, active=True)) + + config.progress_logger.debug("Solving master feasibility problem") + config.progress_logger.debug( + f" Initial objective (total slack): {value(active_obj)}" + ) + if config.solve_master_globally: solver = config.global_solver else: @@ -245,6 +251,7 @@ def solve_master_feasibility_problem(model_data, config): 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) @@ -253,13 +260,14 @@ def solve_master_feasibility_problem(model_data, config): # (such as segmentation faults, function evaluation # errors, etc.) config.progress_logger.error( - f"Solver {repr(solver)} encountered exception attempting to " - "optimize master feasibility problem in iteration " - f"{model_data.iteration}" + 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 @@ -273,6 +281,24 @@ def solve_master_feasibility_problem(model_data, config): } if results.solver.termination_condition in feasible_terminations: model.solutions.load_from(results) + config.progress_logger.debug( + f" Final objective (total slack): {value(active_obj)}" + ) + config.progress_logger.debug( + f" Termination condition: {results.solver.termination_condition}" + ) + config.progress_logger.debug( + f" Solve time: {getattr(results.solver, TIC_TOC_SOLVE_TIME_ATTR)}s" + ) + else: + config.progress_logger.warning( + "Could not successfully solve master feasibility problem " + f"of iteration {model_data.iteration} with primary subordinate " + f"{'global' if config.solve_master_globally else 'local'} solver " + "to acceptable level. " + f"Termination stats:\n{results.solver}\n" + "Maintaining unoptimized point for master problem initialization." + ) # load master feasibility point to master model for master_var, feas_var in model_data.feasibility_problem_varmap: @@ -298,6 +324,9 @@ def minimize_dr_vars(model_data, config): ------- results : SolverResults Subordinate solver results for the polishing problem. + polishing_successful : bool + True if polishing model was solved to acceptable level, + False otherwise. """ # config.progress_logger.info("Executing decision rule variable polishing solve.") model = model_data.master_model @@ -467,11 +496,21 @@ def minimize_dr_vars(model_data, config): else: solver = config.local_solver + config.progress_logger.debug("Solving DR polishing problem") + + # NOTE: this objective evalaution may not be accurate, due + # to the current initialization scheme for the auxiliary + # variables. new initialization will be implemented in the + # near future. + polishing_obj = polishing_model.scenarios[0, 0].polishing_obj + 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) @@ -484,16 +523,35 @@ def minimize_dr_vars(model_data, config): 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 + config.progress_logger.debug(" Done solving DR polishing problem") + config.progress_logger.debug( + f" Solve time: {getattr(results.solver, TIC_TOC_SOLVE_TIME_ATTR)} s" + ) + config.progress_logger.debug( + f" Termination status: {results.solver.termination_condition} " + ) + # === Process solution by termination condition acceptable = {tc.globallyOptimal, tc.optimal, tc.locallyOptimal, tc.feasible} if results.solver.termination_condition not in acceptable: # continue with "unpolished" master model solution - return results + config.progress_logger.warning( + "Could not successfully solve DR polishing problem " + f"of iteration {model_data.iteration} with primary subordinate " + f"{'global' if config.solve_master_globally else 'local'} solver " + "to acceptable level. " + f"Termination stats:\n{results.solver}\n" + "Maintaining unpolished master problem solution." + ) + return results, False # update master model second-stage, state, and decision rule # variables to polishing model solution @@ -520,7 +578,34 @@ def minimize_dr_vars(model_data, config): for mvar, pvar in zip(master_dr.values(), polish_dr.values()): mvar.set_value(value(pvar), skip_validation=True) - return results + config.progress_logger.debug(f" Optimized DR norm: {value(polishing_obj)}") + config.progress_logger.debug(" Polished Master objective:") + + # print master solution + if config.objective_focus == ObjectiveType.worst_case: + worst_blk_idx = max( + model_data.master_model.scenarios.keys(), + key=lambda idx: value( + model_data.master_model.scenarios[idx].second_stage_objective + ), + ) + else: + worst_blk_idx = (0, 0) + + # debugging: summarize objective breakdown + worst_master_blk = model_data.master_model.scenarios[worst_blk_idx] + config.progress_logger.debug( + " First-stage objective: " f"{value(worst_master_blk.first_stage_objective)}" + ) + config.progress_logger.debug( + " Second-stage objective: " f"{value(worst_master_blk.second_stage_objective)}" + ) + polished_master_obj = value( + worst_master_blk.first_stage_objective + worst_master_blk.second_stage_objective + ) + config.progress_logger.debug(f" Objective: {polished_master_obj}") + + return results, True def add_p_robust_constraint(model_data, config): @@ -628,18 +713,27 @@ def solver_call_master(model_data, config, solver, solve_data): solver_term_cond_dict = {} if config.solve_master_globally: - backup_solvers = deepcopy(config.backup_global_solvers) + solvers = [solver] + config.backup_global_solvers else: - backup_solvers = deepcopy(config.backup_local_solvers) - backup_solvers.insert(0, solver) + solvers = [solver] + config.backup_local_solvers higher_order_decision_rule_efficiency(config, model_data) + solve_mode = "global" if config.solve_master_globally else "local" + config.progress_logger.debug("Solving master problem") + timer = TicTocTimer() - for opt in backup_solvers: + 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( @@ -653,12 +747,14 @@ def solver_call_master(model_data, config, solver, solve_data): # (such as segmentation faults, function evaluation # errors, etc.) config.progress_logger.error( - f"Solver {repr(opt)} encountered exception attempting to " - f"optimize master problem in iteration {model_data.iteration}" + 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 @@ -715,6 +811,25 @@ def solver_call_master(model_data, config, solver, solve_data): nlp_model.scenarios[0, 0].first_stage_objective ) + # debugging: log breakdown of master objective + config.progress_logger.debug(" Optimized master objective breakdown:") + config.progress_logger.debug( + f" First-stage objective: {master_soln.first_stage_objective}" + ) + config.progress_logger.debug( + f" Second-stage objective: {master_soln.second_stage_objective}" + ) + master_obj = ( + master_soln.first_stage_objective + master_soln.second_stage_objective + ) + config.progress_logger.debug(f" Objective: {master_obj}") + config.progress_logger.debug( + f" Termination condition: {results.solver.termination_condition}" + ) + config.progress_logger.debug( + f" Solve time: {getattr(results.solver, TIC_TOC_SOLVE_TIME_ATTR)}s" + ) + master_soln.nominal_block = nlp_model.scenarios[0, 0] master_soln.results = results master_soln.master_model = nlp_model @@ -731,7 +846,6 @@ def solver_call_master(model_data, config, solver, solve_data): master_soln.pyros_termination_condition = ( pyrosTerminationCondition.time_out ) - output_logger(config=config, time_out=True, elapsed=elapsed) if not try_backup: return master_soln @@ -742,8 +856,9 @@ def solver_call_master(model_data, config, solver, solve_data): # NOTE: subproblem is written with variables set to their # initial values (not the final subsolver iterate) save_dir = config.subproblem_file_directory + serialization_msg = "" if save_dir and config.keepfiles: - name = os.path.join( + output_problem_path = os.path.join( save_dir, ( config.uncertainty_set.type @@ -754,15 +869,37 @@ def solver_call_master(model_data, config, solver, solve_data): + ".bar" ), ) - nlp_model.write(name, io_options={'symbolic_solver_labels': True}) - output_logger( - config=config, - master_error=True, - status_dict=solver_term_cond_dict, - filename=name, - iteration=model_data.iteration, + nlp_model.write( + output_problem_path, io_options={'symbolic_solver_labels': True} ) + serialization_msg = ( + " For debugging, problem has been serialized to the file " + f"{output_problem_path!r}." + ) + + deterministic_model_qual = ( + " (i.e., the deterministic model)" if model_data.iteration == 0 else "" + ) + deterministic_msg = ( + ( + " Please ensure your deterministic model " + f"is solvable by at least one of the subordinate {solve_mode} " + "optimizers provided." + ) + if model_data.iteration == 0 + else "" + ) master_soln.pyros_termination_condition = pyrosTerminationCondition.subsolver_error + config.progress_logger.warning( + f"Could not successfully solve master problem of iteration " + f"{model_data.iteration}{deterministic_model_qual} with any of the " + f"provided subordinate {solve_mode} optimizers. " + f"(Termination statuses: " + f"{[term_cond for term_cond in solver_term_cond_dict.values()]}.)" + f"{deterministic_msg}" + f"{serialization_msg}" + ) + return master_soln @@ -798,10 +935,6 @@ def solve_master(model_data, config): None, pyrosTerminationCondition.time_out, ) - - # log time out message - output_logger(config=config, time_out=True, elapsed=elapsed) - return master_soln solver = ( diff --git a/pyomo/contrib/pyros/pyros.py b/pyomo/contrib/pyros/pyros.py index 34db54b64e6..5b37b114722 100644 --- a/pyomo/contrib/pyros/pyros.py +++ b/pyomo/contrib/pyros/pyros.py @@ -37,15 +37,52 @@ transform_to_standard_form, turn_bounds_to_constraints, replace_uncertain_bounds_with_constraints, - output_logger, + IterationLogRecord, + setup_pyros_logger, + TimingData, ) from pyomo.contrib.pyros.solve_data import ROSolveResults from pyomo.contrib.pyros.pyros_algorithm_methods import ROSolver_iterative_solve from pyomo.contrib.pyros.uncertainty_sets import uncertainty_sets from pyomo.core.base import Constraint +from datetime import datetime -__version__ = "1.2.7" + +__version__ = "1.2.8" + + +default_pyros_solver_logger = setup_pyros_logger() + + +def _get_pyomo_version_info(): + """ + Get Pyomo version information. + """ + import os + import subprocess + from pyomo.version import version + + pyomo_version = version + commit_hash = "unknown" + + pyros_dir = os.path.join(*os.path.split(__file__)[:-1]) + commit_hash_command_args = [ + "git", + "-C", + f"{pyros_dir}", + "rev-parse", + "--short", + "HEAD", + ] + try: + commit_hash = ( + subprocess.check_output(commit_hash_command_args).decode("ascii").strip() + ) + except subprocess.CalledProcessError: + commit_hash = "unknown" + + return {"Pyomo version": pyomo_version, "Commit hash": commit_hash} def NonNegIntOrMinusOne(obj): @@ -485,13 +522,16 @@ def pyros_config(): CONFIG.declare( "progress_logger", PyROSConfigValue( - default="pyomo.contrib.pyros", + default=default_pyros_solver_logger, domain=a_logger, doc=( """ Logger (or name thereof) used for reporting PyROS solver - progress. If a `str` is specified, then - ``logging.getLogger(progress_logger)`` is used. + progress. If a `str` is specified, then ``progress_logger`` + is cast to ``logging.getLogger(progress_logger)``. + In the default case, `progress_logger` is set to + a :class:`pyomo.contrib.pyros.util.PreformattedLogger` + object of level ``logging.INFO``. """ ), is_optional=True, @@ -642,6 +682,7 @@ class PyROS(object): ''' CONFIG = pyros_config() + _LOG_LINE_LENGTH = 78 def available(self, exception_flag=True): """Check if solver is available.""" @@ -663,6 +704,138 @@ def __enter__(self): def __exit__(self, et, ev, tb): pass + def _log_intro(self, logger, **log_kwargs): + """ + Log PyROS solver introductory messages. + + Parameters + ---------- + logger : logging.Logger + Logger through which to emit messages. + **log_kwargs : dict, optional + Keyword arguments to ``logger.log()`` callable. + Should not include `msg`. + """ + logger.log(msg="=" * self._LOG_LINE_LENGTH, **log_kwargs) + logger.log( + msg=f"PyROS: The Pyomo Robust Optimization Solver, v{self.version()}.", + **log_kwargs, + ) + + # git_info_str = ", ".join( + # f"{field}: {val}" for field, val in _get_pyomo_git_info().items() + # ) + version_info = _get_pyomo_version_info() + version_info_str = ' ' * len("PyROS: ") + ("\n" + ' ' * len("PyROS: ")).join( + f"{key}: {val}" for key, val in version_info.items() + ) + logger.log(msg=version_info_str, **log_kwargs) + logger.log( + msg=( + f"{' ' * len('PyROS:')} " + f"Invoked at UTC {datetime.utcnow().isoformat()}" + ), + **log_kwargs, + ) + logger.log(msg="", **log_kwargs) + logger.log( + msg=("Developed by: Natalie M. Isenberg (1), Jason A. F. Sherman (1),"), + **log_kwargs, + ) + logger.log( + msg=( + f"{' ' * len('Developed by:')} " + "John D. Siirola (2), Chrysanthos E. Gounaris (1)" + ), + **log_kwargs, + ) + logger.log( + msg=( + "(1) Carnegie Mellon University, " "Department of Chemical Engineering" + ), + **log_kwargs, + ) + logger.log( + msg="(2) Sandia National Laboratories, Center for Computing Research", + **log_kwargs, + ) + logger.log(msg="", **log_kwargs) + logger.log( + msg=( + "The developers gratefully acknowledge support " + "from the U.S. Department" + ), + **log_kwargs, + ) + logger.log( + msg=( + "of Energy's " + "Institute for the Design of Advanced Energy Systems (IDAES)." + ), + **log_kwargs, + ) + logger.log(msg="=" * self._LOG_LINE_LENGTH, **log_kwargs) + + def _log_disclaimer(self, logger, **log_kwargs): + """ + Log PyROS solver disclaimer messages. + + Parameters + ---------- + logger : logging.Logger + Logger through which to emit messages. + **log_kwargs : dict, optional + Keyword arguments to ``logger.log()`` callable. + Should not include `msg`. + """ + disclaimer_header = " DISCLAIMER ".center(self._LOG_LINE_LENGTH, "=") + + logger.log(msg=disclaimer_header, **log_kwargs) + logger.log(msg="PyROS is still under development. ", **log_kwargs) + logger.log( + msg=( + "Please provide feedback and/or report any issues by creating " + "a ticket at" + ), + **log_kwargs, + ) + logger.log(msg="https://github.com/Pyomo/pyomo/issues/new/choose", **log_kwargs) + logger.log(msg="=" * self._LOG_LINE_LENGTH, **log_kwargs) + + def _log_config(self, logger, config, exclude_options=None, **log_kwargs): + """ + Log PyROS solver options. + + Parameters + ---------- + logger : logging.Logger + Logger for the solver options. + config : ConfigDict + PyROS solver options. + exclude_options : None or iterable of str, optional + Options (keys of the ConfigDict) to exclude from + logging. If `None` passed, then the names of the + required arguments to ``self.solve()`` are skipped. + **log_kwargs : dict, optional + Keyword arguments to each statement of ``logger.log()``. + """ + # log solver options + if exclude_options is None: + exclude_options = [ + "first_stage_variables", + "second_stage_variables", + "uncertain_params", + "uncertainty_set", + "local_solver", + "global_solver", + ] + + logger.log(msg="Solver options:", **log_kwargs) + for key, val in config.items(): + if key not in exclude_options: + logger.log(msg=f" {key}={val!r}", **log_kwargs) + logger.log(msg="-" * self._LOG_LINE_LENGTH, **log_kwargs) + def solve( self, model, @@ -742,15 +915,26 @@ def solve( model_data = ROSolveResults() model_data.timing = Bunch() - # === Set up logger for logging results - with time_code(model_data.timing, 'total', is_main_timer=True): - config.progress_logger.setLevel(logging.INFO) - - # === PREAMBLE - output_logger(config=config, preamble=True, version=str(self.version())) + # === 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) + self._log_config( + logger=config.progress_logger, + config=config, + exclude_options=None, + level=logging.INFO, + ) - # === DISCLAIMER - output_logger(config=config, disclaimer=True) + # begin preprocessing + config.progress_logger.info("Preprocessing...") + model_data.timing.start_timer("main.preprocessing") # === A block to hold list-type data to make cloning easy util = Block(concrete=True) @@ -783,6 +967,7 @@ def solve( ) assert len(active_objs) == 1 active_obj = active_objs[0] + active_obj_original_sense = active_obj.sense recast_to_min_obj(model_data.working_model, active_obj) # === Determine first and second-stage objectives @@ -831,10 +1016,18 @@ def solve( if "bound_con" in c.name: wm_util.ssv_bounds.append(c) + model_data.timing.stop_timer("main.preprocessing") + preprocessing_time = model_data.timing.get_total_time("main.preprocessing") + config.progress_logger.info( + f"Done preprocessing; required wall time of " + f"{preprocessing_time:.3f}s." + ) + # === Solve and load solution into model pyros_soln, final_iter_separation_solns = ROSolver_iterative_solve( model_data, config ) + IterationLogRecord.log_header_rule(config.progress_logger.info) return_soln = ROSolveResults() if pyros_soln is not None and final_iter_separation_solns is not None: @@ -846,31 +1039,24 @@ def solve( ): load_final_solution(model_data, pyros_soln.master_soln, config) - # === Return time info - model_data.total_cpu_time = get_main_elapsed_time(model_data.timing) - iterations = pyros_soln.total_iters + 1 - - # === Return config to user - return_soln.config = config - # Report the negative of the objective value if it was originally maximize, since we use the minimize form in the algorithm - if next(model.component_data_objects(Objective)).sense == maximize: - negation = -1 - else: - negation = 1 + # account for sense of the original model objective + # when reporting the final PyROS (master) objective, + # since maximization objective is changed to + # minimization objective during preprocessing if config.objective_focus == ObjectiveType.nominal: - return_soln.final_objective_value = negation * value( - pyros_soln.master_soln.master_model.obj + return_soln.final_objective_value = ( + active_obj_original_sense + * value(pyros_soln.master_soln.master_model.obj) ) elif config.objective_focus == ObjectiveType.worst_case: - return_soln.final_objective_value = negation * value( - pyros_soln.master_soln.master_model.zeta + return_soln.final_objective_value = ( + active_obj_original_sense + * value(pyros_soln.master_soln.master_model.zeta) ) return_soln.pyros_termination_condition = ( pyros_soln.pyros_termination_condition ) - - return_soln.time = model_data.total_cpu_time - return_soln.iterations = iterations + return_soln.iterations = pyros_soln.total_iters + 1 # === Remove util block model.del_component(model_data.util_block) @@ -878,12 +1064,25 @@ def solve( del pyros_soln.util_block del pyros_soln.working_model else: + return_soln.final_objective_value = None return_soln.pyros_termination_condition = ( pyrosTerminationCondition.robust_infeasible ) - return_soln.final_objective_value = None - return_soln.time = get_main_elapsed_time(model_data.timing) return_soln.iterations = 0 + + return_soln.config = config + return_soln.time = model_data.timing.get_total_time("main") + + # log termination-related messages + config.progress_logger.info(return_soln.pyros_termination_condition.message) + config.progress_logger.info("-" * self._LOG_LINE_LENGTH) + config.progress_logger.info(f"Timing breakdown:\n\n{model_data.timing}") + config.progress_logger.info("-" * self._LOG_LINE_LENGTH) + config.progress_logger.info(return_soln) + config.progress_logger.info("-" * self._LOG_LINE_LENGTH) + config.progress_logger.info("All done. Exiting PyROS.") + config.progress_logger.info("=" * self._LOG_LINE_LENGTH) + return return_soln diff --git a/pyomo/contrib/pyros/pyros_algorithm_methods.py b/pyomo/contrib/pyros/pyros_algorithm_methods.py index 7a0c990d549..df0d539a70d 100644 --- a/pyomo/contrib/pyros/pyros_algorithm_methods.py +++ b/pyomo/contrib/pyros/pyros_algorithm_methods.py @@ -11,14 +11,14 @@ ObjectiveType, get_time_from_solver, pyrosTerminationCondition, + IterationLogRecord, ) -from pyomo.contrib.pyros.util import ( - get_main_elapsed_time, - output_logger, - coefficient_matching, -) +from pyomo.contrib.pyros.util import get_main_elapsed_time, coefficient_matching from pyomo.core.base import value -from pyomo.common.collections import ComponentSet +from pyomo.common.collections import ComponentSet, ComponentMap +from pyomo.core.base.var import _VarData as VarData +from itertools import chain +from pyomo.common.dependencies import numpy as np def update_grcs_solve_data( @@ -47,6 +47,150 @@ def update_grcs_solve_data( return +def get_dr_var_to_scaled_expr_map( + decision_rule_eqns, second_stage_vars, uncertain_params, decision_rule_vars +): + """ + Generate mapping from decision rule variables + to their terms in a model's DR expression. + """ + var_to_scaled_expr_map = ComponentMap() + ssv_dr_eq_zip = zip(second_stage_vars, decision_rule_eqns) + for ssv_idx, (ssv, dr_eq) in enumerate(ssv_dr_eq_zip): + for term in dr_eq.body.args: + is_ssv_term = ( + isinstance(term.args[0], int) + and term.args[0] == -1 + and isinstance(term.args[1], VarData) + ) + if not is_ssv_term: + dr_var = term.args[1] + var_to_scaled_expr_map[dr_var] = term + + return var_to_scaled_expr_map + + +def evaluate_and_log_component_stats(model_data, separation_model, config): + """ + Evaluate and log model component statistics. + """ + IterationLogRecord.log_header_rule(config.progress_logger.info) + config.progress_logger.info("Model statistics:") + # print model statistics + dr_var_set = ComponentSet( + chain( + *tuple( + indexed_dr_var.values() + for indexed_dr_var in model_data.working_model.util.decision_rule_vars + ) + ) + ) + first_stage_vars = [ + var + for var in model_data.working_model.util.first_stage_variables + if var not in dr_var_set + ] + + # account for epigraph constraint + sep_model_epigraph_con = getattr(separation_model, "epigraph_constr", None) + has_epigraph_con = sep_model_epigraph_con is not None + + num_fsv = len(first_stage_vars) + num_ssv = len(model_data.working_model.util.second_stage_variables) + num_sv = len(model_data.working_model.util.state_vars) + num_dr_vars = len(dr_var_set) + num_vars = int(has_epigraph_con) + num_fsv + num_ssv + num_sv + num_dr_vars + + num_uncertain_params = len(model_data.working_model.util.uncertain_params) + + eq_cons = [ + con + for con in model_data.working_model.component_data_objects( + Constraint, active=True + ) + if con.equality + ] + dr_eq_set = ComponentSet( + chain( + *tuple( + indexed_dr_eq.values() + for indexed_dr_eq in model_data.working_model.util.decision_rule_eqns + ) + ) + ) + num_eq_cons = len(eq_cons) + num_dr_cons = len(dr_eq_set) + num_coefficient_matching_cons = len( + getattr(model_data.working_model, "coefficient_matching_constraints", []) + ) + num_other_eq_cons = num_eq_cons - num_dr_cons - num_coefficient_matching_cons + + # get performance constraints as referenced in the separation + # model object + new_sep_con_map = separation_model.util.map_new_constraint_list_to_original_con + perf_con_set = ComponentSet( + new_sep_con_map.get(con, con) + for con in separation_model.util.performance_constraints + ) + is_epigraph_con_first_stage = ( + has_epigraph_con and sep_model_epigraph_con not in perf_con_set + ) + working_model_perf_con_set = ComponentSet( + model_data.working_model.find_component(new_sep_con_map.get(con, con)) + for con in separation_model.util.performance_constraints + if con is not None + ) + + num_perf_cons = len(separation_model.util.performance_constraints) + num_fsv_bounds = sum( + int(var.lower is not None) + int(var.upper is not None) + for var in first_stage_vars + ) + ineq_con_set = [ + con + for con in model_data.working_model.component_data_objects( + Constraint, active=True + ) + if not con.equality + ] + num_fsv_ineqs = ( + num_fsv_bounds + + len([con for con in ineq_con_set if con not in working_model_perf_con_set]) + + is_epigraph_con_first_stage + ) + num_ineq_cons = len(ineq_con_set) + has_epigraph_con + num_fsv_bounds + + config.progress_logger.info(f"{' Number of variables'} : {num_vars}") + config.progress_logger.info(f"{' Epigraph variable'} : {int(has_epigraph_con)}") + config.progress_logger.info(f"{' First-stage variables'} : {num_fsv}") + config.progress_logger.info(f"{' Second-stage variables'} : {num_ssv}") + config.progress_logger.info(f"{' State variables'} : {num_sv}") + config.progress_logger.info(f"{' Decision rule variables'} : {num_dr_vars}") + config.progress_logger.info( + f"{' Number of uncertain parameters'} : {num_uncertain_params}" + ) + config.progress_logger.info( + f"{' Number of constraints'} : " f"{num_ineq_cons + num_eq_cons}" + ) + config.progress_logger.info(f"{' Equality constraints'} : {num_eq_cons}") + config.progress_logger.info( + f"{' Coefficient matching constraints'} : " + f"{num_coefficient_matching_cons}" + ) + config.progress_logger.info(f"{' Decision rule equations'} : {num_dr_cons}") + config.progress_logger.info( + f"{' All other equality constraints'} : " f"{num_other_eq_cons}" + ) + config.progress_logger.info(f"{' Inequality constraints'} : {num_ineq_cons}") + config.progress_logger.info( + f"{' First-stage inequalities (incl. certain var bounds)'} : " + f"{num_fsv_ineqs}" + ) + config.progress_logger.info( + f"{' Performance constraints (incl. var bounds)'} : {num_perf_cons}" + ) + + def ROSolver_iterative_solve(model_data, config): ''' GRCS algorithm implementation @@ -75,20 +219,23 @@ def ROSolver_iterative_solve(model_data, config): config=config, ) if not coeff_matching_success and not robust_infeasible: - raise ValueError( - "Equality constraint \"%s\" cannot be guaranteed to be robustly feasible, " - "given the current partitioning between first-stage, second-stage and state variables. " - "You might consider editing this constraint to reference some second-stage " - "and/or state variable(s)." % c.name + config.progress_logger.error( + f"Equality constraint {c.name!r} cannot be guaranteed to " + "be robustly feasible, given the current partitioning " + "among first-stage, second-stage, and state variables. " + "Consider editing this constraint to reference some " + "second-stage and/or state variable(s)." ) + raise ValueError("Coefficient matching unsuccessful. See the solver logs.") elif not coeff_matching_success and robust_infeasible: config.progress_logger.info( "PyROS has determined that the model is robust infeasible. " - "One reason for this is that equality constraint \"%s\" cannot be satisfied " - "against all realizations of uncertainty, " - "given the current partitioning between first-stage, second-stage and state variables. " - "You might consider editing this constraint to reference some (additional) second-stage " - "and/or state variable(s)." % c.name + f"One reason for this is that the equality constraint {c.name} " + "cannot be satisfied against all realizations of uncertainty, " + "given the current partitioning between " + "first-stage, second-stage, and state variables. " + "Consider editing this constraint to reference some (additional) " + "second-stage and/or state variable(s)." ) return None, None else: @@ -156,6 +303,10 @@ def ROSolver_iterative_solve(model_data, config): model_data=master_data, config=config ) + evaluate_and_log_component_stats( + model_data=model_data, separation_model=separation_model, config=config + ) + # === Create separation problem data container object and add information to catalog during solve separation_data = SeparationProblemData() separation_data.separation_model = separation_model @@ -204,6 +355,34 @@ def ROSolver_iterative_solve(model_data, config): dr_var_lists_original = [] dr_var_lists_polished = [] + # set up first-stage variable and DR variable sets + master_dr_var_set = ComponentSet( + chain( + *tuple( + indexed_var.values() + for indexed_var in master_data.master_model.scenarios[ + 0, 0 + ].util.decision_rule_vars + ) + ) + ) + master_fsv_set = ComponentSet( + var + for var in master_data.master_model.scenarios[0, 0].util.first_stage_variables + if var not in master_dr_var_set + ) + previous_master_fsv_vals = ComponentMap((var, None) for var in master_fsv_set) + previous_master_dr_var_vals = ComponentMap((var, None) for var in master_dr_var_set) + + nom_master_util_blk = master_data.master_model.scenarios[0, 0].util + dr_var_scaled_expr_map = get_dr_var_to_scaled_expr_map( + decision_rule_vars=nom_master_util_blk.decision_rule_vars, + decision_rule_eqns=nom_master_util_blk.decision_rule_eqns, + second_stage_vars=nom_master_util_blk.second_stage_variables, + uncertain_params=nom_master_util_blk.uncertain_params, + ) + + IterationLogRecord.log_header(config.progress_logger.info) k = 0 master_statuses = [] while config.max_iter == -1 or k < config.max_iter: @@ -216,7 +395,7 @@ def ROSolver_iterative_solve(model_data, config): ) # === Solve Master Problem - config.progress_logger.info("PyROS working on iteration %s..." % k) + config.progress_logger.debug(f"PyROS working on iteration {k}...") master_soln = master_problem_methods.solve_master( model_data=master_data, config=config ) @@ -239,7 +418,6 @@ def ROSolver_iterative_solve(model_data, config): is pyrosTerminationCondition.robust_infeasible ): term_cond = pyrosTerminationCondition.robust_infeasible - output_logger(config=config, robust_infeasible=True) elif ( master_soln.pyros_termination_condition is pyrosTerminationCondition.subsolver_error @@ -257,6 +435,19 @@ def ROSolver_iterative_solve(model_data, config): pyrosTerminationCondition.time_out, pyrosTerminationCondition.robust_infeasible, }: + log_record = IterationLogRecord( + iteration=k, + objective=None, + first_stage_var_shift=None, + dr_var_shift=None, + num_violated_cons=None, + max_violation=None, + dr_polishing_success=None, + all_sep_problems_solved=None, + global_separation=None, + elapsed_time=get_main_elapsed_time(model_data.timing), + ) + log_record.log(config.progress_logger.info) update_grcs_solve_data( pyros_soln=model_data, k=k, @@ -280,6 +471,7 @@ def ROSolver_iterative_solve(model_data, config): nominal_data.nom_second_stage_cost = master_soln.second_stage_objective nominal_data.nom_obj = value(master_data.master_model.obj) + polishing_successful = True if ( config.decision_rule_order != 0 and len(config.second_stage_variables) > 0 @@ -294,7 +486,10 @@ def ROSolver_iterative_solve(model_data, config): vals.append(dvar.value) dr_var_lists_original.append(vals) - polishing_results = master_problem_methods.minimize_dr_vars( + ( + polishing_results, + polishing_successful, + ) = master_problem_methods.minimize_dr_vars( model_data=master_data, config=config ) timing_data.total_dr_polish_time += get_time_from_solver(polishing_results) @@ -308,11 +503,55 @@ def ROSolver_iterative_solve(model_data, config): vals.append(dvar.value) dr_var_lists_polished.append(vals) - # === Check if time limit reached - elapsed = get_main_elapsed_time(model_data.timing) + # get current first-stage and DR variable values + # and compare with previous first-stage and DR variable + # values + current_master_fsv_vals = ComponentMap( + (var, value(var)) for var in master_fsv_set + ) + current_master_dr_var_vals = ComponentMap( + (var, value(var)) for var, expr in dr_var_scaled_expr_map.items() + ) + if k > 0: + first_stage_var_shift = ( + max( + abs(current_master_fsv_vals[var] - previous_master_fsv_vals[var]) + for var in previous_master_fsv_vals + ) + if current_master_fsv_vals + else None + ) + dr_var_shift = ( + max( + abs( + current_master_dr_var_vals[var] + - previous_master_dr_var_vals[var] + ) + for var in previous_master_dr_var_vals + ) + if current_master_dr_var_vals + else None + ) + else: + first_stage_var_shift = None + dr_var_shift = None + + # === Check if time limit reached after polishing if config.time_limit: + elapsed = get_main_elapsed_time(model_data.timing) if elapsed >= config.time_limit: - output_logger(config=config, time_out=True, elapsed=elapsed) + iter_log_record = IterationLogRecord( + iteration=k, + objective=value(master_data.master_model.obj), + first_stage_var_shift=first_stage_var_shift, + dr_var_shift=dr_var_shift, + num_violated_cons=None, + max_violation=None, + dr_polishing_success=polishing_successful, + all_sep_problems_solved=None, + global_separation=None, + elapsed_time=elapsed, + ) update_grcs_solve_data( pyros_soln=model_data, k=k, @@ -322,6 +561,7 @@ def ROSolver_iterative_solve(model_data, config): separation_data=separation_data, master_soln=master_soln, ) + iter_log_record.log(config.progress_logger.info) return model_data, [] # === Set up for the separation problem @@ -376,10 +616,39 @@ def ROSolver_iterative_solve(model_data, config): separation_results.violating_param_realization ) + scaled_violations = [ + solve_call_res.scaled_violations[con] + for con, solve_call_res in separation_results.main_loop_results.solver_call_results.items() + if solve_call_res.scaled_violations is not None + ] + if scaled_violations: + max_sep_con_violation = max(scaled_violations) + else: + max_sep_con_violation = None + num_violated_cons = len(separation_results.violated_performance_constraints) + + all_sep_problems_solved = ( + len(scaled_violations) == len(separation_model.util.performance_constraints) + and not separation_results.subsolver_error + and not separation_results.time_out + ) + + iter_log_record = IterationLogRecord( + iteration=k, + objective=value(master_data.master_model.obj), + first_stage_var_shift=first_stage_var_shift, + dr_var_shift=dr_var_shift, + num_violated_cons=num_violated_cons, + max_violation=max_sep_con_violation, + dr_polishing_success=polishing_successful, + all_sep_problems_solved=all_sep_problems_solved, + global_separation=separation_results.solved_globally, + elapsed_time=get_main_elapsed_time(model_data.timing), + ) + # terminate on time limit elapsed = get_main_elapsed_time(model_data.timing) if separation_results.time_out: - output_logger(config=config, time_out=True, elapsed=elapsed) termination_condition = pyrosTerminationCondition.time_out update_grcs_solve_data( pyros_soln=model_data, @@ -390,6 +659,7 @@ def ROSolver_iterative_solve(model_data, config): separation_data=separation_data, master_soln=master_soln, ) + iter_log_record.log(config.progress_logger.info) return model_data, separation_results # terminate on separation subsolver error @@ -404,24 +674,26 @@ def ROSolver_iterative_solve(model_data, config): separation_data=separation_data, master_soln=master_soln, ) + iter_log_record.log(config.progress_logger.info) return model_data, separation_results # === Check if we terminate due to robust optimality or feasibility, # or in the event of bypassing global separation, no violations robustness_certified = separation_results.robustness_certified if robustness_certified: - output_logger( - config=config, bypass_global_separation=config.bypass_global_separation - ) + if config.bypass_global_separation: + config.progress_logger.warning( + "Option to bypass global separation was chosen. " + "Robust feasibility and optimality of the reported " + "solution are not guaranteed." + ) robust_optimal = ( config.solve_master_globally and config.objective_focus is ObjectiveType.worst_case ) if robust_optimal: - output_logger(config=config, robust_optimal=True) termination_condition = pyrosTerminationCondition.robust_optimal else: - output_logger(config=config, robust_feasible=True) termination_condition = pyrosTerminationCondition.robust_feasible update_grcs_solve_data( pyros_soln=model_data, @@ -432,6 +704,7 @@ def ROSolver_iterative_solve(model_data, config): separation_data=separation_data, master_soln=master_soln, ) + iter_log_record.log(config.progress_logger.info) return model_data, separation_results # === Add block to master at violation @@ -443,13 +716,21 @@ def ROSolver_iterative_solve(model_data, config): separation_results.violating_param_realization ) + config.progress_logger.debug("Points added to master:") + config.progress_logger.debug( + np.array([pt for pt in separation_data.points_added_to_master]) + ) + k += 1 + iter_log_record.log(config.progress_logger.info) + previous_master_fsv_vals = current_master_fsv_vals + previous_master_dr_var_vals = current_master_dr_var_vals + # Iteration limit reached - output_logger(config=config, max_iter=True) update_grcs_solve_data( pyros_soln=model_data, - k=k, + k=k - 1, # remove last increment to fix iteration count term_cond=pyrosTerminationCondition.max_iter, nominal_data=nominal_data, timing_data=timing_data, diff --git a/pyomo/contrib/pyros/separation_problem_methods.py b/pyomo/contrib/pyros/separation_problem_methods.py index 2c41c869474..61f347b418d 100644 --- a/pyomo/contrib/pyros/separation_problem_methods.py +++ b/pyomo/contrib/pyros/separation_problem_methods.py @@ -6,7 +6,7 @@ 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, output_logger +from pyomo.contrib.pyros.util import ObjectiveType, get_time_from_solver from pyomo.contrib.pyros.solve_data import ( DiscreteSeparationSolveCallResults, SeparationSolveCallResults, @@ -536,6 +536,54 @@ def get_worst_discrete_separation_solution( ) +def get_con_name_repr(separation_model, con, with_orig_name=True, with_obj_name=True): + """ + Get string representation of performance constraint + and any other modeling components to which it has + been mapped. + + Parameters + ---------- + separation_model : ConcreteModel + Separation model. + con : ScalarConstraint or ConstraintData + Constraint for which to get the representation. + with_orig_name : bool, optional + If constraint was added during construction of the + separation problem (i.e. if the constraint is a member of + in `separation_model.util.new_constraints`), + include the name of the original constraint from which + `perf_con` was created. + with_obj_name : bool, optional + Include name of separation model objective to which + constraint is mapped. Applicable only to performance + constraints of the separation problem. + + Returns + ------- + str + Constraint name representation. + """ + + qual_strs = [] + if with_orig_name: + # check performance constraint was not added + # at construction of separation problem + orig_con = separation_model.util.map_new_constraint_list_to_original_con.get( + con, con + ) + if orig_con is not con: + qual_strs.append(f"originally {orig_con.name!r}") + if with_obj_name: + objectives_map = separation_model.util.map_obj_to_constr + separation_obj = objectives_map[con] + qual_strs.append(f"mapped to objective {separation_obj.name!r}") + + final_qual_str = f" ({', '.join(qual_strs)})" if qual_strs else "" + + return f"{con.name!r}{final_qual_str}" + + def perform_separation_loop(model_data, config, solve_globally): """ Loop through, and solve, PyROS separation problems to @@ -633,12 +681,22 @@ def perform_separation_loop(model_data, config, solve_globally): ) all_solve_call_results = ComponentMap() - for priority, perf_constraints in sorted_priority_groups.items(): + priority_groups_enum = enumerate(sorted_priority_groups.items()) + for group_idx, (priority, perf_constraints) in priority_groups_enum: priority_group_solve_call_results = ComponentMap() - for perf_con in perf_constraints: - # config.progress_logger.info( - # f"Separating constraint {perf_con.name}" - # ) + for idx, perf_con in enumerate(perf_constraints): + # log progress of separation loop + solve_adverb = "Globally" if solve_globally else "Locally" + config.progress_logger.debug( + f"{solve_adverb} separating performance constraint " + f"{get_con_name_repr(model_data.separation_model, perf_con)} " + f"(priority {priority}, priority group {group_idx + 1} of " + f"{len(sorted_priority_groups)}, " + f"constraint {idx + 1} of {len(perf_constraints)} " + "in priority group, " + f"{len(all_solve_call_results) + idx + 1} of " + f"{len(all_performance_constraints)} total)" + ) # solve separation problem for this performance constraint if uncertainty_set_is_discrete: @@ -689,21 +747,33 @@ def perform_separation_loop(model_data, config, solve_globally): ) # # auxiliary log messages - # objectives_map = ( - # model_data.separation_model.util.map_obj_to_constr - # ) - # violated_con_name = list(objectives_map.keys())[ - # worst_case_perf_con - # ] - # config.progress_logger.info( - # f"Violation found for constraint {violated_con_name} " - # "under realization " - # f"{worst_case_res.violating_param_realization}" - # ) + violated_con_names = "\n ".join( + get_con_name_repr(model_data.separation_model, con) + for con, res in all_solve_call_results.items() + if res.found_violation + ) + config.progress_logger.debug( + f"Violated constraints:\n {violated_con_names} " + ) + config.progress_logger.debug( + "Worst-case constraint: " + f"{get_con_name_repr(model_data.separation_model, worst_case_perf_con)} " + "under realization " + f"{worst_case_res.violating_param_realization}." + ) + config.progress_logger.debug( + f"Maximal scaled violation " + f"{worst_case_res.scaled_violations[worst_case_perf_con]} " + "from this constraint " + "exceeds the robust feasibility tolerance " + f"{config.robust_feasibility_tolerance}" + ) # violating separation problem solution now chosen. # exit loop break + else: + config.progress_logger.debug("No violated performance constraints found.") return SeparationLoopResults( solver_call_results=all_solve_call_results, @@ -786,7 +856,7 @@ def evaluate_performance_constraint_violations( return (violating_param_realization, scaled_violations, constraint_violated) -def initialize_separation(model_data, config): +def initialize_separation(perf_con_to_maximize, model_data, config): """ Initialize separation problem variables, and fix all first-stage variables to their corresponding values from most recent @@ -794,6 +864,9 @@ def initialize_separation(model_data, config): Parameters ---------- + perf_con_to_maximize : ConstraintData + Performance constraint whose violation is to be maximized + for the separation problem of interest. model_data : SeparationProblemData Separation problem data. config : ConfigDict @@ -875,13 +948,34 @@ def get_parent_master_blk(var): "All h(x,q) type constraints must be deactivated in separation." ) - # check: initial point feasible? + # confirm the initial point is feasible for cases where + # we expect it to be (i.e. non-discrete uncertainty sets). + # otherwise, log the violated constraints + tol = ABS_CON_CHECK_FEAS_TOL + perf_con_name_repr = get_con_name_repr( + separation_model=model_data.separation_model, + con=perf_con_to_maximize, + with_orig_name=True, + with_obj_name=True, + ) + uncertainty_set_is_discrete = ( + config.uncertainty_set.geometry is Geometry.DISCRETE_SCENARIOS + ) for con in sep_model.component_data_objects(Constraint, active=True): - lb, val, ub = value(con.lb), value(con.body), value(con.ub) - lb_viol = val < lb - ABS_CON_CHECK_FEAS_TOL if lb is not None else False - ub_viol = val > ub + ABS_CON_CHECK_FEAS_TOL if ub is not None else False - if lb_viol or ub_viol: - config.progress_logger.debug(con.name, lb, val, ub) + lslack, uslack = con.lslack(), con.uslack() + if (lslack < -tol or uslack < -tol) and not uncertainty_set_is_discrete: + con_name_repr = get_con_name_repr( + separation_model=model_data.separation_model, + con=con, + with_orig_name=True, + with_obj_name=False, + ) + config.progress_logger.debug( + f"Initial point for separation of performance constraint " + f"{perf_con_name_repr} violates the model constraint " + f"{con_name_repr} by more than {tol}. " + f"(lslack={con.lslack()}, uslack={con.uslack()})" + ) locally_acceptable = {tc.optimal, tc.locallyOptimal, tc.globallyOptimal} @@ -929,8 +1023,17 @@ def solver_call_separation( solver_status_dict = {} nlp_model = model_data.separation_model + # get name of constraint for loggers + con_name_repr = get_con_name_repr( + separation_model=nlp_model, + con=perf_con_to_maximize, + with_orig_name=True, + with_obj_name=True, + ) + solve_mode = "global" if solve_globally else "local" + # === Initialize separation problem; fix first-stage variables - initialize_separation(model_data, config) + initialize_separation(perf_con_to_maximize, model_data, config) separation_obj.activate() @@ -942,10 +1045,18 @@ def solver_call_separation( subsolver_error=False, ) timer = TicTocTimer() - for opt in solvers: + 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 {solve_mode} " + 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( @@ -958,14 +1069,17 @@ def solver_call_separation( # 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( - f"Solver {repr(opt)} encountered exception attempting to " - "optimize separation problem in iteration " - f"{model_data.iteration}" + f"Optimizer {repr(opt)} ({idx + 1} of {len(solvers)}) " + f"encountered exception attempting " + f"to {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 @@ -1014,15 +1128,25 @@ def solver_call_separation( separation_obj.deactivate() return solve_call_results + else: + config.progress_logger.debug( + f"Solver {opt} ({idx + 1} of {len(solvers)}) " + f"failed for {solve_mode} separation of performance " + f"constraint {con_name_repr} in iteration " + f"{model_data.iteration}. Termination condition: " + f"{results.solver.termination_condition!r}." + ) + config.progress_logger.debug(f"Results:\n{results.solver}") # All subordinate solvers failed to optimize model to appropriate # termination condition. PyROS will terminate with subsolver # error. At this point, export model if desired solve_call_results.subsolver_error = True save_dir = config.subproblem_file_directory + serialization_msg = "" if save_dir and config.keepfiles: objective = separation_obj.name - name = os.path.join( + output_problem_path = os.path.join( save_dir, ( config.uncertainty_set.type @@ -1035,15 +1159,23 @@ def solver_call_separation( + ".bar" ), ) - nlp_model.write(name, io_options={'symbolic_solver_labels': True}) - output_logger( - config=config, - separation_error=True, - filename=name, - iteration=model_data.iteration, - objective=objective, - status_dict=solver_status_dict, + nlp_model.write( + output_problem_path, io_options={'symbolic_solver_labels': True} ) + serialization_msg = ( + " For debugging, problem has been serialized to the file " + f"{output_problem_path!r}." + ) + solve_call_results.message = ( + "Could not successfully solve separation problem of iteration " + f"{model_data.iteration} " + f"for performance constraint {con_name_repr} with any of the " + f"provided subordinate {solve_mode} optimizers. " + f"(Termination statuses: " + f"{[str(term_cond) for term_cond in solver_status_dict.values()]}.)" + f"{serialization_msg}" + ) + config.progress_logger.warning(solve_call_results.message) separation_obj.deactivate() diff --git a/pyomo/contrib/pyros/solve_data.py b/pyomo/contrib/pyros/solve_data.py index 63e7fdd7ebd..40a52757bae 100644 --- a/pyomo/contrib/pyros/solve_data.py +++ b/pyomo/contrib/pyros/solve_data.py @@ -5,17 +5,71 @@ class ROSolveResults(object): """ - Container for solve-instance data returned to the user after solving with PyROS. + PyROS solver results object. - Attributes: - :pyros_termination_condition: termination condition of the PyROS algorithm - :config: the config block for this solve instance - :time: Total solver CPU time - :iterations: total iterations done by PyROS solver - :final_objective_value: objective function value at termination + Parameters + ---------- + config : ConfigDict, optional + User-specified solver settings. + iterations : int, optional + Number of iterations required. + time : float, optional + Total elapsed time (or wall time), in seconds. + final_objective_value : float, optional + Final objective function value to report. + pyros_termination_condition : pyrosTerminationCondition, optional + PyROS-specific termination condition. + + Attributes + ---------- + config : ConfigDict, optional + User-specified solver settings. + iterations : int, optional + Number of iterations required by PyROS. + time : float, optional + Total elapsed time (or wall time), in seconds. + final_objective_value : float, optional + Final objective function value to report. + pyros_termination_condition : pyros.util.pyrosTerminationStatus + Indicator of the manner of termination. """ - pass + def __init__( + self, + config=None, + iterations=None, + time=None, + final_objective_value=None, + pyros_termination_condition=None, + ): + """Initialize self (see class docstring).""" + self.config = config + self.iterations = iterations + self.time = time + self.final_objective_value = final_objective_value + self.pyros_termination_condition = pyros_termination_condition + + def __str__(self): + """ + Generate string representation of self. + Does not include any information about `self.config`. + """ + lines = ["Termination stats:"] + attr_name_format_dict = { + "iterations": ("Iterations", "f'{val}'"), + "time": ("Solve time (wall s)", "f'{val:.3f}'"), + "final_objective_value": ("Final objective value", "f'{val:.4e}'"), + "pyros_termination_condition": ("Termination condition", "f'{val}'"), + } + attr_desc_pad_length = max( + len(desc) for desc, _ in attr_name_format_dict.values() + ) + for attr_name, (attr_desc, fmt_str) in attr_name_format_dict.items(): + val = getattr(self, attr_name) + val_str = eval(fmt_str) if val is not None else str(val) + lines.append(f" {attr_desc:<{attr_desc_pad_length}s} : {val_str}") + + return "\n".join(lines) class MasterProblemData(object): @@ -443,6 +497,7 @@ class SeparationResults: ---------- local_separation_loop_results global_separation_loop_results + main_loop_results subsolver_error time_out solved_locally @@ -462,7 +517,7 @@ def __init__(self, local_separation_loop_results, global_separation_loop_results @property def time_out(self): """ - Return True if time out found for local or global + bool : True if time out found for local or global separation loop, False otherwise. """ local_time_out = ( @@ -476,7 +531,7 @@ def time_out(self): @property def subsolver_error(self): """ - Return True if subsolver error found for local or global + bool : True if subsolver error found for local or global separation loop, False otherwise. """ local_subsolver_error = ( @@ -490,7 +545,7 @@ def subsolver_error(self): @property def solved_locally(self): """ - Return true if local separation loop was invoked, + bool : true if local separation loop was invoked, False otherwise. """ return self.local_separation_loop_results is not None @@ -498,13 +553,18 @@ def solved_locally(self): @property def solved_globally(self): """ - Return True if global separation loop was invoked, + bool : True if global separation loop was invoked, False otherwise. """ return self.global_separation_loop_results is not None def get_violating_attr(self, attr_name): """ + If separation problems solved globally, returns + value of attribute of global separation loop results. + + Otherwise, if separation problems solved locally, + returns value of attribute of local separation loop results. If local separation loop results specified, return value of attribute of local separation loop results. @@ -526,27 +586,33 @@ def get_violating_attr(self, attr_name): object Attribute value. """ - if self.solved_locally: - local_loop_val = getattr(self.local_separation_loop_results, attr_name) - else: - local_loop_val = None + return getattr(self.main_loop_results, attr_name, None) - if local_loop_val is not None: - attr_val = local_loop_val - else: - if self.solved_globally: - attr_val = getattr(self.global_separation_loop_results, attr_name) - else: - attr_val = None + @property + def worst_case_perf_con(self): + """ + ConstraintData : Performance constraint corresponding to the + separation solution chosen for the next master problem. + """ + return self.get_violating_attr("worst_case_perf_con") - return attr_val + @property + def main_loop_results(self): + """ + SeparationLoopResults : Main separation loop results. + In particular, this is considered to be the global + loop result if solved globally, and the local loop + results otherwise. + """ + if self.solved_globally: + return self.global_separation_loop_results + return self.local_separation_loop_results @property def found_violation(self): """ - bool: True if ``found_violation`` attribute for - local or global separation loop results found - to be True, False otherwise. + bool : True if ``found_violation`` attribute for + main separation loop results is True, False otherwise. """ found_viol = self.get_violating_attr("found_violation") if found_viol is None: diff --git a/pyomo/contrib/pyros/tests/test_grcs.py b/pyomo/contrib/pyros/tests/test_grcs.py index 0d24b799b99..2be73826f61 100644 --- a/pyomo/contrib/pyros/tests/test_grcs.py +++ b/pyomo/contrib/pyros/tests/test_grcs.py @@ -19,6 +19,8 @@ ObjectiveType, pyrosTerminationCondition, coefficient_matching, + TimingData, + IterationLogRecord, ) from pyomo.contrib.pyros.util import replace_uncertain_bounds_with_constraints from pyomo.contrib.pyros.util import get_vars_from_component @@ -33,7 +35,7 @@ solve_master, minimize_dr_vars, ) -from pyomo.contrib.pyros.solve_data import MasterProblemData +from pyomo.contrib.pyros.solve_data import MasterProblemData, ROSolveResults from pyomo.common.dependencies import numpy as np, numpy_available from pyomo.common.dependencies import scipy as sp, scipy_available from pyomo.environ import maximize as pyo_max @@ -59,6 +61,10 @@ sqrt, value, ) +import logging + + +logger = logging.getLogger(__name__) if not (numpy_available and scipy_available): @@ -3567,7 +3573,7 @@ def test_solve_master(self): expr=master_data.master_model.scenarios[0, 0].x ) master_data.iteration = 0 - master_data.timing = Bunch() + master_data.timing = TimingData() box_set = BoxSet(bounds=[(0, 2)]) solver = SolverFactory(global_solver) @@ -3589,8 +3595,11 @@ def test_solve_master(self): ) config.declare("subproblem_file_directory", ConfigValue(default=None)) config.declare("time_limit", ConfigValue(default=None)) + config.declare( + "progress_logger", ConfigValue(default=logging.getLogger(__name__)) + ) - with time_code(master_data.timing, "total", is_main_timer=True): + with time_code(master_data.timing, "main", is_main_timer=True): master_soln = solve_master(master_data, config) self.assertEqual( master_soln.termination_condition, @@ -3866,7 +3875,7 @@ def test_minimize_dr_norm(self): m.working_model.util.state_vars = [] m.working_model.util.first_stage_variables = [] - config = Block() + config = Bunch() config.decision_rule_order = 1 config.objective_focus = ObjectiveType.nominal config.global_solver = SolverFactory('baron') @@ -3874,6 +3883,7 @@ def test_minimize_dr_norm(self): config.tee = False config.solve_master_globally = True config.time_limit = None + config.progress_logger = logging.getLogger(__name__) add_decision_rule_variables(model_data=m, config=config) add_decision_rule_constraints(model_data=m, config=config) @@ -3892,15 +3902,19 @@ def test_minimize_dr_norm(self): master_data.master_model = master master_data.master_model.const_efficiency_applied = False master_data.master_model.linear_efficiency_applied = False + master_data.iteration = 0 - master_data.timing = Bunch() - with time_code(master_data.timing, "total", is_main_timer=True): - results = minimize_dr_vars(model_data=master_data, config=config) + master_data.timing = TimingData() + with time_code(master_data.timing, "main", is_main_timer=True): + results, success = minimize_dr_vars(model_data=master_data, config=config) self.assertEqual( results.solver.termination_condition, TerminationCondition.optimal, msg="Minimize dr norm did not solve to optimality.", ) + self.assertTrue( + success, msg=f"DR polishing success {success}, expected True." + ) @unittest.skipUnless( baron_license_is_valid, "Global NLP solver is not available and licensed." @@ -3957,7 +3971,8 @@ def test_identifying_violating_param_realization(self): baron_license_is_valid, "Global NLP solver is not available and licensed." ) @unittest.skipUnless( - baron_version < (23, 1, 5), "Test known to fail beginning with Baron 23.1.5" + baron_version < (23, 1, 5) or baron_version >= (23, 6, 23), + "Test known to fail for BARON 23.1.5 and versions preceding 23.6.23", ) def test_terminate_with_max_iter(self): m = ConcreteModel() @@ -4004,6 +4019,15 @@ def test_terminate_with_max_iter(self): msg="Returned termination condition is not return max_iter.", ) + self.assertEqual( + results.iterations, + 1, + msg=( + f"Number of iterations in results object is {results.iterations}, " + f"but expected value 1." + ), + ) + @unittest.skipUnless( baron_license_is_valid, "Global NLP solver is not available and licensed." ) @@ -4864,14 +4888,16 @@ def test_coefficient_matching_raises_error_4_3(self): # solve with PyROS dr_orders = [1, 2] for dr_order in dr_orders: - with self.assertRaisesRegex( + regex_assert_mgr = self.assertRaisesRegex( ValueError, expected_regex=( - "Equality constraint.*cannot be guaranteed to be robustly " - "feasible.*" + "Coefficient matching unsuccessful. See the solver logs." ), - ): - res = pyros_solver.solve( + ) + logging_intercept_mgr = LoggingIntercept(level=logging.ERROR) + + with regex_assert_mgr, logging_intercept_mgr as LOG: + pyros_solver.solve( model=m, first_stage_variables=[], second_stage_variables=[m.x1, m.x2, m.x3], @@ -4886,6 +4912,16 @@ def test_coefficient_matching_raises_error_4_3(self): robust_feasibility_tolerance=1e-4, ) + detailed_error_msg = LOG.getvalue() + self.assertRegex( + detailed_error_msg[:-1], + ( + r"Equality constraint.*cannot be guaranteed to " + r"be robustly feasible.*" + r"Consider editing this constraint.*" + ), + ) + def test_coefficient_matching_robust_infeasible_proof_in_pyros(self): # Write the deterministic Pyomo model m = ConcreteModel() @@ -5011,28 +5047,42 @@ def test_bypass_global_separation(self): global_subsolver = SolverFactory("baron") # Call the PyROS solver - results = pyros_solver.solve( - model=m, - first_stage_variables=[m.x1], - second_stage_variables=[m.x2], - uncertain_params=[m.u], - uncertainty_set=interval, - local_solver=local_subsolver, - global_solver=global_subsolver, - options={ - "objective_focus": ObjectiveType.worst_case, - "solve_master_globally": True, - "decision_rule_order": 0, - "bypass_global_separation": True, - }, - ) + with LoggingIntercept(level=logging.WARNING) as LOG: + results = pyros_solver.solve( + model=m, + first_stage_variables=[m.x1], + second_stage_variables=[m.x2], + uncertain_params=[m.u], + uncertainty_set=interval, + local_solver=local_subsolver, + global_solver=global_subsolver, + options={ + "objective_focus": ObjectiveType.worst_case, + "solve_master_globally": True, + "decision_rule_order": 0, + "bypass_global_separation": True, + }, + ) + # check termination robust optimal self.assertEqual( results.pyros_termination_condition, pyrosTerminationCondition.robust_optimal, msg="Returned termination condition is not return robust_optimal.", ) + # since robust optimal, we also expect warning-level logger + # message about bypassing of global separation subproblems + warning_msgs = LOG.getvalue() + self.assertRegex( + warning_msgs, + ( + r".*Option to bypass global separation was chosen\. " + r"Robust feasibility and optimality of the reported " + r"solution are not guaranteed\." + ), + ) + @unittest.skipUnless( baron_available and baron_license_is_valid, @@ -5199,12 +5249,26 @@ def test_multiple_objs(self): # and solve again m.obj_max = Objective(expr=-m.obj.expr, sense=pyo_max) m.obj.deactivate() - res = pyros_solver.solve(**solve_kwargs) + max_obj_res = pyros_solver.solve(**solve_kwargs) # check active objectives self.assertEqual(len(list(m.component_data_objects(Objective, active=True))), 1) self.assertTrue(m.obj_max.active) + self.assertTrue( + math.isclose( + res.final_objective_value, + -max_obj_res.final_objective_value, + abs_tol=2e-4, # 2x the default robust feasibility tolerance + ), + msg=( + f"Robust optimal objective value {res.final_objective_value} " + "for problem with minimization objective not close to " + f"negative of value {max_obj_res.final_objective_value} " + "of equivalent maximization objective." + ), + ) + class testModelIdentifyObjectives(unittest.TestCase): """ @@ -5631,5 +5695,420 @@ def test_two_stg_mod_with_intersection_set(self): ) +class TestIterationLogRecord(unittest.TestCase): + """ + Test the PyROS `IterationLogRecord` class. + """ + + def test_log_header(self): + """Test method for logging iteration log table header.""" + ans = ( + "------------------------------------------------------------------------------\n" + "Itn Objective 1-Stg Shift DR Shift #CViol Max Viol Wall Time (s)\n" + "------------------------------------------------------------------------------\n" + ) + with LoggingIntercept(level=logging.INFO) as LOG: + IterationLogRecord.log_header(logger.info) + + self.assertEqual( + LOG.getvalue(), + ans, + msg="Messages logged for iteration table header do not match expected result", + ) + + def test_log_standard_iter_record(self): + """Test logging function for PyROS IterationLogRecord.""" + + # for some fields, we choose floats with more than four + # four decimal points to ensure rounding also matches + iter_record = IterationLogRecord( + iteration=4, + objective=1.234567, + first_stage_var_shift=2.3456789e-8, + dr_var_shift=3.456789e-7, + num_violated_cons=10, + max_violation=7.654321e-3, + elapsed_time=21.2, + dr_polishing_success=True, + all_sep_problems_solved=True, + global_separation=False, + ) + + # now check record logged as expected + ans = ( + "4 1.2346e+00 2.3457e-08 3.4568e-07 10 7.6543e-03 " + "21.200 \n" + ) + with LoggingIntercept(level=logging.INFO) as LOG: + iter_record.log(logger.info) + result = LOG.getvalue() + + self.assertEqual( + ans, + result, + msg="Iteration log record message does not match expected result", + ) + + def test_log_iter_record_polishing_failed(self): + """Test iteration log record in event of polishing failure.""" + # for some fields, we choose floats with more than four + # four decimal points to ensure rounding also matches + iter_record = IterationLogRecord( + iteration=4, + objective=1.234567, + first_stage_var_shift=2.3456789e-8, + dr_var_shift=3.456789e-7, + num_violated_cons=10, + max_violation=7.654321e-3, + elapsed_time=21.2, + dr_polishing_success=False, + all_sep_problems_solved=True, + global_separation=False, + ) + + # now check record logged as expected + ans = ( + "4 1.2346e+00 2.3457e-08 3.4568e-07* 10 7.6543e-03 " + "21.200 \n" + ) + with LoggingIntercept(level=logging.INFO) as LOG: + iter_record.log(logger.info) + result = LOG.getvalue() + + self.assertEqual( + ans, + result, + msg="Iteration log record message does not match expected result", + ) + + def test_log_iter_record_global_separation(self): + """ + Test iteration log record in event global separation performed. + In this case, a 'g' should be appended to the max violation + reported. Useful in the event neither local nor global separation + was bypassed. + """ + # for some fields, we choose floats with more than four + # four decimal points to ensure rounding also matches + iter_record = IterationLogRecord( + iteration=4, + objective=1.234567, + first_stage_var_shift=2.3456789e-8, + dr_var_shift=3.456789e-7, + num_violated_cons=10, + max_violation=7.654321e-3, + elapsed_time=21.2, + dr_polishing_success=True, + all_sep_problems_solved=True, + global_separation=True, + ) + + # now check record logged as expected + ans = ( + "4 1.2346e+00 2.3457e-08 3.4568e-07 10 7.6543e-03g " + "21.200 \n" + ) + with LoggingIntercept(level=logging.INFO) as LOG: + iter_record.log(logger.info) + result = LOG.getvalue() + + self.assertEqual( + ans, + result, + msg="Iteration log record message does not match expected result", + ) + + def test_log_iter_record_not_all_sep_solved(self): + """ + Test iteration log record in event not all separation problems + were solved successfully. This may have occurred if the PyROS + solver time limit was reached, or the user-provides subordinate + optimizer(s) were unable to solve a separation subproblem + to an acceptable level. + A '+' should be appended to the number of performance constraints + found to be violated. + """ + # for some fields, we choose floats with more than four + # four decimal points to ensure rounding also matches + iter_record = IterationLogRecord( + iteration=4, + objective=1.234567, + first_stage_var_shift=2.3456789e-8, + dr_var_shift=3.456789e-7, + num_violated_cons=10, + max_violation=7.654321e-3, + elapsed_time=21.2, + dr_polishing_success=True, + all_sep_problems_solved=False, + global_separation=False, + ) + + # now check record logged as expected + ans = ( + "4 1.2346e+00 2.3457e-08 3.4568e-07 10+ 7.6543e-03 " + "21.200 \n" + ) + with LoggingIntercept(level=logging.INFO) as LOG: + iter_record.log(logger.info) + result = LOG.getvalue() + + self.assertEqual( + ans, + result, + msg="Iteration log record message does not match expected result", + ) + + def test_log_iter_record_all_special(self): + """ + Test iteration log record in event DR polishing and global + separation failed. + """ + # for some fields, we choose floats with more than four + # four decimal points to ensure rounding also matches + iter_record = IterationLogRecord( + iteration=4, + objective=1.234567, + first_stage_var_shift=2.3456789e-8, + dr_var_shift=3.456789e-7, + num_violated_cons=10, + max_violation=7.654321e-3, + elapsed_time=21.2, + dr_polishing_success=False, + all_sep_problems_solved=False, + global_separation=True, + ) + + # now check record logged as expected + ans = ( + "4 1.2346e+00 2.3457e-08 3.4568e-07* 10+ 7.6543e-03g " + "21.200 \n" + ) + with LoggingIntercept(level=logging.INFO) as LOG: + iter_record.log(logger.info) + result = LOG.getvalue() + + self.assertEqual( + ans, + result, + msg="Iteration log record message does not match expected result", + ) + + def test_log_iter_record_attrs_none(self): + """ + Test logging of iteration record in event some + attributes are of value `None`. In this case, a '-' + should be printed in lieu of a numerical value. + Example where this occurs: the first iteration, + in which there is no first-stage shift or DR shift. + """ + # for some fields, we choose floats with more than four + # four decimal points to ensure rounding also matches + iter_record = IterationLogRecord( + iteration=0, + objective=-1.234567, + first_stage_var_shift=None, + dr_var_shift=None, + num_violated_cons=10, + max_violation=7.654321e-3, + elapsed_time=21.2, + dr_polishing_success=True, + all_sep_problems_solved=False, + global_separation=True, + ) + + # now check record logged as expected + ans = ( + "0 -1.2346e+00 - - 10+ 7.6543e-03g " + "21.200 \n" + ) + with LoggingIntercept(level=logging.INFO) as LOG: + iter_record.log(logger.info) + result = LOG.getvalue() + + self.assertEqual( + ans, + result, + msg="Iteration log record message does not match expected result", + ) + + +class TestROSolveResults(unittest.TestCase): + """ + Test PyROS solver results object. + """ + + def test_ro_solve_results_str(self): + """ + Test string representation of RO solve results object. + """ + res = ROSolveResults( + config=SolverFactory("pyros").CONFIG(), + iterations=4, + final_objective_value=123.456789, + time=300.34567, + pyros_termination_condition=pyrosTerminationCondition.robust_optimal, + ) + ans = ( + "Termination stats:\n" + " Iterations : 4\n" + " Solve time (wall s) : 300.346\n" + " Final objective value : 1.2346e+02\n" + " Termination condition : pyrosTerminationCondition.robust_optimal" + ) + self.assertEqual( + str(res), + ans, + msg=( + "String representation of PyROS results object does not " + "match expected value" + ), + ) + + def test_ro_solve_results_str_attrs_none(self): + """ + Test string representation of PyROS solve results in event + one of the printed attributes is of value `None`. + This may occur at instantiation or, for example, + whenever the PyROS solver confirms robust infeasibility through + coefficient matching. + """ + res = ROSolveResults( + config=SolverFactory("pyros").CONFIG(), + iterations=0, + final_objective_value=None, + time=300.34567, + pyros_termination_condition=pyrosTerminationCondition.robust_optimal, + ) + ans = ( + "Termination stats:\n" + " Iterations : 0\n" + " Solve time (wall s) : 300.346\n" + " Final objective value : None\n" + " Termination condition : pyrosTerminationCondition.robust_optimal" + ) + self.assertEqual( + str(res), + ans, + msg=( + "String representation of PyROS results object does not " + "match expected value" + ), + ) + + +class TestPyROSSolverLogIntros(unittest.TestCase): + """ + Test logging of introductory information by PyROS solver. + """ + + def test_log_config(self): + """ + Test method for logging PyROS solver config dict. + """ + pyros_solver = SolverFactory("pyros") + config = pyros_solver.CONFIG(dict(nominal_uncertain_param_vals=[0.5])) + with LoggingIntercept(level=logging.INFO) as LOG: + pyros_solver._log_config(logger=logger, config=config, level=logging.INFO) + + ans = ( + "Solver options:\n" + " time_limit=None\n" + " keepfiles=False\n" + " tee=False\n" + " load_solution=True\n" + " objective_focus=\n" + " nominal_uncertain_param_vals=[0.5]\n" + " decision_rule_order=0\n" + " solve_master_globally=False\n" + " max_iter=-1\n" + " robust_feasibility_tolerance=0.0001\n" + " separation_priority_order={}\n" + " progress_logger=\n" + " backup_local_solvers=[]\n" + " backup_global_solvers=[]\n" + " subproblem_file_directory=None\n" + " bypass_local_separation=False\n" + " bypass_global_separation=False\n" + " p_robustness={}\n" + "-" * 78 + "\n" + ) + + logged_str = LOG.getvalue() + self.assertEqual( + logged_str, + ans, + msg=( + "Logger output for PyROS solver config (default case) " + "does not match expected result." + ), + ) + + def test_log_intro(self): + """ + Test logging of PyROS solver introductory messages. + """ + pyros_solver = SolverFactory("pyros") + with LoggingIntercept(level=logging.INFO) as LOG: + pyros_solver._log_intro(logger=logger, level=logging.INFO) + + intro_msgs = LOG.getvalue() + + # last character should be newline; disregard it + intro_msg_lines = intro_msgs.split("\n")[:-1] + + # check number of lines is as expected + self.assertEqual( + len(intro_msg_lines), + 14, + msg=( + "PyROS solver introductory message does not contain" + "the expected number of lines." + ), + ) + + # first and last lines of the introductory section + self.assertEqual(intro_msg_lines[0], "=" * 78) + self.assertEqual(intro_msg_lines[-1], "=" * 78) + + # check regex main text + self.assertRegex( + " ".join(intro_msg_lines[1:-1]), + r"PyROS: The Pyomo Robust Optimization Solver, v.* \(IDAES\)\.", + ) + + def test_log_disclaimer(self): + """ + Test logging of PyROS solver disclaimer messages. + """ + pyros_solver = SolverFactory("pyros") + with LoggingIntercept(level=logging.INFO) as LOG: + pyros_solver._log_disclaimer(logger=logger, level=logging.INFO) + + disclaimer_msgs = LOG.getvalue() + + # last character should be newline; disregard it + disclaimer_msg_lines = disclaimer_msgs.split("\n")[:-1] + + # check number of lines is as expected + self.assertEqual( + len(disclaimer_msg_lines), + 5, + msg=( + "PyROS solver disclaimer message does not contain" + "the expected number of lines." + ), + ) + + # regex first line of disclaimer section + self.assertRegex(disclaimer_msg_lines[0], r"=.* DISCLAIMER .*=") + # check last line of disclaimer section + self.assertEqual(disclaimer_msg_lines[-1], "=" * 78) + + # check regex main text + self.assertRegex( + " ".join(disclaimer_msg_lines[1:-1]), + r"PyROS is still under development.*ticket at.*", + ) + + if __name__ == "__main__": unittest.main() diff --git a/pyomo/contrib/pyros/util.py b/pyomo/contrib/pyros/util.py index 2c1a309ced3..a956e17b089 100644 --- a/pyomo/contrib/pyros/util.py +++ b/pyomo/contrib/pyros/util.py @@ -41,6 +41,8 @@ import logging from pprint import pprint import math +from pyomo.common.timing import HierarchicalTimer +from pyomo.common.log import Preformatted # Tolerances used in the code @@ -50,6 +52,135 @@ COEFF_MATCH_ABS_TOL = 0 ABS_CON_CHECK_FEAS_TOL = 1e-5 TIC_TOC_SOLVE_TIME_ATTR = "pyros_tic_toc_time" +DEFAULT_LOGGER_NAME = "pyomo.contrib.pyros" + + +class TimingData: + """ + PyROS solver timing data object. + + Implemented as a wrapper around `common.timing.HierarchicalTimer`, + with added functionality for enforcing a standardized + hierarchy of identifiers. + + Attributes + ---------- + hierarchical_timer_full_ids : set of str + (Class attribute.) Valid identifiers for use with + the encapsulated hierarchical timer. + """ + + hierarchical_timer_full_ids = { + "main", + "main.preprocessing", + "main.master_feasibility", + "main.master", + "main.dr_polishing", + "main.local_separation", + "main.global_separation", + } + + def __init__(self): + """Initialize self (see class docstring).""" + self._hierarchical_timer = HierarchicalTimer() + + def __str__(self): + """ + String representation of `self`. Currently + returns the string representation of `self.hierarchical_timer`. + + Returns + ------- + str + String representation. + """ + return self._hierarchical_timer.__str__() + + def _validate_full_identifier(self, full_identifier): + """ + Validate identifier for hierarchical timer. + + Parameters + ---------- + full_identifier : str + Identifier to validate. + + Raises + ------ + ValueError + If identifier not in `TimingData.hierarchical_timer_full_ids`. + """ + if full_identifier not in self.hierarchical_timer_full_ids: + raise ValueError( + "PyROS timing data object does not support timing ID: " + f"{full_identifier}." + ) + + def start_timer(self, full_identifier): + """ + Start timer for `self.hierarchical_timer`. + + Parameters + ---------- + full_identifier : str + Full identifier for the timer to be started. + Must be an entry of + `TimingData.hierarchical_timer_full_ids`. + """ + self._validate_full_identifier(full_identifier) + identifier = full_identifier.split(".")[-1] + return self._hierarchical_timer.start(identifier=identifier) + + def stop_timer(self, full_identifier): + """ + Stop timer for `self.hierarchical_timer`. + + Parameters + ---------- + full_identifier : str + Full identifier for the timer to be stopped. + Must be an entry of + `TimingData.hierarchical_timer_full_ids`. + """ + self._validate_full_identifier(full_identifier) + identifier = full_identifier.split(".")[-1] + return self._hierarchical_timer.stop(identifier=identifier) + + def get_total_time(self, full_identifier): + """ + Get total time spent with identifier active. + + Parameters + ---------- + full_identifier : str + Full identifier for the timer of interest. + + Returns + ------- + float + Total time spent with identifier active. + """ + return self._hierarchical_timer.get_total_time(identifier=full_identifier) + + def get_main_elapsed_time(self): + """ + Get total time elapsed for main timer of + the HierarchicalTimer contained in self. + + Returns + ------- + float + Total elapsed time. + + Note + ---- + This method is meant for use while the main timer is active. + Otherwise, use ``self.get_total_time("main")``. + """ + # clean? + return self._hierarchical_timer.timers["main"].tic_toc.toc( + msg=None, delta=False + ) '''Code borrowed from gdpopt: time_code, get_main_elapsed_time, a_logger.''' @@ -57,31 +188,33 @@ @contextmanager def time_code(timing_data_obj, code_block_name, is_main_timer=False): - """Starts timer at entry, stores elapsed time at exit + """ + Starts timer at entry, stores elapsed time at exit. + + Parameters + ---------- + timing_data_obj : TimingData + Timing data object. + code_block_name : str + Name of code block being timed. If `is_main_timer=True`, the start time is stored in the timing_data_obj, allowing calculation of total elapsed time 'on the fly' (e.g. to enforce a time limit) using `get_main_elapsed_time(timing_data_obj)`. """ + # initialize tic toc timer + timing_data_obj.start_timer(code_block_name) + start_time = timeit.default_timer() if is_main_timer: timing_data_obj.main_timer_start_time = start_time yield - elapsed_time = timeit.default_timer() - start_time - prev_time = timing_data_obj.get(code_block_name, 0) - timing_data_obj[code_block_name] = prev_time + elapsed_time + timing_data_obj.stop_timer(code_block_name) def get_main_elapsed_time(timing_data_obj): """Returns the time since entering the main `time_code` context""" - current_time = timeit.default_timer() - try: - return current_time - timing_data_obj.main_timer_start_time - except AttributeError as e: - if 'main_timer_start_time' in str(e): - raise AttributeError( - "You need to be in a 'time_code' context to use `get_main_elapsed_time()`." - ) + return timing_data_obj.get_main_elapsed_time() def adjust_solver_time_settings(timing_data_obj, solver, config): @@ -223,10 +356,107 @@ def revert_solver_max_time_adjustment( del solver.options[options_key] +class PreformattedLogger(logging.Logger): + """ + A specialized logger object designed to cast log messages + to Pyomo `Preformatted` objects prior to logging the messages. + Useful for circumventing the formatters of the standard Pyomo + logger in the event an instance is a descendant of the Pyomo + logger. + """ + + def critical(self, msg, *args, **kwargs): + """ + Preformat and log ``msg % args`` with severity + `logging.CRITICAL`. + """ + return super(PreformattedLogger, self).critical( + Preformatted(msg % args if args else msg), **kwargs + ) + + def error(self, msg, *args, **kwargs): + """ + Preformat and log ``msg % args`` with severity + `logging.ERROR`. + """ + return super(PreformattedLogger, self).error( + Preformatted(msg % args if args else msg), **kwargs + ) + + def warning(self, msg, *args, **kwargs): + """ + Preformat and log ``msg % args`` with severity + `logging.WARNING`. + """ + return super(PreformattedLogger, self).warning( + Preformatted(msg % args if args else msg), **kwargs + ) + + def info(self, msg, *args, **kwargs): + """ + Preformat and log ``msg % args`` with severity + `logging.INFO`. + """ + return super(PreformattedLogger, self).info( + Preformatted(msg % args if args else msg), **kwargs + ) + + def debug(self, msg, *args, **kwargs): + """ + Preformat and log ``msg % args`` with severity + `logging.DEBUG`. + """ + return super(PreformattedLogger, self).debug( + Preformatted(msg % args if args else msg), **kwargs + ) + + def log(self, level, msg, *args, **kwargs): + """ + Preformat and log ``msg % args`` with integer + severity `level`. + """ + return super(PreformattedLogger, self).log( + level, Preformatted(msg % args if args else msg), **kwargs + ) + + +def setup_pyros_logger(name=DEFAULT_LOGGER_NAME): + """ + Set up pyros logger. + """ + # default logger: INFO level, with preformatted messages + current_logger_class = logging.getLoggerClass() + logging.setLoggerClass(PreformattedLogger) + logger = logging.getLogger(DEFAULT_LOGGER_NAME) + logger.setLevel(logging.INFO) + logging.setLoggerClass(current_logger_class) + + return logger + + def a_logger(str_or_logger): - """Returns a logger when passed either a logger name or logger object.""" + """ + Standardize a string or logger object to a logger object. + + Parameters + ---------- + str_or_logger : str or logging.Logger + String or logger object to normalize. + + Returns + ------- + logging.Logger + If `str_or_logger` is of type `logging.Logger`,then + `str_or_logger` is returned. + Otherwise, ``logging.getLogger(str_or_logger)`` + is returned. In the event `str_or_logger` is + the name of the default PyROS logger, the logger level + is set to `logging.INFO`, and a `PreformattedLogger` + instance is returned in lieu of a standard `Logger` + instance. + """ if isinstance(str_or_logger, logging.Logger): - return str_or_logger + return logging.getLogger(str_or_logger.name) else: return logging.getLogger(str_or_logger) @@ -271,6 +501,25 @@ class pyrosTerminationCondition(Enum): time_out = 5 """Maximum allowable time exceeded.""" + @property + def message(self): + """ + str : Message associated with a given PyROS + termination condition. + """ + message_dict = { + self.robust_optimal: "Robust optimal solution identified.", + self.robust_feasible: "Robust feasible solution identified.", + self.robust_infeasible: "Problem is robust infeasible.", + self.time_out: "Maximum allowable time exceeded.", + self.max_iter: "Maximum number of iterations reached.", + self.subsolver_error: ( + "Subordinate optimizer(s) could not solve a subproblem " + "to an acceptable status." + ), + } + return message_dict[self] + class SeparationStrategy(Enum): all_violations = auto() @@ -1383,111 +1632,193 @@ def process_termination_condition_master_problem(config, results): ) -def output_logger(config, **kwargs): - ''' - All user returned messages (termination conditions, runtime errors) are here - Includes when - "sub-solver %s returned status infeasible..." - :return: - ''' +class IterationLogRecord: + """ + PyROS solver iteration log record. - # === PREAMBLE + LICENSING - # Version printing - if "preamble" in kwargs: - if kwargs["preamble"]: - version = str(kwargs["version"]) - preamble = ( - "===========================================================================================\n" - "PyROS: Pyomo Robust Optimization Solver v.%s \n" - "Developed by: Natalie M. Isenberg (1), Jason A. F. Sherman (1), \n" - " John D. Siirola (2), Chrysanthos E. Gounaris (1) \n" - "(1) Carnegie Mellon University, Department of Chemical Engineering \n" - "(2) Sandia National Laboratories, Center for Computing Research\n\n" - "The developers gratefully acknowledge support from the U.S. Department of Energy's \n" - "Institute for the Design of Advanced Energy Systems (IDAES) \n" - "===========================================================================================" - % version - ) - print(preamble) - # === DISCLAIMER - if "disclaimer" in kwargs: - if kwargs["disclaimer"]: - print( - "======================================== DISCLAIMER =======================================\n" - "PyROS is still under development. \n" - "Please provide feedback and/or report any issues by opening a Pyomo ticket.\n" - "===========================================================================================\n" - ) - # === ALL LOGGER RETURN MESSAGES - if "bypass_global_separation" in kwargs: - if kwargs["bypass_global_separation"]: - config.progress_logger.info( - "NOTE: Option to bypass global separation was chosen. " - "Robust feasibility and optimality of the reported " - "solution are not guaranteed." - ) - if "robust_optimal" in kwargs: - if kwargs["robust_optimal"]: - config.progress_logger.info( - 'Robust optimal solution identified. Exiting PyROS.' - ) + Parameters + ---------- + iteration : int or None, optional + Iteration number. + objective : int or None, optional + Master problem objective value. + Note: if the sense of the original model is maximization, + then this is the negative of the objective value + of the original model. + first_stage_var_shift : float or None, optional + Infinity norm of the difference between first-stage + variable vectors for the current and previous iterations. + dr_var_shift : float or None, optional + Infinity norm of the difference between decision rule + variable vectors for the current and previous iterations. + dr_polishing_success : bool or None, optional + True if DR polishing solved successfully, False otherwise. + num_violated_cons : int or None, optional + Number of performance constraints found to be violated + during separation step. + all_sep_problems_solved : int or None, optional + True if all separation problems were solved successfully, + False otherwise (such as if there was a time out, subsolver + error, or only a subset of the problems were solved due to + custom constraint prioritization). + global_separation : bool, optional + True if separation problems were solved with the subordinate + global optimizer(s), False otherwise. + max_violation : int or None + Maximum scaled violation of any performance constraint + found during separation step. + elapsed_time : float, optional + Total time elapsed up to the current iteration, in seconds. + + Attributes + ---------- + iteration : int or None + Iteration number. + objective : int or None + Master problem objective value. + Note: if the sense of the original model is maximization, + then this is the negative of the objective value + of the original model. + first_stage_var_shift : float or None + Infinity norm of the difference between first-stage + variable vectors for the current and previous iterations. + dr_var_shift : float or None + Infinity norm of the difference between decision rule + variable vectors for the current and previous iterations. + dr_polishing_success : bool or None + True if DR polishing solved successfully, False otherwise. + num_violated_cons : int or None + Number of performance constraints found to be violated + during separation step. + all_sep_problems_solved : int or None + True if all separation problems were solved successfully, + False otherwise (such as if there was a time out, subsolver + error, or only a subset of the problems were solved due to + custom constraint prioritization). + global_separation : bool + True if separation problems were solved with the subordinate + global optimizer(s), False otherwise. + max_violation : int or None + Maximum scaled violation of any performance constraint + found during separation step. + elapsed_time : float + Total time elapsed up to the current iteration, in seconds. + """ - if "robust_feasible" in kwargs: - if kwargs["robust_feasible"]: - config.progress_logger.info( - 'Robust feasible solution identified. Exiting PyROS.' - ) + _LINE_LENGTH = 78 + _ATTR_FORMAT_LENGTHS = { + "iteration": 5, + "objective": 13, + "first_stage_var_shift": 13, + "dr_var_shift": 13, + "num_violated_cons": 8, + "max_violation": 13, + "elapsed_time": 13, + } + _ATTR_HEADER_NAMES = { + "iteration": "Itn", + "objective": "Objective", + "first_stage_var_shift": "1-Stg Shift", + "dr_var_shift": "DR Shift", + "num_violated_cons": "#CViol", + "max_violation": "Max Viol", + "elapsed_time": "Wall Time (s)", + } + + def __init__( + self, + iteration, + objective, + first_stage_var_shift, + dr_var_shift, + dr_polishing_success, + num_violated_cons, + all_sep_problems_solved, + global_separation, + max_violation, + elapsed_time, + ): + """Initialize self (see class docstring).""" + self.iteration = iteration + self.objective = objective + self.first_stage_var_shift = first_stage_var_shift + self.dr_var_shift = dr_var_shift + self.dr_polishing_success = dr_polishing_success + self.num_violated_cons = num_violated_cons + self.all_sep_problems_solved = all_sep_problems_solved + self.global_separation = global_separation + self.max_violation = max_violation + self.elapsed_time = elapsed_time + + def get_log_str(self): + """Get iteration log string.""" + attrs = [ + "iteration", + "objective", + "first_stage_var_shift", + "dr_var_shift", + "num_violated_cons", + "max_violation", + "elapsed_time", + ] + return "".join(self._format_record_attr(attr) for attr in attrs) + + def _format_record_attr(self, attr_name): + """Format attribute record for logging.""" + attr_val = getattr(self, attr_name) + if attr_val is None: + fmt_str = f"<{self._ATTR_FORMAT_LENGTHS[attr_name]}s" + return f"{'-':{fmt_str}}" + else: + attr_val_fstrs = { + "iteration": "f'{attr_val:d}'", + "objective": "f'{attr_val: .4e}'", + "first_stage_var_shift": "f'{attr_val:.4e}'", + "dr_var_shift": "f'{attr_val:.4e}'", + "num_violated_cons": "f'{attr_val:d}'", + "max_violation": "f'{attr_val:.4e}'", + "elapsed_time": "f'{attr_val:.3f}'", + } + + # qualifier for DR polishing and separation columns + if attr_name == "dr_var_shift": + qual = "*" if not self.dr_polishing_success else "" + elif attr_name == "num_violated_cons": + qual = "+" if not self.all_sep_problems_solved else "" + elif attr_name == "max_violation": + qual = "g" if self.global_separation else "" + else: + qual = "" - if "robust_infeasible" in kwargs: - if kwargs["robust_infeasible"]: - config.progress_logger.info('Robust infeasible problem. Exiting PyROS.') - - if "time_out" in kwargs: - if kwargs["time_out"]: - config.progress_logger.info( - 'PyROS was unable to identify robust solution ' - 'before exceeding time limit of %s seconds. ' - 'Consider increasing the time limit via option time_limit.' - % config.time_limit - ) + attr_val_str = f"{eval(attr_val_fstrs[attr_name])}{qual}" - if "max_iter" in kwargs: - if kwargs["max_iter"]: - config.progress_logger.info( - 'PyROS was unable to identify robust solution ' - 'within %s iterations of the GRCS algorithm. ' - 'Consider increasing the iteration limit via option max_iter.' - % config.max_iter - ) + return f"{attr_val_str:{f'<{self._ATTR_FORMAT_LENGTHS[attr_name]}'}}" - if "master_error" in kwargs: - if kwargs["master_error"]: - status_dict = kwargs["status_dict"] - filename = kwargs["filename"] # solver name to solver termination condition - if kwargs["iteration"] == 0: - raise AttributeError( - "User-supplied solver(s) could not solve the deterministic model. " - "Returned termination conditions were: %s" - "Please ensure deterministic model is solvable by at least one of the supplied solvers. " - "Exiting PyROS." % pprint(status_dict, width=1) - ) - config.progress_logger.info( - "User-supplied solver(s) could not solve the master model at iteration %s.\n" - "Returned termination conditions were: %s\n" - "For debugging, this problem has been written to a GAMS file titled %s. Exiting PyROS." - % (kwargs["iteration"], pprint(status_dict), filename) - ) - if "separation_error" in kwargs: - if kwargs["separation_error"]: - status_dict = kwargs["status_dict"] - filename = kwargs["filename"] - iteration = kwargs["iteration"] - obj = kwargs["objective"] - config.progress_logger.info( - "User-supplied solver(s) could not solve the separation problem at iteration %s under separation objective %s.\n" - "Returned termination conditions were: %s\n" - "For debugging, this problem has been written to a GAMS file titled %s. Exiting PyROS." - % (iteration, obj, pprint(status_dict, width=1), filename) - ) + def log(self, log_func, **log_func_kwargs): + """Log self.""" + log_str = self.get_log_str() + log_func(log_str, **log_func_kwargs) - return + @staticmethod + def get_log_header_str(): + """Get string for iteration log header.""" + fmt_lengths_dict = IterationLogRecord._ATTR_FORMAT_LENGTHS + header_names_dict = IterationLogRecord._ATTR_HEADER_NAMES + return "".join( + f"{header_names_dict[attr]:<{fmt_lengths_dict[attr]}s}" + for attr in fmt_lengths_dict + ) + + @staticmethod + def log_header(log_func, with_rules=True, **log_func_kwargs): + """Log header.""" + if with_rules: + IterationLogRecord.log_header_rule(log_func, **log_func_kwargs) + log_func(IterationLogRecord.get_log_header_str(), **log_func_kwargs) + if with_rules: + IterationLogRecord.log_header_rule(log_func, **log_func_kwargs) + + @staticmethod + def log_header_rule(log_func, fillchar="-", **log_func_kwargs): + """Log header rule.""" + log_func(fillchar * IterationLogRecord._LINE_LENGTH, **log_func_kwargs)