Merge pull request #2473 from jsiirola/nl-writer-cache-expressions

NL Writer, version 2

Author: blnicho

doc/OnlineDocs/conf.py

@@ -245,6 +245,14 @@ def check_output(self, want, got, optionflags):
 doctest.OutputChecker = IgnoreResultOutputChecker
 
 doctest_global_setup = '''
+import os, platform, sys
+on_github_actions = bool(os.environ.get('GITHUB_ACTIONS', ''))
+system_info = (
+    sys.platform,
+    platform.machine(),
+    platform.python_implementation()
+)
+
 from pyomo.common.dependencies import (
     attempt_import, numpy_available, scipy_available, pandas_available,
     yaml_available, networkx_available, matplotlib_available,
@@ -253,26 +261,30 @@ def check_output(self, want, got, optionflags):
 pint_available = attempt_import('pint', defer_check=False)[1]
 from pyomo.contrib.parmest.parmest import parmest_available
 
-import pyomo.opt
+import pyomo.environ as _pe # (trigger all plugin registrations)
+import pyomo.opt as _opt
+
 # Not using SolverFactory to check solver availability because
 # as of June 2020 there is no way to supress warnings when 
 # solvers are not available
-ipopt_available = bool(pyomo.opt.check_available_solvers('ipopt'))
-sipopt_available = bool(pyomo.opt.check_available_solvers('ipopt_sens'))
-k_aug_available = bool(pyomo.opt.check_available_solvers('k_aug'))
-dot_sens_available = bool(pyomo.opt.check_available_solvers('dot_sens'))
-baron_available = bool(pyomo.opt.check_available_solvers('baron'))
-glpk_available = bool(pyomo.opt.check_available_solvers('glpk'))
-baron = pyomo.opt.SolverFactory('baron')
-gurobipy_available = bool(pyomo.opt.check_available_solvers('gurobi_direct'))
+ipopt_available = bool(_opt.check_available_solvers('ipopt'))
+sipopt_available = bool(_opt.check_available_solvers('ipopt_sens'))
+k_aug_available = bool(_opt.check_available_solvers('k_aug'))
+dot_sens_available = bool(_opt.check_available_solvers('dot_sens'))
+baron_available = bool(_opt.check_available_solvers('baron'))
+glpk_available = bool(_opt.check_available_solvers('glpk'))
+gurobipy_available = bool(_opt.check_available_solvers('gurobi_direct'))
+
+baron = _opt.SolverFactory('baron')
+
 if numpy_available and scipy_available:
-    from pyomo.contrib.pynumero.asl import AmplInterface
-    asl_available = AmplInterface.available()
+    import pyomo.contrib.pynumero.asl as _asl
+    asl_available = _asl.AmplInterface.available()
+    import pyomo.contrib.pynumero.linalg.ma27 as _ma27
+    ma27_available = _ma27.MA27Interface.available()
     from pyomo.contrib.pynumero.linalg.mumps_interface import mumps_available
-    from pyomo.contrib.pynumero.linalg.ma27 import MA27Interface
-    ma27_available = MA27Interface.available()
 else:
     asl_available = False
-    mumps_available = False
     ma27_available = False
+    mumps_available = False
 '''

doc/OnlineDocs/errors.rst

@@ -16,6 +16,10 @@ Common Warnings/Errors
 .. py:currentmodule:: pyomo.environ
 
 
+.. ===================================================================
+.. Extended descriptions for Pyomo warnings
+.. ===================================================================
+
 Warnings
 --------
 
@@ -51,6 +55,7 @@ Users can bypass all domain validation by setting the value using:
    0.75
 
 
+
 .. _W1002:
 
 W1002: Setting Var value outside the bounds
@@ -82,6 +87,72 @@ Users can bypass all domain validation by setting the value using:
    10
 
 
