From 8488d017889260848366b25c861ddcaf62f89ce7 Mon Sep 17 00:00:00 2001 From: Dave Woodruff Date: Sun, 17 May 2026 15:04:31 -0700 Subject: [PATCH 1/3] display_timing: expose via Config and CLI (#290) display_timing was previously a "secret menu" option that had to be set by hand on the options dict. Bring it into mpisppy.utils.config.Config alongside display_progress and display_convergence_detail so it is documented via --help and propagates through cfg_vanilla like its siblings. - mpisppy/utils/config.py: register display_timing (bool, default False). - mpisppy/utils/cfg_vanilla.py: * shared_options(): forward cfg.display_timing into opt_kwargs.options. * subgradient_spoke, ph_dual_spoke, relaxed_ph_spoke: hardcode options["display_timing"] = False, matching the existing pattern for display_progress / display_convergence_detail (these spokes should not print per-iteration diagnostics). - doc/src/secretmenu.rst: drop the display_timing section now that it's a first-class CLI option. The defensive default in phbase.py:887-888 is left in place so PHBase can still be instantiated outside the cfg flow with a manual options dict. Fixes #290 Co-Authored-By: Claude Opus 4.7 (1M context) --- doc/src/secretmenu.rst | 27 --------------------------- mpisppy/utils/cfg_vanilla.py | 4 ++++ mpisppy/utils/config.py | 5 +++++ 3 files changed, 9 insertions(+), 27 deletions(-) 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/mpisppy/utils/cfg_vanilla.py b/mpisppy/utils/cfg_vanilla.py index 4cea09835..8d2a7b1ae 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 @@ -1017,6 +1018,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", @@ -1059,6 +1061,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) @@ -1099,6 +1102,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 e948363a7..53e33482d 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, From fd951cb1567eaaabf2c82a618812a5d41d4085ca Mon Sep 17 00:00:00 2001 From: Dave Woodruff Date: Sun, 17 May 2026 17:27:00 -0700 Subject: [PATCH 2/3] doc + smoke test for --display-timing - doc/src/hubs.rst: mention the new --display-timing flag next to the existing --with-display-convergence-detail note so the option is discoverable from the docs now that the secret-menu section was removed. - examples/run_all.py: add --display-timing to the existing sizes sizes_cylinders.py command so the run_all CI jobs exercise the new CLI plumbing end-to-end as a smoke test. Co-Authored-By: Claude Opus 4.7 (1M context) --- doc/src/hubs.rst | 4 +++- examples/run_all.py | 2 +- 2 files changed, 4 insertions(+), 2 deletions(-) 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/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") From 27c6eacd9bf63432169310ef5f4368bc3b6dbf0d Mon Sep 17 00:00:00 2001 From: Dave Woodruff Date: Sun, 17 May 2026 17:42:58 -0700 Subject: [PATCH 3/3] test: end-to-end verify --display-timing emits non-zero solve times Adds two tests to Test_sizes in mpisppy/tests/test_ef_ph.py: - test_display_timing_emits_nonzero_solve_times: runs PH iter0 with display_timing=True, captures stdout, asserts the "Pyomo solve times (seconds):" header appears, parses the min/mean/max stats line, and requires max > 0. Guards against a future refactor quietly dropping the option from self.options or the print path (issue #290). - test_display_timing_off_suppresses_solve_times: companion that confirms 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. Both tests skip when no solver is available. Co-Authored-By: Claude Opus 4.7 (1M context) --- mpisppy/tests/test_ef_ph.py | 72 ++++++++++++++++++++++++++++++++++++- 1 file changed, 71 insertions(+), 1 deletion(-) 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):