Redo TraceEvaluation using a decorator...

This also allows the external debugger to do a much better job of this

mathics/builtin/trace.py

@@ -22,6 +22,7 @@
 from time import time
 from typing import Callable
 
+import mathics.eval.tracing
 from mathics.core.attributes import A_HOLD_ALL, A_HOLD_ALL_COMPLETE, A_PROTECTED
 from mathics.core.builtin import Builtin
 from mathics.core.convert.python import from_bool, from_python
@@ -354,11 +355,13 @@ class TraceEvaluation(Builtin):
       <dd>Evaluate $expr$ and print each step of the evaluation.
     </dl>
 
-    >> TraceEvaluation[(x + x)^2]
+    The 'ShowTimeBySteps' option prints the elapsed time before an evaluation occurs.
+
+    >> TraceEvaluation[(x + 1)^2]
      | ...
      = ...
 
-    >> TraceEvaluation[(x + x)^2, ShowTimeBySteps->True]
+    >> TraceEvaluation[(x + 1)^2, ShowTimeBySteps->True]
      | ...
      = ...
     """
@@ -367,19 +370,30 @@ class TraceEvaluation(Builtin):
     options = {
         "System`ShowTimeBySteps": "False",
     }
-    summary_text = "trace the successive evaluations"
+    summary_text = "trace expression evaluation"
 
     def eval(self, expr, evaluation: Evaluation, options: dict):
         "TraceEvaluation[expr_, OptionsPattern[]]"
+
         curr_trace_evaluation = evaluation.definitions.trace_evaluation
         curr_time_by_steps = evaluation.definitions.timing_trace_evaluation
+
+        old_evaluation_hook = mathics.eval.tracing.trace_evaluate_on_call
+
+        mathics.eval.tracing.trace_evaluate_on_call = (
+            mathics.eval.tracing.print_evaluate
+        )
+
         evaluation.definitions.trace_evaluation = True
         evaluation.definitions.timing_trace_evaluation = (
             options["System`ShowTimeBySteps"] is SymbolTrue
         )
         result = expr.evaluate(evaluation)
         evaluation.definitions.trace_evaluation = curr_trace_evaluation
         evaluation.definitions.timing_trace_evaluation = curr_time_by_steps
+
+        mathics.eval.tracing.trace_evaluate_on_call = old_evaluation_hook
+
         return result
 
 

mathics/core/evaluation.py

@@ -188,6 +188,8 @@ def __init__(
         # ``mathics.builtin.numeric.N``.
         self._preferred_n_method: List[str] = []
 
+        self.is_boxing = False
+
     def parse(self, query, src_name: str = ""):
         "Parse a single expression and print the messages."
         from mathics.core.parser import MathicsSingleLineFeeder
@@ -510,6 +512,7 @@ def print_out(self, text) -> None:
         if self.definitions.trace_evaluation:
             self.definitions.trace_evaluation = False
             text = self.format_output(from_python(text), "text")
+            self.is_boxing = False
             self.definitions.trace_evaluation = True
         else:
             text = self.format_output(from_python(text), "text")

mathics/core/expression.py

@@ -2,7 +2,6 @@
 # -*- coding: utf-8 -*-
 
 import math
-import time
 from bisect import bisect_left
 from itertools import chain
 from typing import (
@@ -78,6 +77,7 @@
     SymbolSubtract,
     SymbolUnevaluated,
 )
+from mathics.eval.tracing import trace_evaluate
 
 # from mathics.timing import timeit
 
@@ -521,6 +521,7 @@ def equal2(self, rhs: Any) -> Optional[bool]:
     # Note that the return type is some subclass of BaseElement, it could be
     # a Real, an Expression, etc. It probably will *not* be a BaseElement since
     # the point of evaluation when there is not an error is to produce a concrete result.
+    @trace_evaluate
     def evaluate(
         self,
         evaluation: Evaluation,
@@ -544,12 +545,6 @@ def evaluate(
 
         old_options = evaluation.options
         evaluation.inc_recursion_depth()
-        if evaluation.definitions.trace_evaluation:
-            if evaluation.definitions.timing_trace_evaluation:
-                evaluation.print_out(time.time() - evaluation.start_time)
-            evaluation.print_out(
-                "  " * evaluation.recursion_depth + "Evaluating: %s" % expr
-            )
         try:
             # Evaluation loop:
             while reevaluate:

mathics/core/symbols.py

@@ -1,7 +1,6 @@
 # cython: language_level=3
 # -*- coding: utf-8 -*-
 
-import time
 from typing import TYPE_CHECKING, Any, Dict, FrozenSet, List, Optional, Sequence, Union
 
 from mathics.core.element import (
@@ -14,6 +13,8 @@
 if TYPE_CHECKING:
     from mathics.core.atoms import String
 
+from mathics.eval.tracing import trace_evaluate
+
 # I put this constants here instead of inside `mathics.core.convert.sympy`
 # to avoid a circular reference. Maybe they should be in its own module.
 
@@ -483,18 +484,12 @@ def equal2(self, rhs: Any) -> Optional[bool]:
             return self == rhs
         return None
 
+    @trace_evaluate
     def evaluate(self, evaluation):
         """
         Evaluates the symbol by applying the rules (ownvalues) in its definition,
         recursively.
         """
-        if evaluation.definitions.trace_evaluation:
-            if evaluation.definitions.timing_trace_evaluation:
-                evaluation.print_out(time.time() - evaluation.start_time)
-            evaluation.print_out(
-                "  " * evaluation.recursion_depth + "  Evaluating: %s" % self
-            )
-
         rules = evaluation.definitions.get_ownvalues(self.name)
         for rule in rules:
             result = rule.apply(self, evaluation, fully=True)

mathics/eval/makeboxes.py

@@ -209,6 +209,7 @@ def format_element(
     """
     Applies formats associated to the expression, and then calls Makeboxes
     """
+    evaluation.is_boxing = True
     expr = do_format(element, evaluation, form)
     if expr is None:
         return None

mathics/eval/tracing.py

@@ -5,17 +5,68 @@
 """
 
 import inspect