+
+.. _W1003:
+
+W1003: Unexpected RecursionError walking an expression tree
+^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
+
+Pyomo leverages a recursive walker (the
+:py:class:`~pyomo.core.expr.visitor.StreamBasedExpressionVisitor`) to
+traverse (walk) expression trees.  For most expressions, this recursive
+walker is the most efficient.  However, Python has a relatively shallow
+recursion limit (generally, 1000 frames).  The recursive walker is
+designed to monitor the stack depth and cleanly switch to a nonrecursive
+walker before hitting the stack limit.  However, there are two (rare)
+cases where the Python stack limit can still generate a
+:py:exc:`RecursionError` exception:
+
+#. Starting the walker with fewer than
+   :py:data:`pyomo.core.expr.visitor.RECURSION_LIMIT` available frames.
+#. Callbacks that require more than 2 *
+   :py:data:`pyomo.core.expr.visitor.RECURSION_LIMIT` frames.
+
+The (default) recursive walker will catch the exception and restart the
+walker from the beginning in non-recursive mode, issuing this warning.
+The caution is that any partial work done by the walker before the
+exception was raised will be lost, potentially leaving the walker in an
+inconsistent state.  Users can avoid this by
+
+- avoiding recursive callbacks
+- restructuring the system design to avoid triggering the walker with
+  few available stack frames
+- directly calling the
+  :py:meth:`~pyomo.core.expr.visitor.StreamBasedExpressionVisitor.walk_expression_nonrecursive()`
+  walker method
+
+.. doctest::
+   :skipif: (on_github_actions and system_info[0].startswith('win')) \
+            or system_info[2] == 'PyPy'
+
+   >>> import sys
+   >>> import pyomo.core.expr.visitor as visitor
+   >>> from pyomo.core.tests.unit.test_visitor import fill_stack
+   >>> expression_depth = visitor.StreamBasedExpressionVisitor(
+   ...     exitNode=lambda node, data: max(data) + 1 if data else 1)
+   >>> m = pyo.ConcreteModel()
+   >>> m.x = pyo.Var()
+   >>> @m.Expression(range(35))
+   ... def e(m, i):
+   ...     return m.e[i-1] if i else m.x
+   >>> expression_depth.walk_expression(m.e[34])
+   36
+   >>> fill_stack(sys.getrecursionlimit() - visitor.get_stack_depth() - 30,
+   ...            expression_depth.walk_expression,
+   ...            m.e[34])
+   WARNING (W1003): Unexpected RecursionError walking an expression tree.
+       See also https://pyomo.readthedocs.io/en/stable/errors.html#w1003
+   36
+   >>> fill_stack(sys.getrecursionlimit() - visitor.get_stack_depth() - 30,
+   ...            expression_depth.walk_expression_nonrecursive,
+   ...            m.e[34])
+   36
+
+
+.. ===================================================================
+.. Extended descriptions for Pyomo errors
+.. ===================================================================
+
 Errors
 ------
 
@@ -110,7 +181,12 @@ this warning (and an exception from the converter):
        See also https://pyomo.readthedocs.io/en/stable/errors.html#e2001
 
 
-Exceptions
-----------
 
-.. _X101:
+.. ===================================================================
+.. Extended descriptions for Pyomo exceptions
+.. ===================================================================
+
+.. Exceptions
+.. ----------
+
+.. .. _X101:

pyomo/common/tests/test_timing.py

@@ -14,6 +14,7 @@
 
 import gc
 from io import StringIO
+import logging
 import sys
 import time
 
@@ -23,6 +24,7 @@
     TicTocTimer, HierarchicalTimer,
 )
 from pyomo.environ import ConcreteModel, RangeSet, Var, TransformationFactory
+from pyomo.core.base.var import _VarData
 
 class _pseudo_component(Var):
     def getname(*args, **kwds):
@@ -40,9 +42,24 @@ def tearDown(self):
 
     def test_raw_construction_timer(self):
         a = ConstructionTimer(None)
