Tracing improvements (#1224)

Trace rewrite rules. Also, we were dropping some return value
expressions.

Improvement seen from mathics: 

```
In[1]:= TraceEvaluation[Exponent[x, 1]]
  Evaluating Expression.evaluate(): System`Exponent[Global`x, 1]
    Rewriting: System`Exponent[Global`x, 1, System`Max] -> (<Expression: <Symbol: System`Exponent>[<Symbol: Global`x>, <Integer: 1>, <Symbol: System`Max>]>, True)
    -> System`Exponent[Global`x, 1, System`Max]
    Rewriting: System`Max[0] -> (<Expression: <Symbol: System`Max>[<Integer: 0>]>, True)
    -> System`Max[0]
  Returning: System`Exponent[Global`x, 1] = 0
Out[1]= 0

In[2]:= TraceEvaluation[1+3]
  Evaluating Expression.evaluate(): System`Plus[1, 3]
  Returning: System`Plus[1, 3] = 4
Out[2]= 4
```


![image](https://github.com/user-attachments/assets/c82fa2d8-b53b-427b-b041-98f194f0a463)

mathics/builtin/trace.py

@@ -378,12 +378,17 @@ def eval(self, expr, evaluation: Evaluation, options: dict):
         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
+        old_evaluation_call_hook = mathics.eval.tracing.trace_evaluate_on_call
+        old_evaluation_return_hook = mathics.eval.tracing.trace_evaluate_on_return
 
         mathics.eval.tracing.trace_evaluate_on_call = (
             mathics.eval.tracing.print_evaluate
         )
 
+        mathics.eval.tracing.trace_evaluate_on_return = (
+            mathics.eval.tracing.print_evaluate
+        )
+
         evaluation.definitions.trace_evaluation = True
         evaluation.definitions.timing_trace_evaluation = (
             options["System`ShowTimeBySteps"] is SymbolTrue
@@ -397,7 +402,8 @@ def eval(self, expr, evaluation: Evaluation, options: dict):
             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
+            mathics.eval.tracing.trace_evaluate_on_call = old_evaluation_call_hook
+            mathics.eval.tracing.trace_evaluate_on_return = old_evaluation_return_hook
 
 
 class TraceEvaluationVariable(Builtin):

mathics/core/builtin.py

@@ -786,7 +786,7 @@ def check_requires_list(requires: list) -> bool:
     return True
 
 
-def get_option(options, name, evaluation, pop=False, evaluate=True):
+def get_option(options: dict, name, evaluation, pop=False, evaluate=True):
     # we do not care whether an option X is given as System`X,
     # Global`X, or with any prefix from $ContextPath for that
     # matter. Also, the quoted string form "X" is ok. all these

mathics/core/expression.py

@@ -576,10 +576,6 @@ def evaluate(
                     break
 
                 # TraceEvaluation[] logging.
-                if evaluation.definitions.trace_evaluation:
-                    evaluation.print_out(
-                        "  " * evaluation.recursion_depth + "-> %s" % expr
-                    )
                 iteration += 1
                 # Check whether we have hit $Iterationlimit: is the number of times
                 # ``reevaluate`` came back False in this loop.
@@ -1127,6 +1123,7 @@ def restructure(self, head, elements, evaluation, structure_cache=None, deps=Non
         s = structure(head, deps, evaluation, structure_cache=structure_cache)
         return s(list(elements))
 
+    @trace_evaluate
     def rewrite_apply_eval_step(self, evaluation) -> Tuple[BaseElement, bool]:
         """Perform a single rewrite/apply/eval step of the bigger
         Expression.evaluate() process.

mathics/core/symbols.py

@@ -494,10 +494,6 @@ def evaluate(self, evaluation):
         for rule in rules:
             result = rule.apply(self, evaluation, fully=True)
             if result is not None and not result.sameQ(self):
-                if evaluation.definitions.trace_evaluation:
-                    evaluation.print_out(
-                        "  " * evaluation.recursion_depth + "  -> %s" % result
-                    )
                 return result.evaluate(evaluation)
         return self
 

mathics/eval/tracing.py

@@ -17,16 +17,63 @@
 hook_exit_fn: Optional[Callable] = None
 
 
-def print_evaluate(expr, evaluation, status: str, orig_expr=None) -> bool:
+def print_evaluate(expr, evaluation, status: str, fn: Callable, orig_expr=None):
     """
     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)
+
+    # Test and dispose of various situations where showing information
+    # is pretty useless: evaluating a Symbol is the Symbol.
+    # Showing the return value of a ListExpression literal is
+    # also useless.
+    from mathics.core.symbols import Symbol, SymbolConstant
+
+    if isinstance(expr, Symbol) and not isinstance(expr, SymbolConstant):
+        return
+
+    if (
+        status == "Returning"
+        and hasattr(expr, "is_literal")
+        and expr.is_literal
+        and hasattr(orig_expr, "is_literal")
+        and orig_expr.is_literal
+    ):
+        return
+
+    if orig_expr == expr:
+        # If the two expressions are the same, there is no point in
+        # repeating the output.
+        return
+
     indents = "  " * evaluation.recursion_depth
-    evaluation.print_out(f"{indents}{status}: {expr}")
-    return False
+
+    if orig_expr is not None:
+        if fn.__name__ == "rewrite_apply_eval_step":
+            assert isinstance(expr, tuple)
+            if orig_expr != expr[0]:
+                if status == "Returning":
+                    if expr[1]:
+                        status = "Rewriting"
+                        arrow = " -> "
+                    else:
+                        return
+                else:
+                    arrow = " = "
+                    return
+
+                evaluation.print_out(
+                    f"{indents}{status}: {expr[0]}" + arrow + str(expr)
+                )
+        else:
+            evaluation.print_out(f"{indents}{status}: {orig_expr} = " + str(expr))
+
+    elif fn.__name__ != "rewrite_apply_eval_step":
+        evaluation.print_out(f"{indents}{status}: {expr}")
+    return
 
 
 # When not None, evaluate() methods call this
@@ -47,21 +94,22 @@ def wrapper(expr, evaluation) -> Any:
 
         skip_call = False
         result = None
+        was_boxing = evaluation.is_boxing
         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")
+            skip_call = trace_evaluate_on_call(expr, evaluation, "Evaluating", func)
             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_return(result, evaluation, "Returning", expr)
+            if trace_evaluate_on_return is not None and not was_boxing:
+                trace_evaluate_on_return(result, evaluation, "Returning", func, expr)
+            evaluation.is_boxing = was_boxing
         return result
 
     return wrapper
@@ -106,7 +154,7 @@ def call_event_print(event: TraceEvent, fn: Callable, *args) -> bool:
     """
     A somewhat generic function to show an event-traced call.
     """
-    if type(fn) == type or inspect.ismethod(fn) or inspect.isfunction(fn):
+    if isinstance(type(fn), type) or inspect.ismethod(fn) or inspect.isfunction(fn):
         name = f"{fn.__module__}.{fn.__qualname__}"
     else:
         name = str(fn)

test/builtin/test_trace.py

@@ -2,12 +2,15 @@
 """
 Unit tests for mathics.builtin.trace
 """
-
+from inspect import isfunction
 from test.helper import evaluate
+from typing import Callable
 
 import pytest
 
 import mathics.eval.tracing
+from mathics import version_info
+from mathics.core.evaluation import Evaluation
 from mathics.core.interrupt import AbortInterrupt
 
 trace_evaluation_calls = 0
@@ -20,25 +23,32 @@ def test_TraceEvaluation():
     old_recursion_limit = evaluate("$RecursionLimit")
     old_evaluation_hook = mathics.eval.tracing.print_evaluate
 
-    def counting_print_evaluate(expr, evaluation, status: str, orig_expr=None) -> bool:
+    def counting_print_evaluate(
+        expr, evaluation: Evaluation, status: str, fn: Callable, orig_expr=None
+    ) -> bool:
         """
         A replacement for mathics.eval.tracing.print_evaluate() that counts the
         number of evaluation calls.
         """
         global trace_evaluation_calls
         trace_evaluation_calls += 1
+        assert status in ("Evaluating", "Returning")
+        if "cython" not in version_info:
+            assert isfunction(fn), "Expecting 4th argument to be a function"
         return False
 
     try:
         # Set a small recursion limit,
         # Replace TraceEvaluation's print function something that counts evaluation
         # calls, and then force a RecursionLimit Error.
-        evaluate("$RecursionLimit = 20")
+        evaluate("$RecursionLimit = 40")
         assert mathics.eval.tracing.print_evaluate == old_evaluation_hook
         evaluate("f[x_] := x + f[x-1]; f[0] = 0")
         global trace_evaluation_calls
         trace_evaluation_calls = 0
-        mathics.eval.tracing.print_evaluate = counting_print_evaluate
+        mathics.eval.tracing.print_evaluate = (
+            mathics.eval.tracing.trace_evaluate_on_call
+        ) = mathics.eval.tracing.trace_evaluate_on_return = counting_print_evaluate
         evaluate("f[30] // TraceEvaluation")
 
     except AbortInterrupt: