Attempt to merge mlbynum's changes / main

pyomo/common/collections/component_map.py

@@ -91,6 +91,13 @@ def __len__(self):
     # Overload MutableMapping default implementations
     #
 
+    # We want a specialization of update() to avoid unnecessary calls to
+    # id() when copying / merging ComponentMaps
+    def update(self, *args, **kwargs):
+        if len(args) == 1 and not kwargs and isinstance(args[0], ComponentMap):
+            return self._dict.update(args[0]._dict)
+        return super().update(*args, **kwargs)
+
     # We want to avoid generating Pyomo expressions due to
     # comparison of values, so we convert both objects to a
     # plain dictionary mapping key->(type(val), id(val)) and

pyomo/common/tests/test_timing.py

@@ -14,6 +14,7 @@
 
 import gc
 from io import StringIO
+from itertools import zip_longest
 import logging
 import sys
 import time
@@ -26,7 +27,14 @@
     TicTocTimer,
     HierarchicalTimer,
 )
-from pyomo.environ import ConcreteModel, RangeSet, Var, Any, TransformationFactory
+from pyomo.environ import (
+    AbstractModel,
+    ConcreteModel,
+    RangeSet,
+    Var,
+    Any,
+    TransformationFactory,
+)
 from pyomo.core.base.var import _VarData
 
 
@@ -132,6 +140,48 @@ def test_report_timing(self):
                 self.assertRegex(str(l.strip()), str(r.strip()))
             self.assertEqual(buf.getvalue().strip(), "")
 
+    def test_report_timing_context_manager(self):
+        ref = r"""
+           (0(\.\d+)?) seconds to construct Var x; 2 indices total
+           (0(\.\d+)?) seconds to construct Var y; 0 indices total
+           (0(\.\d+)?) seconds to construct Suffix Suffix
+           (0(\.\d+)?) seconds to apply Transformation RelaxIntegerVars \(in-place\)
+           """.strip()
+
+        xfrm = TransformationFactory('core.relax_integer_vars')
+
+        model = AbstractModel()
+        model.r = RangeSet(2)
+        model.x = Var(model.r)
+        model.y = Var(Any, dense=False)
+
+        OS = StringIO()
+
+        with report_timing(False):
+            with report_timing(OS):
+                with report_timing(False):
+                    # Active reporting is False: nothing should be emitted
+                    with capture_output() as OUT:
+                        m = model.create_instance()
+                        xfrm.apply_to(m)
+                    self.assertEqual(OUT.getvalue(), "")
+                    self.assertEqual(OS.getvalue(), "")
+                # Active reporting: we should log the timing
+                with capture_output() as OUT:
+                    m = model.create_instance()
+                    xfrm.apply_to(m)
+                self.assertEqual(OUT.getvalue(), "")
+                result = OS.getvalue().strip()
+                self.maxDiff = None
+                for l, r in zip_longest(result.splitlines(), ref.splitlines()):
+                    self.assertRegex(str(l.strip()), str(r.strip()))
+            # Active reporting is False: the previous log should not have changed
+            with capture_output() as OUT:
+                m = model.create_instance()
+                xfrm.apply_to(m)
+            self.assertEqual(OUT.getvalue(), "")
+            self.assertEqual(result, OS.getvalue().strip())
+
     def test_TicTocTimer_tictoc(self):
         SLEEP = 0.1
         RES = 0.02  # resolution (seconds): 1/5 the sleep

pyomo/common/timing.py

@@ -44,30 +44,59 @@
 _transform_logger = logging.getLogger('pyomo.common.timing.transformation')
 
 
-def report_timing(stream=True, level=logging.INFO):
-    """Set reporting of Pyomo timing information.
+class report_timing(object):
+    def __init__(self, stream=True, level=logging.INFO):
+        """Set reporting of Pyomo timing information.
 
-    Parameters
-    ----------
-    stream: bool, TextIOBase
-        The destination stream to emit timing information.  If ``True``,
-        defaults to ``sys.stdout``.  If ``False`` or ``None``, disables
-        reporting of timing information.
-    level: int
-        The logging level for the timing logger
-    """
-    if stream:
-        _logger.setLevel(level)
-        if stream is True:
-            stream = sys.stdout
-        handler = logging.StreamHandler(stream)
-        handler.setFormatter(logging.Formatter("      %(message)s"))
-        _logger.addHandler(handler)
-        return handler
-    else:
-        _logger.setLevel(logging.WARNING)
-        for h in _logger.handlers:
-            _logger.removeHandler(h)
+        For historical reasons, this class may be used as a function
+        (the reporting logger is configured as part of the instance
+        initializer).  However, the preferred usage is as a context
+        manager (thereby ensuring that the timing logger is restored
+        upon exit).
+
+        Parameters
+        ----------
+        stream: bool, TextIOBase
+
+            The destination stream to emit timing information.  If
+            ``True``, defaults to ``sys.stdout``.  If ``False`` or
+            ``None``, disables reporting of timing information.
+
+        level: int
+
+            The logging level for the timing logger
+
+        """
+        self._old_level = _logger.level
+        # For historical reasons (because report_timing() used to be a
+        # function), we will do what you think should be done in
+        # __enter__ here in __init__.
+        if stream:
+            _logger.setLevel(level)
+            if stream is True:
+                stream = sys.stdout
+            self._handler = logging.StreamHandler(stream)
+            self._handler.setFormatter(logging.Formatter("      %(message)s"))
+            _logger.addHandler(self._handler)
+        else:
+            self._handler = list(_logger.handlers)
+            _logger.setLevel(logging.WARNING)
+            for h in list(_logger.handlers):
+                _logger.removeHandler(h)
+
+    def reset(self):
+        _logger.setLevel(self._old_level)
+        if type(self._handler) is list:
+            for h in self._handler:
+                _logger.addHandler(h)
+        else:
+            _logger.removeHandler(self._handler)
+
+    def __enter__(self):
+        return self
+
+    def __exit__(self, et, ev, tb):
+        self.reset()
 
 
 class GeneralTimer(object):