-        self.assertIn(
-            "ConstructionTimer object for NoneType (unknown); ",
-            str(a))
+        self.assertRegex(
+            str(a),
+            r"ConstructionTimer object for NoneType \(unknown\); "
+            r"[0-9\.]+ elapsed seconds")
+        v = Var()
+        v.construct()
+        a = ConstructionTimer(_VarData(v))
+        self.assertRegex(
+            str(a),
+            r"ConstructionTimer object for Var ScalarVar\[NOTSET\]; "
+            r"[0-9\.]+ elapsed seconds")
+
+    def test_raw_transformation_timer(self):
+        a = TransformationTimer(None)
+        self.assertRegex(
+            str(a),
+            r"TransformationTimer object for NoneType; "
+            r"[0-9\.]+ elapsed seconds")
 
         v = _pseudo_component()
         a = ConstructionTimer(v)
@@ -223,6 +240,65 @@ def test_TicTocTimer_context_manager(self):
         self.assertGreater(abs_time, SLEEP*3 - RES/10)
         self.assertAlmostEqual(timer.toc(None), abs_time - exclude, delta=RES)
 
+    def test_TicTocTimer_logger(self):
+        # test specifying a logger to the timer constructor disables all
+        # output to stdout
+        timer = TicTocTimer(logger=logging.getLogger(__name__))
+        with capture_output() as OUT:
+            with LoggingIntercept(level=logging.INFO) as LOG:
+                timer.toc("msg1")
+            self.assertRegex(LOG.getvalue(), r"^\[[^\]]+\] msg1$")
+            with LoggingIntercept(level=logging.INFO) as LOG:
+                timer.toc("msg2", level=logging.DEBUG)
+            self.assertEqual(LOG.getvalue(), "")
+        self.assertEqual(OUT.getvalue(), "")
+
+        with capture_output() as OUT:
+            with LoggingIntercept(level=logging.DEBUG) as LOG:
+                timer.toc("msg1")
+                timer.toc("msg2", level=logging.DEBUG)
+        self.assertEqual(OUT.getvalue(), "")
+        self.assertRegex(LOG.getvalue(), r"^\[[^\]]+\] msg1\n\[[^\]]+\] msg2$")
+
+        # test specifying a logger to toc() for a general timer disables
+        # output to stdout
+        timer = TicTocTimer()
+        with capture_output() as OUT:
+            with LoggingIntercept(level=logging.INFO) as LOG:
+                timer.toc("msg1", logger=logging.getLogger(__name__))
+        self.assertRegex(LOG.getvalue(), r"^\[[^\]]+\] msg1$")
+        self.assertEqual(OUT.getvalue(), "")
+
+    def test_TicTocTimer_deprecated(self):
+        timer = TicTocTimer()
+        with LoggingIntercept() as LOG, capture_output() as out:
+            timer.tic("msg", None, None)
+        self.assertEqual(out.getvalue(), "")
+        self.assertRegex(
+            LOG.getvalue().replace('\n', ' ').strip(),
+            r"DEPRECATED: tic\(\): 'ostream' and 'logger' should be specified "
+            r"as keyword arguments( +\([^\)]+\)){2}")
+
+        with LoggingIntercept() as LOG, capture_output() as out:
+            timer.toc("msg", True, None, None)
+        self.assertEqual(out.getvalue(), "")
+        self.assertRegex(
+            LOG.getvalue().replace('\n', ' ').strip(),
+            r"DEPRECATED: toc\(\): 'delta', 'ostream', and 'logger' should be "
+            r"specified as keyword arguments( +\([^\)]+\)){2}")
+
+        timer = TicTocTimer()
+        with LoggingIntercept() as LOG, capture_output() as out:
+            timer.tic("msg %s, %s", None, None)
+        self.assertIn('msg None, None', out.getvalue())
+        self.assertEqual(LOG.getvalue(), "")
+
+        with LoggingIntercept() as LOG, capture_output() as out:
+            timer.toc("msg %s, %s, %s", True, None, None)
+        self.assertIn('msg True, None, None', out.getvalue())
+        self.assertEqual(LOG.getvalue(), "")
+
+
     def test_HierarchicalTimer(self):
         RES = 0.01 # resolution (seconds)