diff --git a/doc/src/hubs.rst b/doc/src/hubs.rst index 3a8d9f9e9..4031dab13 100644 --- a/doc/src/hubs.rst +++ b/doc/src/hubs.rst @@ -109,7 +109,9 @@ in the farmer example. The ``farmer_cylinders.py`` file has:: from mpisppy.convergers.norm_rho_converger import NormRhoConverger and optionally passes ``NormRhoConverger`` to the hub constructor. Note that you can observe -the behavior of the hub converger using the option ``--with-display-convergence-detail``. +the behavior of the hub converger using the option ``--with-display-convergence-detail``, +and can request subproblem-solve timing diagnostics (requires one subproblem per +rank) with ``--display-timing``. Unfortunately, the word "converger" is also used to describe spokes that return bounds for the purpose of measuring overall convergence (as opposed to convergence within the hub diff --git a/doc/src/secretmenu.rst b/doc/src/secretmenu.rst index fcad0e260..206533903 100644 --- a/doc/src/secretmenu.rst +++ b/doc/src/secretmenu.rst @@ -5,33 +5,6 @@ There are many options that are not exposed in ``mpisppy.utils.config.py`` and w a few of them here. -display_timing --------------- - -This is a PH option that adds a barrier step to collect information about -the time required to solve subproblems. This can be helpful in diagnosis -and tuning of algorithms because for some problems, the variability in -time to solve scenario sub-problems can be quite large. - -.. Note:: - This option should be used only when there is exactly one subproblem per rank. - -To set the option, use - -.. code-block:: python - - PHoptions["display_timing"] = True - -E.g., if you were adding this to ``examples.farmer.farmer_cylinders`` where the -hub definition dictionary is called ``hub_dict`` you would add - -.. code-block:: python - - hub_dict["opt_kwargs"]["PHoptions"]["display_timing"] = True - -before passing it to ``spin_the_wheel``. - - initial_proximal_cut_count -------------------------- diff --git a/examples/run_all.py b/examples/run_all.py index 693dd5675..c7d5835ef 100644 --- a/examples/run_all.py +++ b/examples/run_all.py @@ -388,7 +388,7 @@ def do_one_mmw(dirname, modname, runefstring, npyfile, mmwargstring): "--num-scens=3 --max-iterations=5 " "--iter0-mipgap=0.01 --iterk-mipgap=0.005 " "--default-rho=1 --lagrangian --xhatshuffle --fwph " - "--solver-name={} --display-progress".format(solver_name)) + "--solver-name={} --display-progress --display-timing".format(solver_name)) if egret_avail(): print("\nSlow runs ahead...\n") diff --git a/mpisppy/tests/test_ef_ph.py b/mpisppy/tests/test_ef_ph.py index 615c366dc..1e5aa6b34 100644 --- a/mpisppy/tests/test_ef_ph.py +++ b/mpisppy/tests/test_ef_ph.py @@ -15,6 +15,9 @@ import os import glob +import io +import contextlib +import re import json import shutil import unittest @@ -192,9 +195,76 @@ def test_ph_iter0(self): scenario_denouement, scenario_creator_kwargs={"scenario_count": 3}, ) - + conv, obj, tbound = ph.ph_main() + @unittest.skipIf(not solver_available, + "no solver is available") + def test_display_timing_emits_nonzero_solve_times(self): + # End-to-end check that display_timing actually reaches the PH + # solve loop and produces a non-zero solve-time report. Guards + # the user-facing CLI flag (issue #290): if a future refactor + # quietly drops the option from self.options or the print path, + # this test fails. + options = self._copy_of_base_options() + options["PHIterLimit"] = 0 + options["display_timing"] = True + + ph = mpisppy.opt.ph.PH( + options, + self.all3_scenario_names, + scenario_creator, + scenario_denouement, + scenario_creator_kwargs={"scenario_count": 3}, + ) + + buf = io.StringIO() + with contextlib.redirect_stdout(buf): + ph.ph_main() + out = buf.getvalue() + + self.assertIn("Pyomo solve times (seconds):", out, + msg=f"display_timing=True but timing header not in output:\n{out}") + m = re.search( + r"min=([0-9.]+)@\d+ mean=([0-9.]+) max=([0-9.]+)@\d+", + out, + ) + self.assertIsNotNone( + m, + msg=f"display_timing stats line not found in output:\n{out}", + ) + mn, me, mx = float(m.group(1)), float(m.group(2)), float(m.group(3)) + # max across scenarios must be strictly positive — any real + # subproblem solve takes measurable wallclock time. min/mean + # could round to 0.00 under %4.2f if subproblems are tiny. + self.assertGreater( + mx, 0.0, + msg=f"max solve time reported as zero: min={mn} mean={me} max={mx}", + ) + + @unittest.skipIf(not solver_available, + "no solver is available") + def test_display_timing_off_suppresses_solve_times(self): + # Companion: confirm the timing report is NOT printed when the + # flag is False, so we know the assertion above isn't picking up + # output emitted unconditionally somewhere. + options = self._copy_of_base_options() + options["PHIterLimit"] = 0 + options["display_timing"] = False + + ph = mpisppy.opt.ph.PH( + options, + self.all3_scenario_names, + scenario_creator, + scenario_denouement, + scenario_creator_kwargs={"scenario_count": 3}, + ) + + buf = io.StringIO() + with contextlib.redirect_stdout(buf): + ph.ph_main() + self.assertNotIn("Pyomo solve times (seconds):", buf.getvalue()) + @unittest.skipIf(not solver_available, "no solver is available") def test_fix_ph_iter0(self): diff --git a/mpisppy/utils/cfg_vanilla.py b/mpisppy/utils/cfg_vanilla.py index 9ac289bab..d71e7e58a 100644 --- a/mpisppy/utils/cfg_vanilla.py +++ b/mpisppy/utils/cfg_vanilla.py @@ -62,6 +62,7 @@ def shared_options(cfg, is_hub=False): "verbose": cfg.verbose, "display_progress": cfg.display_progress, "display_convergence_detail": cfg.display_convergence_detail, + "display_timing": cfg.display_timing, "iter0_solver_options": dict(), "iterk_solver_options": dict(), # Layered representation of solver options. Built in parallel @@ -1034,6 +1035,7 @@ def subgradient_spoke( options["PHIterLimit"] = cfg.max_iterations * 1_000_000 options["display_progress"] = False options["display_convergence_detail"] = False + options["display_timing"] = False add_ph_tracking(subgradient_spoke, cfg, spoke=True) _maybe_attach_jensens(subgradient_spoke, cfg, "subgradient", @@ -1076,6 +1078,7 @@ def ph_dual_spoke( options["PHIterLimit"] = cfg.max_iterations * 1_000_000 options["display_progress"] = False options["display_convergence_detail"] = False + options["display_timing"] = False add_ph_tracking(ph_dual_spoke, cfg, spoke=True) @@ -1116,6 +1119,7 @@ def relaxed_ph_spoke( options["PHIterLimit"] = cfg.max_iterations * 1_000_000 options["display_progress"] = False options["display_convergence_detail"] = False + options["display_timing"] = False add_ph_tracking(relaxed_ph_spoke, cfg, spoke=True) diff --git a/mpisppy/utils/config.py b/mpisppy/utils/config.py index d5785b8d2..0c040fb68 100644 --- a/mpisppy/utils/config.py +++ b/mpisppy/utils/config.py @@ -279,6 +279,11 @@ def popular_args(self): domain=bool, default=False) + self.add_to_config('display_timing', + description="display subproblem solve timing (requires exactly one subproblem per rank)", + domain=bool, + default=False) + self.add_to_config("max_solver_threads", description="Limit on threads per solver (default None)", domain=int,