@@ -194,19 +223,14 @@ def __str__(self):
 #
 # Setup the timer
 #
-# TODO: Remove this bit for Pyomo 6.0 - we won't care about older versions
-if sys.version_info >= (3, 3):
-    # perf_counter is guaranteed to be monotonic and the most accurate timer
-    default_timer = time.perf_counter
-elif sys.platform.startswith('win'):
-    # On old Pythons, clock() is more accurate than time() on Windows
-    # (.35us vs 15ms), but time() is more accurate than clock() on Linux
-    # (1ns vs 1us).  It is unfortunate that time() is not monotonic, but
-    # since the TicTocTimer is used for (potentially very accurate)
-    # timers, we will sacrifice monotonicity on Linux for resolution.
-    default_timer = time.clock
-else:
-    default_timer = time.time
+# perf_counter is guaranteed to be monotonic and the most accurate
+# timer.  It became available in Python 3.3.  Prior to that, clock() was
+# more accurate than time() on Windows (.35us vs 15ms), but time() was
+# more accurate than clock() on Linux (1ns vs 1us).  It is unfortunate
+# that time() is not monotonic, but since the TicTocTimer is used for
+# (potentially very accurate) timers, we will sacrifice monotonicity on
+# Linux for resolution.
+default_timer = time.perf_counter
 
 
 class TicTocTimer(object):

pyomo/contrib/appsi/solvers/tests/test_ipopt_persistent.py

@@ -11,7 +11,7 @@ def test_external_function(self):
         if not DLL:
             self.skipTest('Could not find the amplgls.dll library')
 
-        opt = pe.SolverFactory('appsi_ipopt')
+        opt = pe.SolverFactory('ipopt_v2')
         if not opt.available(exception_flag=False):
             raise unittest.SkipTest
 
@@ -31,7 +31,7 @@ def test_external_function_in_objective(self):
         if not DLL:
             self.skipTest('Could not find the amplgls.dll library')
 
-        opt = pe.SolverFactory('appsi_ipopt')
+        opt = pe.SolverFactory('ipopt_v2')
         if not opt.available(exception_flag=False):
             raise unittest.SkipTest
 

pyomo/core/base/PyomoModel.py

@@ -40,6 +40,7 @@
 
 from pyomo.opt.results import SolverResults, Solution, SolverStatus, UndefinedData
 
+from contextlib import nullcontext
 from io import StringIO
 
 logger = logging.getLogger('pyomo.core')
@@ -691,9 +692,6 @@ def create_instance(
         if self.is_constructed():
             return self.clone()
 
-        if report_timing:
-            timing.report_timing()
-
         if name is None:
             # Preserve only the local name (not the FQ name, as that may
             # have been quoted or otherwise escaped)
@@ -709,42 +707,44 @@ def create_instance(
         if data is None:
             data = {}
 
-        #
-        # Clone the model and load the data
-        #
-        instance = self.clone()
+        reporting_context = timing.report_timing if report_timing else nullcontext
+        with reporting_context():
+            #
+            # Clone the model and load the data
+            #
+            instance = self.clone()
 
-        if name is not None:
-            instance._name = name
+            if name is not None:
+                instance._name = name
 
-        # If someone passed a rule for creating the instance, fire the
-        # rule before constructing the components.
-        if instance._rule is not None:
-            instance._rule(instance, next(iter(self.index_set())))
+            # If someone passed a rule for creating the instance, fire the
+            # rule before constructing the components.
+            if instance._rule is not None:
+                instance._rule(instance, next(iter(self.index_set())))
 
-        if namespaces:
-            _namespaces = list(namespaces)
-        else:
-            _namespaces = []
-        if namespace is not None:
-            _namespaces.append(namespace)
-        if None not in _namespaces:
-            _namespaces.append(None)
+            if namespaces:
+                _namespaces = list(namespaces)
+            else:
+                _namespaces = []
+            if namespace is not None:
+                _namespaces.append(namespace)
+            if None not in _namespaces:
+                _namespaces.append(None)
 
-        instance.load(data, namespaces=_namespaces, profile_memory=profile_memory)
+            instance.load(data, namespaces=_namespaces, profile_memory=profile_memory)
 
-        #
-        # Indicate that the model is concrete/constructed
-        #
-        instance._constructed = True
-        #
-        # Change this class from "Abstract" to "Concrete".  It is
-        # absolutely crazy that this is allowed in Python, but since the
-        # AbstractModel and ConcreteModel are basically identical, we
-        # can "reassign" the new concrete instance to be an instance of
-        # ConcreteModel
-        #
-        instance.__class__ = ConcreteModel
+            #
+            # Indicate that the model is concrete/constructed
+            #
+            instance._constructed = True
+            #
+            # Change this class from "Abstract" to "Concrete".  It is
+            # absolutely crazy that this is allowed in Python, but since the
+            # AbstractModel and ConcreteModel are basically identical, we
+            # can "reassign" the new concrete instance to be an instance of
+            # ConcreteModel
+            #
+            instance.__class__ = ConcreteModel
         return instance
 
     @deprecated(

pyomo/core/base/suffix.py

@@ -542,8 +542,8 @@ def __init__(self, name, default=None):
         """
         self.name = name
         self.default = default
-        self._suffixes_by_block = ComponentMap({None: []})
         self.all_suffixes = []
+        self._suffixes_by_block = {None: []}
 
     def find(self, component_data):
         """Find suffix value for a given component data object in model tree