From 3fd1184e1843b081d3d27437ad21f6de7fc00f38 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Thu, 23 Apr 2026 23:36:34 -0600 Subject: [PATCH 01/28] Switch Lock from threading to multiprocessing --- pyomo/common/tee.py | 3 ++- pyomo/common/tests/test_tee.py | 11 ++++++++++- 2 files changed, 12 insertions(+), 2 deletions(-) diff --git a/pyomo/common/tee.py b/pyomo/common/tee.py index 227ae71bae8..c8bde5eba1c 100644 --- a/pyomo/common/tee.py +++ b/pyomo/common/tee.py @@ -17,6 +17,7 @@ import collections.abc import io import logging +import multiprocessing import os import sys import threading @@ -297,7 +298,7 @@ class capture_output: """ - startup_shutdown = threading.Lock() + startup_shutdown = multiprocessing.Lock() def __init__(self, output=None, capture_fd=False): self.output = output diff --git a/pyomo/common/tests/test_tee.py b/pyomo/common/tests/test_tee.py index b1c697dbb22..739df6b3a18 100644 --- a/pyomo/common/tests/test_tee.py +++ b/pyomo/common/tests/test_tee.py @@ -601,8 +601,17 @@ def test_atomic_deadlock(self): tee.capture_output.startup_shutdown.acquire() finally: tee._poll_timeout_deadlock = save_poll - if tee.capture_output.startup_shutdown.locked(): + # We would like to just test if out Lock was aquired and + # then release it if necessary. Unfortunately, + # multiprocessing.Lock doesn't support locked(), so we will + # just catch and eat the error for releasing an unlocked + # lock. + # + ## if tee.capture_output.startup_shutdown.locked(): + try: tee.capture_output.startup_shutdown.release() + except ValueError: + pass co.reset() def test_capture_output_invalid_ostream(self): From 0264d1c2ed430d9586ba73f791b30f1b8917bbc6 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Thu, 23 Apr 2026 23:39:31 -0600 Subject: [PATCH 02/28] Do not raise threading Lock errors when Python is shutting down --- pyomo/common/tee.py | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/pyomo/common/tee.py b/pyomo/common/tee.py index c8bde5eba1c..4e3d961c6e2 100644 --- a/pyomo/common/tee.py +++ b/pyomo/common/tee.py @@ -25,6 +25,7 @@ from pyomo.common.errors import DeveloperError from pyomo.common.log import LoggingIntercept, LogStream +from pyomo.common.shutdown import python_is_shutting_down _poll_interval = 0.0001 _poll_rampup_limit = 0.099 @@ -359,7 +360,8 @@ def __enter__(self): # was trying to start up / run (so the other solver held # the lock, but the GC interrupted that thread and # wouldn't let go). - raise DeveloperError("Deadlock starting capture_output") + if not python_is_shutting_down(): + raise DeveloperError("Deadlock starting capture_output") try: return self._enter_impl() finally: @@ -368,7 +370,8 @@ def __enter__(self): def __exit__(self, et, ev, tb): if not capture_output.startup_shutdown.acquire(timeout=_poll_timeout_deadlock): # See comments & breadcrumbs in __enter__() above. - raise DeveloperError("Deadlock closing capture_output") + if not python_is_shutting_down(): + raise DeveloperError("Deadlock closing capture_output") try: return self._exit_impl(et, ev, tb) finally: From c98bc8ba0508ef710c272dbb5887f65c08b9d569 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Thu, 23 Apr 2026 23:40:21 -0600 Subject: [PATCH 03/28] Split the deadlock timeout parameter --- pyomo/common/tee.py | 5 +++-- pyomo/common/tests/test_tee.py | 6 +++--- 2 files changed, 6 insertions(+), 5 deletions(-) diff --git a/pyomo/common/tee.py b/pyomo/common/tee.py index 4e3d961c6e2..f660c1d9a34 100644 --- a/pyomo/common/tee.py +++ b/pyomo/common/tee.py @@ -37,6 +37,7 @@ # ~(13.1 * #threads) seconds _poll_timeout = 1 # 14 rounds: 0.0001 * 2**14 == 1.6384 _poll_timeout_deadlock = 100 # seconds +_threading_deadlock = 200 # seconds; should be longer than _poll_timeout_deadlock _pipe_buffersize = 1 << 16 # 65536 _noop = lambda: None _mswindows = sys.platform.startswith('win') @@ -347,7 +348,7 @@ def _exit_context_stack(self, et, ev, tb): return FAIL def __enter__(self): - if not capture_output.startup_shutdown.acquire(timeout=_poll_timeout_deadlock): + if not capture_output.startup_shutdown.acquire(timeout=_threading_deadlock): # This situation *shouldn't* happen. If it does, it is # unlikely that the user can fix it (or even debug it). # Instead they should report it back to us. @@ -368,7 +369,7 @@ def __enter__(self): capture_output.startup_shutdown.release() def __exit__(self, et, ev, tb): - if not capture_output.startup_shutdown.acquire(timeout=_poll_timeout_deadlock): + if not capture_output.startup_shutdown.acquire(timeout=_threading_deadlock): # See comments & breadcrumbs in __enter__() above. if not python_is_shutting_down(): raise DeveloperError("Deadlock closing capture_output") diff --git a/pyomo/common/tests/test_tee.py b/pyomo/common/tests/test_tee.py index 739df6b3a18..ff607493964 100644 --- a/pyomo/common/tests/test_tee.py +++ b/pyomo/common/tests/test_tee.py @@ -581,8 +581,8 @@ def test_capture_output_stack_error(self): logging.getLogger('pyomo.common.tee').handlers.clear() def test_atomic_deadlock(self): - save_poll = tee._poll_timeout_deadlock - tee._poll_timeout_deadlock = 0.01 + save_poll = tee._threading_deadlock + tee._threading_deadlock = 0.01 co = tee.capture_output() try: @@ -600,7 +600,7 @@ def test_atomic_deadlock(self): with co: tee.capture_output.startup_shutdown.acquire() finally: - tee._poll_timeout_deadlock = save_poll + tee._threading_deadlock = save_poll # We would like to just test if out Lock was aquired and # then release it if necessary. Unfortunately, # multiprocessing.Lock doesn't support locked(), so we will From b72d5e7ab447028e79aa2107769d6ade47da40d7 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Thu, 23 Apr 2026 23:40:35 -0600 Subject: [PATCH 04/28] Minor code cleanup --- pyomo/common/tee.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/pyomo/common/tee.py b/pyomo/common/tee.py index f660c1d9a34..5b6a869db9f 100644 --- a/pyomo/common/tee.py +++ b/pyomo/common/tee.py @@ -342,9 +342,8 @@ def _exit_context_stack(self, et, ev, tb): cm.__exit__(et, ev, tb) except: _stack = self.context_stack - FAIL.append( - f"{sys.exc_info()[0].__name__}: {sys.exc_info()[1]} ({len(_stack)+1}: {cm}@{id(cm):x})" - ) + _et, _e, _tb = sys.exc_info() + FAIL.append(f"{_et.__name__}: {_e} ({len(_stack)+1}: {cm}@{id(cm):x})") return FAIL def __enter__(self): From 935226649498d61d6d39e4e9927cf02a175b07c2 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Mon, 27 Apr 2026 12:23:43 -0600 Subject: [PATCH 05/28] Avoid Lock deadlock in @timeout() decorator --- pyomo/common/tee.py | 7 ++++++- pyomo/common/tests/test_unittest.py | 24 ++++++++++++++++++++++-- pyomo/common/unittest.py | 26 +++++++++++++++++++++++++- 3 files changed, 53 insertions(+), 4 deletions(-) diff --git a/pyomo/common/tee.py b/pyomo/common/tee.py index 5b6a869db9f..eb9c3abf221 100644 --- a/pyomo/common/tee.py +++ b/pyomo/common/tee.py @@ -17,12 +17,17 @@ import collections.abc import io import logging -import multiprocessing import os import sys import threading import time +# Note: multiprocessing is very slow to import, but we need to make sure +# that the startup_shutdown Lock is created *before* the user spawns any +# subprocesses. Therefore, we will bite the bullet and import it so +# we can create the Lock immediately when we import this module. +import multiprocessing + from pyomo.common.errors import DeveloperError from pyomo.common.log import LoggingIntercept, LogStream from pyomo.common.shutdown import python_is_shutting_down diff --git a/pyomo/common/tests/test_unittest.py b/pyomo/common/tests/test_unittest.py index d00e3c1124f..2d41b37f190 100644 --- a/pyomo/common/tests/test_unittest.py +++ b/pyomo/common/tests/test_unittest.py @@ -171,8 +171,28 @@ def test_assertStructuredAlmostEqual_numericvalue(self): def test_timeout_fcn_call(self): self.assertEqual(short_sleep(), 42) - with self.assertRaisesRegex(TimeoutError, 'test timed out after 0.01 seconds'): - long_sleep() + with LoggingIntercept() as LOG: + with self.assertRaisesRegex( + TimeoutError, 'test timed out after 0.01 seconds' + ): + long_sleep() + self.assertEqual(LOG.getvalue(), "") + capture_output.startup_shutdown.acquire() + save = unittest._timeout_terminate_timeout + unittest._timeout_terminate_timeout = 0.01 + try: + with self.assertRaisesRegex( + TimeoutError, 'test timed out after 0.01 seconds' + ): + long_sleep() + finally: + unittest._timeout_terminate_timeout = save + capture_output.startup_shutdown.release() + self.assertEqual( + LOG.getvalue(), + "Failed to acquire capture_output.startup_shutdown Lock before " + "terminating subprocess on timeout: process deadlock is likely.\n", + ) with self.assertRaisesRegex( NameError, r"name 'foo' is not defined\s+Original traceback:" ): diff --git a/pyomo/common/unittest.py b/pyomo/common/unittest.py index 25c87c1f276..6576c4c0627 100644 --- a/pyomo/common/unittest.py +++ b/pyomo/common/unittest.py @@ -44,6 +44,10 @@ # (and then enforce a strict dependence on pytest) pytest, pytest_available = attempt_import('pytest') +#: A time limit for acquiring the capture_output.startup_shutdown lock +#: before terminating a subprocess +_timeout_terminate_timeout = 2 # seconds + def _defaultFormatter(msg, default): return msg or default @@ -487,7 +491,27 @@ def test_timer(*args, **kwargs): if pipe_recv.poll(seconds): resultType, result, stdout = pipe_recv.recv() else: - test_proc.terminate() + # Note: because we are using capture_output within + # the _runner handler, we can trigger a deadlock + # when we call terminate() while the _runner's + # capture_output holds the startup_shutdown lock + # (terminate() bypasses all __exit__ handlers!). To + # avoid that, we will grab the lock here before + # terminating the subprocess. + locked = capture_output.startup_shutdown.acquire( + timeout=_timeout_terminate_timeout + ) + if not locked: + logging.getLogger(__name__).error( + "Failed to acquire capture_output.startup_shutdown " + "Lock before terminating subprocess on timeout: " + "process deadlock is likely." + ) + try: + test_proc.terminate() + finally: + if locked: + capture_output.startup_shutdown.release() raise timeout_raises( "test timed out after %s seconds" % (seconds,) ) from None From 09b6e52e801310fe7af9ca93255504f5dcfc0320 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Mon, 27 Apr 2026 12:26:25 -0600 Subject: [PATCH 06/28] multiprocessing is now an automatic import --- pyomo/environ/tests/test_environ.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/pyomo/environ/tests/test_environ.py b/pyomo/environ/tests/test_environ.py index b012e9e656e..3c912ddaaac 100644 --- a/pyomo/environ/tests/test_environ.py +++ b/pyomo/environ/tests/test_environ.py @@ -116,7 +116,7 @@ def test_tpl_import_time(self): print("TPLS (by package time):") print( "\n".join( - " %12s: %6d (%4.1f%%)" % (m, t, 100 * t / total) + " %15s: %6d (%4.1f%%)" % (m, t, 100 * t / total) for m, t in tpl_by_time ) ) @@ -149,6 +149,7 @@ def test_tpl_import_time(self): 'json', # Imported on Windows 'locale', # Added in Python 3.9 'logging', + 'multiprocessing', # capture_output requires multiprocessing.Lock 'pickle', 'platform', 'shlex', From 96e3aff8499e0f4b50c6ae27aadb7ea27829f6df Mon Sep 17 00:00:00 2001 From: John Siirola Date: Mon, 27 Apr 2026 12:57:37 -0600 Subject: [PATCH 07/28] NFC: typo --- pyomo/common/tests/test_tee.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pyomo/common/tests/test_tee.py b/pyomo/common/tests/test_tee.py index ff607493964..b2fdedc73b6 100644 --- a/pyomo/common/tests/test_tee.py +++ b/pyomo/common/tests/test_tee.py @@ -601,7 +601,7 @@ def test_atomic_deadlock(self): tee.capture_output.startup_shutdown.acquire() finally: tee._threading_deadlock = save_poll - # We would like to just test if out Lock was aquired and + # We would like to just test if out Lock was acquired and # then release it if necessary. Unfortunately, # multiprocessing.Lock doesn't support locked(), so we will # just catch and eat the error for releasing an unlocked From 4042736973c7a07619a9f85e688f32c5f181bbb5 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Mon, 27 Apr 2026 12:59:36 -0600 Subject: [PATCH 08/28] Debugging --- pyomo/environ/tests/test_environ.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/pyomo/environ/tests/test_environ.py b/pyomo/environ/tests/test_environ.py index 3c912ddaaac..59310bd1e1e 100644 --- a/pyomo/environ/tests/test_environ.py +++ b/pyomo/environ/tests/test_environ.py @@ -35,6 +35,7 @@ def collect_import_time(module): # Note: test only runs in PY3 output = output.decode() line_re = re.compile(r'.*:\s*(\d+) \|\s*(\d+) \| ( *)([^ ]+)') + print(output) data = [] for line in output.splitlines(): g = line_re.match(line) @@ -44,7 +45,7 @@ def collect_import_time(module): _cumul = int(g.group(2)) _level = len(g.group(3)) // 2 _module = g.group(4) - # print("%6d %8d %2d %s" % (_self, _cumul, _level, _module)) + print("%6d %8d %2d %s" % (_self, _cumul, _level, _module)) while len(data) < _level + 1: data.append(ImportData()) if len(data) > _level + 1: From e1c7edcd9d641811ac811bec0b660cd7bb683eef Mon Sep 17 00:00:00 2001 From: John Siirola Date: Mon, 27 Apr 2026 14:15:06 -0600 Subject: [PATCH 09/28] Update parser for new output --- pyomo/environ/tests/test_environ.py | 14 +++++++++++--- 1 file changed, 11 insertions(+), 3 deletions(-) diff --git a/pyomo/environ/tests/test_environ.py b/pyomo/environ/tests/test_environ.py index 59310bd1e1e..2e16574197f 100644 --- a/pyomo/environ/tests/test_environ.py +++ b/pyomo/environ/tests/test_environ.py @@ -35,8 +35,9 @@ def collect_import_time(module): # Note: test only runs in PY3 output = output.decode() line_re = re.compile(r'.*:\s*(\d+) \|\s*(\d+) \| ( *)([^ ]+)') - print(output) + # print(output) data = [] + seen = set() for line in output.splitlines(): g = line_re.match(line) if not g: @@ -45,11 +46,17 @@ def collect_import_time(module): _cumul = int(g.group(2)) _level = len(g.group(3)) // 2 _module = g.group(4) - print("%6d %8d %2d %s" % (_self, _cumul, _level, _module)) + # print("%6d %8d %2d %s" % (_self, _cumul, _level, _module)) while len(data) < _level + 1: data.append(ImportData()) if len(data) > _level + 1: - assert len(data) == _level + 2 + if len(data) != _level + 2: + if _self in seen: + continue + print(output) + raise RuntimeError( + f"Error processing line '{line}': unexpected unindent" + ) inner = data.pop() inner.tpl = { (k if '(from' in k else "%s (from %s)" % (k, _module), v) @@ -65,6 +72,7 @@ def collect_import_time(module): data[_level].pyomo[_module] = _self elif _level > 0: data[_level].tpl[_module] = _self + seen.add(_self) assert len(data) == 1 return data[0] From c0081efa8a7f50630cc7e5bd75c9200302782e96 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Mon, 27 Apr 2026 15:12:29 -0600 Subject: [PATCH 10/28] Fix logic error --- pyomo/environ/tests/test_environ.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/pyomo/environ/tests/test_environ.py b/pyomo/environ/tests/test_environ.py index 2e16574197f..3119549e8dd 100644 --- a/pyomo/environ/tests/test_environ.py +++ b/pyomo/environ/tests/test_environ.py @@ -51,7 +51,7 @@ def collect_import_time(module): data.append(ImportData()) if len(data) > _level + 1: if len(data) != _level + 2: - if _self in seen: + if _module in seen: continue print(output) raise RuntimeError( @@ -72,7 +72,7 @@ def collect_import_time(module): data[_level].pyomo[_module] = _self elif _level > 0: data[_level].tpl[_module] = _self - seen.add(_self) + seen.add(_module) assert len(data) == 1 return data[0] From 155c1f87bc5fefed5b063f100b2246c1c8585c6c Mon Sep 17 00:00:00 2001 From: John Siirola Date: Mon, 27 Apr 2026 23:08:25 -0600 Subject: [PATCH 11/28] Attempt to make multiprocessing import more deterministic --- pyomo/common/dependencies.py | 20 +++++++++++++++----- 1 file changed, 15 insertions(+), 5 deletions(-) diff --git a/pyomo/common/dependencies.py b/pyomo/common/dependencies.py index 1f9f694932e..1c312172fe6 100644 --- a/pyomo/common/dependencies.py +++ b/pyomo/common/dependencies.py @@ -1081,6 +1081,21 @@ def _pyutilib_importer(): with declare_modules_as_importable(globals()): + # Standard libraries that we will unconditionally import. We are + # importing it here so that import timing is better reported from + # pyomo.environ.tests.test_environ (hence the imports are not + # necessarily alphebetical) + # + # Pickle is used by Pyomo and by multiprocessing + try: + import cPickle as pickle + except ImportError: + import pickle + # multiprocessing is unconditionally needed by capture_output + import multiprocessing + import multiprocessing.dummy + import multiprocessing.resource_tracker + # Standard libraries that are slower to import and not strictly required # on all platforms / situations. ctypes, _ = attempt_import( @@ -1127,8 +1142,3 @@ def _pyutilib_importer(): deferred_submodules=['pyplot', 'pylab', 'backends'], catch_exceptions=(ImportError, RuntimeError), ) - -try: - import cPickle as pickle -except ImportError: - import pickle From 30994a3a08fac82e5d195fab8b151c12b0ecedc0 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Mon, 27 Apr 2026 23:59:42 -0600 Subject: [PATCH 12/28] Attempt to make multiprocessing import more deterministic (try 2) --- pyomo/common/dependencies.py | 1 - pyomo/common/env.py | 2 +- pyomo/common/tee.py | 2 +- pyomo/common/tests/test_multithread.py | 14 +++++++------- pyomo/common/tests/test_unittest.py | 2 +- 5 files changed, 10 insertions(+), 11 deletions(-) diff --git a/pyomo/common/dependencies.py b/pyomo/common/dependencies.py index 1c312172fe6..ebe8dd45010 100644 --- a/pyomo/common/dependencies.py +++ b/pyomo/common/dependencies.py @@ -1101,7 +1101,6 @@ def _pyutilib_importer(): ctypes, _ = attempt_import( 'ctypes', deferred_submodules=['util'], callback=_finalize_ctypes ) - multiprocessing, _ = attempt_import('multiprocessing') random, _ = attempt_import('random') # Necessary for minimum version checking for other optional dependencies diff --git a/pyomo/common/env.py b/pyomo/common/env.py index bd816ef7548..b06ebb8ccbe 100644 --- a/pyomo/common/env.py +++ b/pyomo/common/env.py @@ -9,7 +9,7 @@ import os -from .dependencies import ctypes, multiprocessing +from pyomo.common.dependencies import ctypes, multiprocessing def _as_bytes(val): diff --git a/pyomo/common/tee.py b/pyomo/common/tee.py index eb9c3abf221..76cb0935476 100644 --- a/pyomo/common/tee.py +++ b/pyomo/common/tee.py @@ -26,7 +26,7 @@ # that the startup_shutdown Lock is created *before* the user spawns any # subprocesses. Therefore, we will bite the bullet and import it so # we can create the Lock immediately when we import this module. -import multiprocessing +from pyomo.common.dependencies import multiprocessing from pyomo.common.errors import DeveloperError from pyomo.common.log import LoggingIntercept, LogStream diff --git a/pyomo/common/tests/test_multithread.py b/pyomo/common/tests/test_multithread.py index a47933d7ba9..bc0592a023f 100644 --- a/pyomo/common/tests/test_multithread.py +++ b/pyomo/common/tests/test_multithread.py @@ -8,11 +8,15 @@ # ____________________________________________________________________________________ import threading -import pyomo.common.unittest as unittest -from pyomo.common.multithread import * from threading import Thread + +import pyomo.common.unittest as unittest + +from pyomo.common.dependencies.multiprocessing.dummy import Pool as ThreadPool +from pyomo.common.multithread import MultiThreadWrapper, MultiThreadWrapperWithMain from pyomo.opt.base.solvers import check_available_solvers +import pyomo.environ as pyo class Dummy: """asdfg""" @@ -103,10 +107,6 @@ def thread_func(): ) def test_solve(self): # Based on the minimal example in https://github.com/Pyomo/pyomo/issues/2475 - import pyomo.environ as pyo - from pyomo.opt import SolverFactory - from multiprocessing.dummy import Pool as ThreadPool - model = pyo.ConcreteModel() model.nVars = pyo.Param(initialize=4) model.N = pyo.RangeSet(model.nVars) @@ -115,7 +115,7 @@ def test_solve(self): model.cuts = pyo.ConstraintList() def test(model): - opt = SolverFactory('glpk') + opt = pyo.SolverFactory('glpk') opt.solve(model) # Iterate, adding a cut to exclude the previously found solution diff --git a/pyomo/common/tests/test_unittest.py b/pyomo/common/tests/test_unittest.py index 2d41b37f190..9b361ddd356 100644 --- a/pyomo/common/tests/test_unittest.py +++ b/pyomo/common/tests/test_unittest.py @@ -8,12 +8,12 @@ # ____________________________________________________________________________________ import datetime -import multiprocessing import os import pickle import time import pyomo.common.unittest as unittest +from pyomo.common.dependencies import multiprocessing from pyomo.common.log import LoggingIntercept from pyomo.common.tee import capture_output from pyomo.common.tempfiles import TempfileManager From 5dc09becfb67b7f6b181727a3c2a8c3f8f9873d4 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Tue, 28 Apr 2026 12:39:45 -0600 Subject: [PATCH 13/28] Update importtime tester to handle multiprocessing, improve output --- pyomo/environ/tests/test_environ.py | 170 +++++++++++++++++++--------- 1 file changed, 115 insertions(+), 55 deletions(-) diff --git a/pyomo/environ/tests/test_environ.py b/pyomo/environ/tests/test_environ.py index 3119549e8dd..d0588dc7d20 100644 --- a/pyomo/environ/tests/test_environ.py +++ b/pyomo/environ/tests/test_environ.py @@ -10,6 +10,7 @@ # Unit Tests for pyomo.base.misc # +import math import re import sys import subprocess @@ -20,27 +21,45 @@ class ImportData: def __init__(self): self.tpl = {} - self.pyomo = {} + self.module = {} def update(self, other): self.tpl.update(other.tpl) - self.pyomo.update(other.pyomo) + self.module.update(other.module) + def imax(self, other): + for k, v in other.tpl.items(): + if k in self.tpl: + v = max(v, self.tpl[k]) + self.tpl[k] = v + self.module.update(other.module) -def collect_import_time(module): + +def collect_import_time(module, preimport=""): + basemodule = module.split('.')[0] + if preimport: + cmd = f"{preimport}; import {module}" + else: + cmd = f"import {module}" output = subprocess.check_output( - [sys.executable, '-X', 'importtime', '-c', 'import %s' % (module,)], - stderr=subprocess.STDOUT, + [sys.executable, '-X', 'importtime', '-c', cmd], stderr=subprocess.STDOUT ) # Note: test only runs in PY3 output = output.decode() - line_re = re.compile(r'.*:\s*(\d+) \|\s*(\d+) \| ( *)([^ ]+)') # print(output) - data = [] - seen = set() + line_re = re.compile(r'.*:\s*(\d+) \|\s*(\d+) \| ( *)([^ ]+)') + header_re = re.compile(r'.*:\s*(.*)') + results = [] + data = None for line in output.splitlines(): g = line_re.match(line) if not g: + g = header_re.match(line) + if g: + data = [] + results.append(data) + else: + raise RuntimeError(f"Unrecognized line: '{line}'") continue _self = int(g.group(1)) _cumul = int(g.group(2)) @@ -51,9 +70,6 @@ def collect_import_time(module): data.append(ImportData()) if len(data) > _level + 1: if len(data) != _level + 2: - if _module in seen: - continue - print(output) raise RuntimeError( f"Error processing line '{line}': unexpected unindent" ) @@ -62,19 +78,84 @@ def collect_import_time(module): (k if '(from' in k else "%s (from %s)" % (k, _module), v) for k, v in inner.tpl.items() } - if _module.startswith('pyomo'): + if _module.startswith(basemodule): data[_level].update(inner) - data[_level].pyomo[_module] = _self + data[_level].module[_module] = _self else: - if _level > 0: - data[_level].tpl[_module] = _cumul - elif _module.startswith('pyomo'): - data[_level].pyomo[_module] = _self - elif _level > 0: + # if _level > 0: + data[_level].tpl[_module] = _cumul + elif _module.startswith(basemodule): + data[_level].module[_module] = _self + else: # if _level > 0: data[_level].tpl[_module] = _self - seen.add(_module) - assert len(data) == 1 - return data[0] + ans = None + for d in results: + assert len(d) == 1 + d = d[0] + if not d.module: + continue + if ans: + raise RuntimeError( + "Multiple timing results imported target module '{module}'" + ) + ans = d + return ans + + +def summarize_import_time(module, data): + modname = module.split('.')[0] + + N = int(math.log10(max(max(data.module.values()), max(data.tpl.values())))) + 4 + print(f"{modname.title()} (by module time):") + print( + "\n".join( + f"%{N}d: %s" % (v, k) + for k, v in sorted(data.module.items(), key=lambda x: x[1]) + ) + ) + tpls = sorted( + (*_mod.split(' ', maxsplit=1), '', _time) for _mod, _time in data.tpl.items() + ) + print("TPLS:") + _line_fmt = f" %{max(len(l[0]) for l in tpls)}s: %6d %s" + print("\n".join(_line_fmt % (l[0], l[-1], l[1]) for l in tpls)) + tpl = {} + for k, v in data.tpl.items(): + _mod = k.split()[0].split('.')[0] + _base_time, _base_cat = tpl.get(_mod, (0, 0)) + tpl[_mod] = _base_time + v, _base_cat | (1 if ' ' in k else 2) + tpl_by_time = sorted(tpl.items(), key=lambda x: x[1]) + + pyomo_time = sum(data.module.values()) + tpl_time = sum(data.tpl.values()) + total = float(pyomo_time + tpl_time) + python_time = sum(t for m, (t, s) in tpl_by_time if s & 1 == 0) + module_tpl_time = sum(t for m, (t, s) in tpl_by_time if s & 1) + assert abs(python_time + module_tpl_time - tpl_time) < 1 + + print("TPLS (by package time):") + _line_fmt = f" %{max(len(k) for k in tpl)}s: %6d (%4.1f%%)%s" + source = {1: '', 2: ' *', 3: ' *+'} + print( + "\n".join( + _line_fmt % (m, t, 100 * t / total, source[s]) for m, (t, s) in tpl_by_time + ) + ) + N = len(modname) + 8 + print( + f"\n%-{N}s %6d (%4.1f%%)" + % (f"{modname.title()}:", pyomo_time, 100 * pyomo_time / total) + ) + print( + f"%-{N}s %6d (%4.1f%%)" + % (f"TPL ({modname}):", module_tpl_time, 100 * module_tpl_time / total) + ) + print( + f"%-{N}s %6d (%4.1f%%)" + % ("TPL (python):", python_time, 100 * python_time / total) + ) + + return python_time, module_tpl_time, pyomo_time, tpl_by_time class TestPyomoEnviron(unittest.TestCase): @@ -94,47 +175,24 @@ def test_not_auto_imported(self): ) @unittest.skipIf( - 'pypy_version_info' in dir(sys), "PyPy does not support '-X importtime" + 'pypy_version_info' in dir(sys), "PyPy does not support '-X importtime'" ) def test_tpl_import_time(self): - data = collect_import_time('pyomo.environ') - pyomo_time = sum(data.pyomo.values()) - tpl_time = sum(data.tpl.values()) - total = float(pyomo_time + tpl_time) - print("Pyomo (by module time):") - print( - "\n".join( - " %s: %s" % i for i in sorted(data.pyomo.items(), key=lambda x: x[1]) - ) - ) - print("TPLS:") - _line_fmt = " %%%ds: %%6d %%s" % ( - max(len(k[: k.find(' ')]) for k in data.tpl), - ) - print( - "\n".join( - _line_fmt % (k[: k.find(' ')], v, k[k.find(' ') :]) - for k, v in sorted(data.tpl.items()) - ) + data = collect_import_time( + 'pyomo.environ', + # pre-load and pre-start multiprocessing so that the + # asynchronous task triggered by creating a Lock will not be + # interleaved in the importtime report + 'import time, multiprocessing; multiprocessing.Lock(); time.sleep(0.1)', ) - tpl = {} - for k, v in data.tpl.items(): - _mod = k[: k.find(' ')].split('.')[0] - tpl[_mod] = tpl.get(_mod, 0) + v - tpl_by_time = sorted(tpl.items(), key=lambda x: x[1]) - print("TPLS (by package time):") - print( - "\n".join( - " %15s: %6d (%4.1f%%)" % (m, t, 100 * t / total) - for m, t in tpl_by_time - ) + python_time, module_tpl_time, pyomo_time, tpl_by_time = summarize_import_time( + 'pyomo.environ', data ) - print("Pyomo: %6d (%4.1f%%)" % (pyomo_time, 100 * pyomo_time / total)) - print("TPL: %6d (%4.1f%%)" % (tpl_time, 100 * tpl_time / total)) + # Arbitrarily choose a threshold 10% more than the expected # value (at time of writing, TPL imports were 52-57% of the # import time on a development machine) - self.assertLess(tpl_time / total, 0.65) + self.assertLess(module_tpl_time / (module_tpl_time + pyomo_time), 0.33) # Spot-check the (known) worst offenders. The following are # modules from the "standard" library. Their order in the list # of slow-loading TPLs can vary from platform to platform. @@ -150,6 +208,7 @@ def test_tpl_import_time(self): 'ctypes', # mandatory import in core/base/external.py; TODO: fix this 'datetime', # imported by contrib.solver 'decimal', + 'encodings', # We now tabulate modules imported by python 'gc', # Imported on MacOS, Windows; Linux in 3.10 'glob', 'heapq', # Added in Python 3.10 @@ -162,6 +221,7 @@ def test_tpl_import_time(self): 'pickle', 'platform', 'shlex', + 'site', # We now tabulate modules imported by python 'socket', # Imported on MacOS, Windows; Linux in 3.10 'subprocess', 'tempfile', # Imported on MacOS, Windows From 01be5ce974fac607e6d898e3b13c6c31c0075b93 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Tue, 28 Apr 2026 12:55:18 -0600 Subject: [PATCH 14/28] NFC: apply black --- pyomo/common/tests/test_multithread.py | 1 + 1 file changed, 1 insertion(+) diff --git a/pyomo/common/tests/test_multithread.py b/pyomo/common/tests/test_multithread.py index bc0592a023f..6d948a9f456 100644 --- a/pyomo/common/tests/test_multithread.py +++ b/pyomo/common/tests/test_multithread.py @@ -18,6 +18,7 @@ import pyomo.environ as pyo + class Dummy: """asdfg""" From 00164ee3ad4880475cd34e4ff4c74c0fff55ed53 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Tue, 28 Apr 2026 13:10:18 -0600 Subject: [PATCH 15/28] Debugging --- pyomo/environ/tests/test_environ.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pyomo/environ/tests/test_environ.py b/pyomo/environ/tests/test_environ.py index d0588dc7d20..c5f78757778 100644 --- a/pyomo/environ/tests/test_environ.py +++ b/pyomo/environ/tests/test_environ.py @@ -46,7 +46,7 @@ def collect_import_time(module, preimport=""): ) # Note: test only runs in PY3 output = output.decode() - # print(output) + print(output) line_re = re.compile(r'.*:\s*(\d+) \|\s*(\d+) \| ( *)([^ ]+)') header_re = re.compile(r'.*:\s*(.*)') results = [] From ce60ebc62f84810686a28d3e0843f23b3ba4da85 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Tue, 28 Apr 2026 14:17:04 -0600 Subject: [PATCH 16/28] Remove debugging; increase delay for GHA --- pyomo/environ/tests/test_environ.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/pyomo/environ/tests/test_environ.py b/pyomo/environ/tests/test_environ.py index c5f78757778..7f221e381ed 100644 --- a/pyomo/environ/tests/test_environ.py +++ b/pyomo/environ/tests/test_environ.py @@ -46,7 +46,7 @@ def collect_import_time(module, preimport=""): ) # Note: test only runs in PY3 output = output.decode() - print(output) + # print(output) line_re = re.compile(r'.*:\s*(\d+) \|\s*(\d+) \| ( *)([^ ]+)') header_re = re.compile(r'.*:\s*(.*)') results = [] @@ -183,7 +183,7 @@ def test_tpl_import_time(self): # pre-load and pre-start multiprocessing so that the # asynchronous task triggered by creating a Lock will not be # interleaved in the importtime report - 'import time, multiprocessing; multiprocessing.Lock(); time.sleep(0.1)', + 'import time, multiprocessing; multiprocessing.Lock(); time.sleep(0.25)', ) python_time, module_tpl_time, pyomo_time, tpl_by_time = summarize_import_time( 'pyomo.environ', data From 4c5d03221aabea0034ecea3f2774159f56ad0f5c Mon Sep 17 00:00:00 2001 From: John Siirola Date: Tue, 28 Apr 2026 14:17:20 -0600 Subject: [PATCH 17/28] Clean up multiprocessing imports --- pyomo/common/dependencies.py | 2 -- pyomo/common/tests/test_multithread.py | 2 +- 2 files changed, 1 insertion(+), 3 deletions(-) diff --git a/pyomo/common/dependencies.py b/pyomo/common/dependencies.py index ebe8dd45010..3993b82fc24 100644 --- a/pyomo/common/dependencies.py +++ b/pyomo/common/dependencies.py @@ -1093,8 +1093,6 @@ def _pyutilib_importer(): import pickle # multiprocessing is unconditionally needed by capture_output import multiprocessing - import multiprocessing.dummy - import multiprocessing.resource_tracker # Standard libraries that are slower to import and not strictly required # on all platforms / situations. diff --git a/pyomo/common/tests/test_multithread.py b/pyomo/common/tests/test_multithread.py index 6d948a9f456..b290b6307eb 100644 --- a/pyomo/common/tests/test_multithread.py +++ b/pyomo/common/tests/test_multithread.py @@ -9,10 +9,10 @@ import threading from threading import Thread +from multiprocessing.dummy import Pool as ThreadPool import pyomo.common.unittest as unittest -from pyomo.common.dependencies.multiprocessing.dummy import Pool as ThreadPool from pyomo.common.multithread import MultiThreadWrapper, MultiThreadWrapperWithMain from pyomo.opt.base.solvers import check_available_solvers From 63635b17ad49aba1a8ce304a0ae62b7f4e6d8f17 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Mon, 18 May 2026 16:23:22 -0600 Subject: [PATCH 18/28] Remove required import of multiprocessing --- pyomo/common/dependencies.py | 27 +++++++++++++++++++++++++-- pyomo/common/tee.py | 17 +++++------------ pyomo/common/tests/test_tee.py | 14 +++++++++----- pyomo/environ/tests/test_environ.py | 12 ++++++++---- 4 files changed, 47 insertions(+), 23 deletions(-) diff --git a/pyomo/common/dependencies.py b/pyomo/common/dependencies.py index 3993b82fc24..08f84537e11 100644 --- a/pyomo/common/dependencies.py +++ b/pyomo/common/dependencies.py @@ -945,6 +945,16 @@ def __exit__(self, exc_type, exc_value, traceback): # Common optional dependencies used throughout Pyomo # + +class _DummyLock: + def acquire(self, timeout): + return True + + def release(self): + pass + + +capture_output_lock = _DummyLock() yaml_load_args = {} @@ -961,6 +971,18 @@ def _finalize_ctypes(module, available): import ctypes.util +def _finalize_multiprocessing(module, available): + # Note: multiprocessing is very slow to import, but we need to make + # sure that the capture_output_lock Lock is created *before* the + # user spawns any subprocesses. tee.capture_output will look here + # for the lock, which will start out as a "dummy" lock, and then + # will be updated to a multiprocessing.Lock when the forst module + # triggers the multiprocessing import. + + global capture_output_lock + capture_output_lock = module.Lock() + + def _finalize_scipy(module, available): if available: # Import key subpackages that we will want to assume are present @@ -1091,14 +1113,15 @@ def _pyutilib_importer(): import cPickle as pickle except ImportError: import pickle - # multiprocessing is unconditionally needed by capture_output - import multiprocessing # Standard libraries that are slower to import and not strictly required # on all platforms / situations. ctypes, _ = attempt_import( 'ctypes', deferred_submodules=['util'], callback=_finalize_ctypes ) + multiprocessing, _ = attempt_import( + 'multiprocessing', callback=_finalize_multiprocessing + ) random, _ = attempt_import('random') # Necessary for minimum version checking for other optional dependencies diff --git a/pyomo/common/tee.py b/pyomo/common/tee.py index 76cb0935476..c679771cb99 100644 --- a/pyomo/common/tee.py +++ b/pyomo/common/tee.py @@ -22,12 +22,7 @@ import threading import time -# Note: multiprocessing is very slow to import, but we need to make sure -# that the startup_shutdown Lock is created *before* the user spawns any -# subprocesses. Therefore, we will bite the bullet and import it so -# we can create the Lock immediately when we import this module. -from pyomo.common.dependencies import multiprocessing - +import pyomo.common.dependencies as dependencies from pyomo.common.errors import DeveloperError from pyomo.common.log import LoggingIntercept, LogStream from pyomo.common.shutdown import python_is_shutting_down @@ -305,8 +300,6 @@ class capture_output: """ - startup_shutdown = multiprocessing.Lock() - def __init__(self, output=None, capture_fd=False): self.output = output self.output_stream = None @@ -352,7 +345,7 @@ def _exit_context_stack(self, et, ev, tb): return FAIL def __enter__(self): - if not capture_output.startup_shutdown.acquire(timeout=_threading_deadlock): + if not dependencies.capture_output_lock.acquire(timeout=_threading_deadlock): # This situation *shouldn't* happen. If it does, it is # unlikely that the user can fix it (or even debug it). # Instead they should report it back to us. @@ -370,17 +363,17 @@ def __enter__(self): try: return self._enter_impl() finally: - capture_output.startup_shutdown.release() + dependencies.capture_output_lock.release() def __exit__(self, et, ev, tb): - if not capture_output.startup_shutdown.acquire(timeout=_threading_deadlock): + if not dependencies.capture_output_lock.acquire(timeout=_threading_deadlock): # See comments & breadcrumbs in __enter__() above. if not python_is_shutting_down(): raise DeveloperError("Deadlock closing capture_output") try: return self._exit_impl(et, ev, tb) finally: - capture_output.startup_shutdown.release() + dependencies.capture_output_lock.release() def _enter_impl(self): self.old = (sys.stdout, sys.stderr) diff --git a/pyomo/common/tests/test_tee.py b/pyomo/common/tests/test_tee.py index b2fdedc73b6..9c45a5353ba 100644 --- a/pyomo/common/tests/test_tee.py +++ b/pyomo/common/tests/test_tee.py @@ -21,6 +21,7 @@ from pyomo.common.errors import DeveloperError from pyomo.common.log import LoggingIntercept, LogStream from pyomo.common.tempfiles import TempfileManager +import pyomo.common.dependencies as deps import pyomo.common.tee as tee import pyomo.common.unittest as unittest @@ -584,21 +585,24 @@ def test_atomic_deadlock(self): save_poll = tee._threading_deadlock tee._threading_deadlock = 0.01 + # Ensure multiprocessing is loaded: + deps.multiprocessing.Lock + co = tee.capture_output() try: - tee.capture_output.startup_shutdown.acquire() + deps.capture_output_lock.acquire() with self.assertRaisesRegex( DeveloperError, "Deadlock starting capture_output" ): with tee.capture_output(): pass - tee.capture_output.startup_shutdown.release() + deps.capture_output_lock.release() with self.assertRaisesRegex( DeveloperError, "Deadlock closing capture_output" ): with co: - tee.capture_output.startup_shutdown.acquire() + deps.capture_output_lock.acquire() finally: tee._threading_deadlock = save_poll # We would like to just test if out Lock was acquired and @@ -607,9 +611,9 @@ def test_atomic_deadlock(self): # just catch and eat the error for releasing an unlocked # lock. # - ## if tee.capture_output.startup_shutdown.locked(): + ## if deps.capture_output_lock.locked(): try: - tee.capture_output.startup_shutdown.release() + deps.capture_output_lock.release() except ValueError: pass co.reset() diff --git a/pyomo/environ/tests/test_environ.py b/pyomo/environ/tests/test_environ.py index 7f221e381ed..f4ddf599134 100644 --- a/pyomo/environ/tests/test_environ.py +++ b/pyomo/environ/tests/test_environ.py @@ -180,10 +180,15 @@ def test_not_auto_imported(self): def test_tpl_import_time(self): data = collect_import_time( 'pyomo.environ', - # pre-load and pre-start multiprocessing so that the + # We used to pre-load and pre-start multiprocessing so that the # asynchronous task triggered by creating a Lock will not be - # interleaved in the importtime report - 'import time, multiprocessing; multiprocessing.Lock(); time.sleep(0.25)', + # interleaved in the importtime report: + # + ##'import time, multiprocessing; multiprocessing.Lock(); time.sleep(0.25)', + # + # This is no longer needed as we have removed + # multiprocessing from the list of required modules for + # pyomo.environ. ) python_time, module_tpl_time, pyomo_time, tpl_by_time = summarize_import_time( 'pyomo.environ', data @@ -217,7 +222,6 @@ def test_tpl_import_time(self): 'json', # Imported on Windows 'locale', # Added in Python 3.9 'logging', - 'multiprocessing', # capture_output requires multiprocessing.Lock 'pickle', 'platform', 'shlex', From 61ffa306002ceec69eb58b612975332958e88f67 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Mon, 18 May 2026 16:34:14 -0600 Subject: [PATCH 19/28] Use a threading.Lock until multiprocessing is imported --- pyomo/common/dependencies.py | 16 ++++++---------- 1 file changed, 6 insertions(+), 10 deletions(-) diff --git a/pyomo/common/dependencies.py b/pyomo/common/dependencies.py index 08f84537e11..da4fb843320 100644 --- a/pyomo/common/dependencies.py +++ b/pyomo/common/dependencies.py @@ -12,6 +12,7 @@ import importlib.util import logging import sys +import threading import warnings from collections.abc import Mapping @@ -945,16 +946,11 @@ def __exit__(self, exc_type, exc_value, traceback): # Common optional dependencies used throughout Pyomo # - -class _DummyLock: - def acquire(self, timeout): - return True - - def release(self): - pass - - -capture_output_lock = _DummyLock() +#: lock for deconflicting access to capturing the process file +#: descriptors. This starts as a threading.Lock, unless the environment +#: imports multiprocessing, in which case, it is upgraded to a +#: multiprocessing lock. +capture_output_lock = threading.Lock() yaml_load_args = {} From 5e7ad72e666eeda2a1eaceab08fb9a3429cbf8c5 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Mon, 18 May 2026 17:07:49 -0600 Subject: [PATCH 20/28] NFC: fix typo --- pyomo/common/dependencies.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pyomo/common/dependencies.py b/pyomo/common/dependencies.py index da4fb843320..07452649858 100644 --- a/pyomo/common/dependencies.py +++ b/pyomo/common/dependencies.py @@ -972,7 +972,7 @@ def _finalize_multiprocessing(module, available): # sure that the capture_output_lock Lock is created *before* the # user spawns any subprocesses. tee.capture_output will look here # for the lock, which will start out as a "dummy" lock, and then - # will be updated to a multiprocessing.Lock when the forst module + # will be updated to a multiprocessing.Lock when the first module # triggers the multiprocessing import. global capture_output_lock From 8afd437b3a6648a5ebf41d1b925ef0ddbf4d3e4a Mon Sep 17 00:00:00 2001 From: John Siirola Date: Tue, 19 May 2026 10:28:44 -0600 Subject: [PATCH 21/28] Update references to capture_output_lock --- pyomo/common/tests/test_unittest.py | 7 ++++--- pyomo/common/unittest.py | 11 ++++++----- 2 files changed, 10 insertions(+), 8 deletions(-) diff --git a/pyomo/common/tests/test_unittest.py b/pyomo/common/tests/test_unittest.py index 9b361ddd356..78c12215a68 100644 --- a/pyomo/common/tests/test_unittest.py +++ b/pyomo/common/tests/test_unittest.py @@ -13,6 +13,7 @@ import time import pyomo.common.unittest as unittest +import pyomo.common.dependencies as deps from pyomo.common.dependencies import multiprocessing from pyomo.common.log import LoggingIntercept from pyomo.common.tee import capture_output @@ -177,7 +178,7 @@ def test_timeout_fcn_call(self): ): long_sleep() self.assertEqual(LOG.getvalue(), "") - capture_output.startup_shutdown.acquire() + deps.capture_output_lock.acquire() save = unittest._timeout_terminate_timeout unittest._timeout_terminate_timeout = 0.01 try: @@ -187,10 +188,10 @@ def test_timeout_fcn_call(self): long_sleep() finally: unittest._timeout_terminate_timeout = save - capture_output.startup_shutdown.release() + deps.capture_output_lock.release() self.assertEqual( LOG.getvalue(), - "Failed to acquire capture_output.startup_shutdown Lock before " + "Failed to acquire capture_output_lock Lock before " "terminating subprocess on timeout: process deadlock is likely.\n", ) with self.assertRaisesRegex( diff --git a/pyomo/common/unittest.py b/pyomo/common/unittest.py index 6576c4c0627..4bf4df76ef5 100644 --- a/pyomo/common/unittest.py +++ b/pyomo/common/unittest.py @@ -29,6 +29,7 @@ # specifically later from unittest import * import unittest as _unittest +import pyomo.common.dependencies as deps from pyomo.common.collections import Mapping, Sequence from pyomo.common.dependencies import attempt_import, check_min_version, multiprocessing @@ -44,7 +45,7 @@ # (and then enforce a strict dependence on pytest) pytest, pytest_available = attempt_import('pytest') -#: A time limit for acquiring the capture_output.startup_shutdown lock +#: A time limit for acquiring the capture_output_lock lock #: before terminating a subprocess _timeout_terminate_timeout = 2 # seconds @@ -494,16 +495,16 @@ def test_timer(*args, **kwargs): # Note: because we are using capture_output within # the _runner handler, we can trigger a deadlock # when we call terminate() while the _runner's - # capture_output holds the startup_shutdown lock + # capture_output holds the capture_output_lock lock # (terminate() bypasses all __exit__ handlers!). To # avoid that, we will grab the lock here before # terminating the subprocess. - locked = capture_output.startup_shutdown.acquire( + locked = deps.capture_output_lock.acquire( timeout=_timeout_terminate_timeout ) if not locked: logging.getLogger(__name__).error( - "Failed to acquire capture_output.startup_shutdown " + "Failed to acquire capture_output_lock " "Lock before terminating subprocess on timeout: " "process deadlock is likely." ) @@ -511,7 +512,7 @@ def test_timer(*args, **kwargs): test_proc.terminate() finally: if locked: - capture_output.startup_shutdown.release() + deps.capture_output_lock.release() raise timeout_raises( "test timed out after %s seconds" % (seconds,) ) from None From f31df34efd880ee537b10b02b3511545c2523110 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Tue, 19 May 2026 12:14:56 -0600 Subject: [PATCH 22/28] Add debugging to environ summary --- pyomo/environ/tests/test_environ.py | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/pyomo/environ/tests/test_environ.py b/pyomo/environ/tests/test_environ.py index f4ddf599134..4d4f8b92eb8 100644 --- a/pyomo/environ/tests/test_environ.py +++ b/pyomo/environ/tests/test_environ.py @@ -99,10 +99,13 @@ def collect_import_time(module, preimport=""): "Multiple timing results imported target module '{module}'" ) ans = d - return ans + return ans, output -def summarize_import_time(module, data): +def summarize_import_time(module, data, raw_output): + print(raw_output) + print("\n") + modname = module.split('.')[0] N = int(math.log10(max(max(data.module.values()), max(data.tpl.values())))) + 4 @@ -178,7 +181,7 @@ def test_not_auto_imported(self): 'pypy_version_info' in dir(sys), "PyPy does not support '-X importtime'" ) def test_tpl_import_time(self): - data = collect_import_time( + data, output = collect_import_time( 'pyomo.environ', # We used to pre-load and pre-start multiprocessing so that the # asynchronous task triggered by creating a Lock will not be @@ -191,7 +194,7 @@ def test_tpl_import_time(self): # pyomo.environ. ) python_time, module_tpl_time, pyomo_time, tpl_by_time = summarize_import_time( - 'pyomo.environ', data + 'pyomo.environ', data, output ) # Arbitrarily choose a threshold 10% more than the expected From b0579233d1bc999be9092811c546e0069c84ff1d Mon Sep 17 00:00:00 2001 From: John Siirola Date: Tue, 19 May 2026 14:39:23 -0600 Subject: [PATCH 23/28] Disable coverage when testing importtime --- pyomo/environ/tests/test_environ.py | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/pyomo/environ/tests/test_environ.py b/pyomo/environ/tests/test_environ.py index 4d4f8b92eb8..71f36d7b17c 100644 --- a/pyomo/environ/tests/test_environ.py +++ b/pyomo/environ/tests/test_environ.py @@ -11,6 +11,7 @@ # import math +import os import re import sys import subprocess @@ -41,8 +42,12 @@ def collect_import_time(module, preimport=""): cmd = f"{preimport}; import {module}" else: cmd = f"import {module}" + env = dict(os.environ) + env.pop('COVERAGE_PROCESS_START', None) output = subprocess.check_output( - [sys.executable, '-X', 'importtime', '-c', cmd], stderr=subprocess.STDOUT + [sys.executable, '-X', 'importtime', '-c', cmd], + stderr=subprocess.STDOUT, + env=env, ) # Note: test only runs in PY3 output = output.decode() From ba4d83b9db51628ae326958be0b446389da50a2f Mon Sep 17 00:00:00 2001 From: John Siirola Date: Tue, 19 May 2026 16:50:20 -0600 Subject: [PATCH 24/28] Remove unused dependency --- pyomo/contrib/solver/solvers/gams.py | 1 - 1 file changed, 1 deletion(-) diff --git a/pyomo/contrib/solver/solvers/gams.py b/pyomo/contrib/solver/solvers/gams.py index 716872c9d89..ddfd23f4d96 100644 --- a/pyomo/contrib/solver/solvers/gams.py +++ b/pyomo/contrib/solver/solvers/gams.py @@ -16,7 +16,6 @@ import sys import struct import re -import pathlib from pyomo.common.dependencies import attempt_import from pyomo.common.errors import InfeasibleConstraintException From 63974f8a07502c31968a99a90704f6ce39622e1a Mon Sep 17 00:00:00 2001 From: John Siirola Date: Tue, 19 May 2026 16:50:53 -0600 Subject: [PATCH 25/28] Importtime tests: prevent import of site pth files --- pyomo/environ/tests/test_environ.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/pyomo/environ/tests/test_environ.py b/pyomo/environ/tests/test_environ.py index 71f36d7b17c..6aaf14732ff 100644 --- a/pyomo/environ/tests/test_environ.py +++ b/pyomo/environ/tests/test_environ.py @@ -45,7 +45,7 @@ def collect_import_time(module, preimport=""): env = dict(os.environ) env.pop('COVERAGE_PROCESS_START', None) output = subprocess.check_output( - [sys.executable, '-X', 'importtime', '-c', cmd], + [sys.executable, '-S', '-X', 'importtime', '-c', cmd], stderr=subprocess.STDOUT, env=env, ) @@ -217,23 +217,24 @@ def test_tpl_import_time(self): 'base64', # Imported on Windows 'bisect', # Imported by dae, dataportal, contrib/mpc 'cPickle', + 'copy', # Imported by ply, et al. 'csv', 'ctypes', # mandatory import in core/base/external.py; TODO: fix this 'datetime', # imported by contrib.solver 'decimal', - 'encodings', # We now tabulate modules imported by python + 'encodings', # We tabulate modules imported by python 'gc', # Imported on MacOS, Windows; Linux in 3.10 'glob', 'heapq', # Added in Python 3.10 'importlib', 'inspect', + 'io', 'json', # Imported on Windows 'locale', # Added in Python 3.9 'logging', 'pickle', 'platform', 'shlex', - 'site', # We now tabulate modules imported by python 'socket', # Imported on MacOS, Windows; Linux in 3.10 'subprocess', 'tempfile', # Imported on MacOS, Windows From 6089c5309da01bc3c7787983b58f0a8da86c6ce1 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Tue, 19 May 2026 16:54:42 -0600 Subject: [PATCH 26/28] Convert commented test to 'documentation' --- pyomo/environ/tests/test_environ.py | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/pyomo/environ/tests/test_environ.py b/pyomo/environ/tests/test_environ.py index 6aaf14732ff..dd9e895ab36 100644 --- a/pyomo/environ/tests/test_environ.py +++ b/pyomo/environ/tests/test_environ.py @@ -51,7 +51,6 @@ def collect_import_time(module, preimport=""): ) # Note: test only runs in PY3 output = output.decode() - # print(output) line_re = re.compile(r'.*:\s*(\d+) \|\s*(\d+) \| ( *)([^ ]+)') header_re = re.compile(r'.*:\s*(.*)') results = [] @@ -86,12 +85,11 @@ def collect_import_time(module, preimport=""): if _module.startswith(basemodule): data[_level].update(inner) data[_level].module[_module] = _self - else: - # if _level > 0: + else: # _level > 0: data[_level].tpl[_module] = _cumul elif _module.startswith(basemodule): data[_level].module[_module] = _self - else: # if _level > 0: + else: # _level > 0: data[_level].tpl[_module] = _self ans = None for d in results: From 4c64b30a2311f840cf7867d733deb5c424db4211 Mon Sep 17 00:00:00 2001 From: John Siirola Date: Tue, 19 May 2026 20:01:16 -0600 Subject: [PATCH 27/28] Preserve PYTHONPATH when running importtime test --- pyomo/environ/tests/test_environ.py | 1 + 1 file changed, 1 insertion(+) diff --git a/pyomo/environ/tests/test_environ.py b/pyomo/environ/tests/test_environ.py index dd9e895ab36..cea66290ae6 100644 --- a/pyomo/environ/tests/test_environ.py +++ b/pyomo/environ/tests/test_environ.py @@ -43,6 +43,7 @@ def collect_import_time(module, preimport=""): else: cmd = f"import {module}" env = dict(os.environ) + env['PYTHONPATH'] = os.pathsep.join(filter(None, sys.path)) env.pop('COVERAGE_PROCESS_START', None) output = subprocess.check_output( [sys.executable, '-S', '-X', 'importtime', '-c', cmd], From b8a1608dfc8dea4ab134eb1c0010362709e6223f Mon Sep 17 00:00:00 2001 From: John Siirola Date: Thu, 21 May 2026 00:21:30 -0600 Subject: [PATCH 28/28] Add global flag to (partially) disable capture_output --- pyomo/common/enums.py | 27 +++++++++++++++++++++++++++ pyomo/common/tee.py | 14 +++++++++++--- pyomo/common/tests/test_tee.py | 16 ++++++++++++++++ 3 files changed, 54 insertions(+), 3 deletions(-) diff --git a/pyomo/common/enums.py b/pyomo/common/enums.py index 7290d9ba545..a08b3e7be68 100644 --- a/pyomo/common/enums.py +++ b/pyomo/common/enums.py @@ -249,3 +249,30 @@ class SolverAPIVersion(NamedIntEnum): minimize = ObjectiveSense.minimize maximize = ObjectiveSense.maximize + + +class CaptureOutputMode(IntEnum): + """Enum to override the default behavior of the :class:`capture_output` + context manager. + + This enum provides options for overriding the behavior of the + :class:`capture_output` context manager through the + :attr:`~pyomo.common.tee.OVERRIDE_CAPTURE_OUTPUT` flag. + + """ + + #: Setting this mode will cause :class:`capture_output` to be a noop + DISABLE = 0 + #: :class:`capture_output` will capture the standard ``sys.stdout`` / + #: ``sys.stderr`` streams + ENABLE_STREAM_CAPTURE = 1 + #: :class:`capture_output` will capture the file descriptors that + #: underlie the standard ``sys.stdout`` / ``sys.stderr`` streams + ENABLE_FD_CAPTURE = 2 + #: This is :class:`capture_output`'s normal operation (all capturing is enabled) + NORMAL = 3 + #: :class:`capture_output` will capture the standard ``sys.stdout`` / + #: ``sys.stderr`` streams, but will not attempt to capture their raw + #: file descriptors (regardless of the value of `capture_fd`) [alias + #: of ENABLE_STREAM_CAPTURE] + DISABLE_FD_CAPTURE = 1 diff --git a/pyomo/common/tee.py b/pyomo/common/tee.py index c679771cb99..e4dd15c5a99 100644 --- a/pyomo/common/tee.py +++ b/pyomo/common/tee.py @@ -23,6 +23,7 @@ import time import pyomo.common.dependencies as dependencies +from pyomo.common.enums import CaptureOutputMode from pyomo.common.errors import DeveloperError from pyomo.common.log import LoggingIntercept, LogStream from pyomo.common.shutdown import python_is_shutting_down @@ -57,6 +58,8 @@ logger = logging.getLogger(__name__) +OVERRIDE_CAPTURE_OUTPUT = CaptureOutputMode.NORMAL + class _SignalFlush: def __init__(self, ostream, handle): @@ -305,7 +308,9 @@ def __init__(self, output=None, capture_fd=False): self.output_stream = None self.old = None self.tee = None - self.capture_fd = capture_fd + self.capture_fd = capture_fd and ( + OVERRIDE_CAPTURE_OUTPUT & CaptureOutputMode.ENABLE_FD_CAPTURE + ) self.context_stack = [] def _enter_context(self, cm, prior_to=None): @@ -488,8 +493,11 @@ def _enter_impl(self): # exception. self._exit_context_stack(*sys.exc_info()) raise - sys.stdout = self.tee.STDOUT - sys.stderr = self.tee.STDERR + if OVERRIDE_CAPTURE_OUTPUT & CaptureOutputMode.ENABLE_STREAM_CAPTURE: + sys.stdout = self.tee.STDOUT + sys.stderr = self.tee.STDERR + else: + self.old = None buf = self.tee.ostreams if len(buf) == 1: buf = buf[0] diff --git a/pyomo/common/tests/test_tee.py b/pyomo/common/tests/test_tee.py index 9c45a5353ba..d07f0042503 100644 --- a/pyomo/common/tests/test_tee.py +++ b/pyomo/common/tests/test_tee.py @@ -723,6 +723,22 @@ def flush(self): finally: tee._poll_timeout, tee._poll_timeout_deadlock = _save + def test_capture_output_override(self): + capture1 = tee.capture_output(capture_fd=True) + self.assertTrue(capture1.capture_fd) + with capture1 as OUT1: + try: + orig = tee.OVERRIDE_CAPTURE_OUTPUT + tee.OVERRIDE_CAPTURE_OUTPUT = tee.CaptureOutputMode.DISABLE + capture2 = tee.capture_output(capture_fd=True) + with capture2 as OUT2: + self.assertFalse(capture2.capture_fd) + print("Hello, World") + self.assertEqual(OUT2.getvalue(), "") + finally: + tee.OVERRIDE_CAPTURE_OUTPUT = orig + self.assertEqual(OUT1.getvalue(), "Hello, World\n") + class BufferTester: def setUp(self):