display_timing: expose via Config and CLI (#290)

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,