Merge branch 'main' into benchmark

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/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/gdp/disjunct.py

@@ -564,30 +564,31 @@ def set_value(self, expr):
             # IndexedDisjunct indexed by Any which has already been transformed,
             # the new Disjuncts are Blocks already. This catches them for who
             # they are anyway.
-            if isinstance(e, _DisjunctData):
-                self.disjuncts.append(e)
-                continue
-            # The user was lazy and gave us a single constraint
-            # expression or an iterable of expressions
-            expressions = []
-            if hasattr(e, '__iter__'):
+            if hasattr(e, 'is_component_type') and e.is_component_type():
+                if e.ctype == Disjunct and not e.is_indexed():
+                    self.disjuncts.append(e)
+                    continue
+                e_iter = [e]
+            elif hasattr(e, '__iter__'):
                 e_iter = e
             else:
                 e_iter = [e]
+            # The user was lazy and gave us a single constraint
+            # expression or an iterable of expressions
+            expressions = []
             for _tmpe in e_iter:
                 try:
                     if _tmpe.is_expression_type():
                         expressions.append(_tmpe)
                         continue
                 except AttributeError:
                     pass
-                msg = "\n\tin %s" % (type(e),) if e_iter is e else ""
+                msg = " in '%s'" % (type(e).__name__,) if e_iter is e else ""
                 raise ValueError(
-                    "Unexpected term for Disjunction %s.\n"
-                    "\tExpected a Disjunct object, relational expression, "
-                    "or iterable of\n"
-                    "\trelational expressions but got %s%s"
-                    % (self.name, type(_tmpe), msg)
+                    "Unexpected term for Disjunction '%s'.\n"
+                    "    Expected a Disjunct object, relational expression, "
+                    "or iterable of\n    relational expressions but got '%s'%s"
+                    % (self.name, type(_tmpe).__name__, msg)
                 )
 
             comp = self.parent_component()

pyomo/gdp/tests/test_disjunct.py

@@ -108,6 +108,31 @@ def _gen():
         self.assertEqual(len(disjuncts[0].parent_component().name), 11)
         self.assertEqual(disjuncts[0].name, "f_disjuncts[0]")
 
+    def test_construct_invalid_component(self):
+        m = ConcreteModel()
+        m.d = Disjunct([1, 2])
+        with self.assertRaisesRegex(
+            ValueError,
+            "Unexpected term for Disjunction 'dd'.\n    "
+            "Expected a Disjunct object, relational expression, or iterable of\n"
+            "    relational expressions but got 'IndexedDisjunct'",
+        ):
+            m.dd = Disjunction(expr=[m.d])
+        with self.assertRaisesRegex(
+            ValueError,
+            "Unexpected term for Disjunction 'ee'.\n    "
+            "Expected a Disjunct object, relational expression, or iterable of\n"
+            "    relational expressions but got 'str' in 'list'",
+        ):
+            m.ee = Disjunction(expr=[['a']])
+        with self.assertRaisesRegex(
+            ValueError,
+            "Unexpected term for Disjunction 'ff'.\n    "
+            "Expected a Disjunct object, relational expression, or iterable of\n"
+            "    relational expressions but got 'str'",
+        ):
+            m.ff = Disjunction(expr=['a'])
+
 
 class TestDisjunct(unittest.TestCase):
     def test_deactivate(self):