display_timing: expose via Config and CLI (#290) (#708)

* 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) <noreply@anthropic.com>

* 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) <noreply@anthropic.com>

* 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) <noreply@anthropic.com>

---------

Co-authored-by: Claude Opus 4.7 (1M context) <noreply@anthropic.com>

Author: DLWoodruff

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

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
 --------------------------
 

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")

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):

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)
 

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,