+import time
 from enum import Enum
 from typing import Any, Callable, Optional
 
-TraceEventNames = ("SymPy", "Numpy", "mpmath", "apply", "debugger")
+TraceEventNames = ("SymPy", "Numpy", "mpmath", "apply", "evaluate", "debugger")
 TraceEvent = Enum("TraceEvent", TraceEventNames)
 
 
 hook_entry_fn: Optional[Callable] = None
 hook_exit_fn: Optional[Callable] = None
 
 
+def print_evaluate(expr, evaluation, status: str, orig_expr=None) -> bool:
+    """
+    Called from a decorated Python @trace_evaluate .evaluate()
+    method when TraceActivate["evaluate" -> True]
+    """
+    if evaluation.definitions.timing_trace_evaluation:
+        evaluation.print_out(time.time() - evaluation.start_time)
+    indents = "  " * evaluation.recursion_depth
+    evaluation.print_out(f"{indents}{status}: {expr}")
+    return False
+
+
+# When not None, evaluate() methods call this
+# to show the status of evaluation on entry and return.
+trace_evaluate_on_call: Optional[Callable] = None
+trace_evaluate_on_return: Optional[Callable] = None
+
+
+def trace_evaluate(func: Callable) -> Callable:
+    """
+    Wrap a method evaluate() call event with trace_evaluate_on_call()
+    and trace_evaluate_on_return() callback so we can trace the
+    progress in evaluation.
+    """
+
+    def wrapper(expr, evaluation) -> Any:
+        from mathics.core.symbols import SymbolConstant
+
+        skip_call = False
+        result = None
+        if (
+            trace_evaluate_on_call is not None
+            and not evaluation.is_boxing
+            and not isinstance(expr, SymbolConstant)
+        ):
+            # We may use boxing in print_evaluate_fn(). So turn off
+            # boxing temporarily.
+            was_boxing = evaluation.is_boxing
+            evaluation.is_boxing = True
+            skip_call = trace_evaluate_on_call(expr, evaluation, "Evaluating")
+            evaluation.is_boxing = was_boxing
+        if not skip_call:
+            result = func(expr, evaluation)
+            if trace_evaluate_on_return is not None and not evaluation.is_boxing:
+                trace_evaluate_on_call(result, evaluation, "Returning", expr)
+        return result
+
+    return wrapper
+
+
 def trace_fn_call_event(func: Callable) -> Callable:
     """
     Wrap a call event with callbacks,