More trace evaluation filtering (#1410)

Author: rocky

mathics/eval/tracing.py

@@ -29,30 +29,39 @@ def skip_trivial_evaluation(expr, status: str, orig_expr=None) -> bool:
     """
     from mathics.core.symbols import Symbol, SymbolConstant
 
-    if isinstance(expr, Symbol) and not isinstance(expr, SymbolConstant):
-        return True
-
-    if (
-        status == "Returning"
-        and hasattr(expr, "is_literal")
-        and expr.is_literal
-        and hasattr(orig_expr, "is_literal")
-        and orig_expr.is_literal
-    ):
-        return True
-
-    if orig_expr == expr:
-        # If the two expressions are the same, there is no point in
-        # repeating the output.
-        return True
+    if status == "Returning":
+        if (
+            hasattr(expr, "is_literal")
+            and expr.is_literal
+            and hasattr(orig_expr, "is_literal")
+            and orig_expr.is_literal
+        ):
+            return True
+        pass
+        if isinstance(expr, Symbol) and not isinstance(expr, SymbolConstant):
+            # Evaluation of a symbol, like Plus isn't that interesting
+            return True
+
+    else:
+        # Status != "Returning", i.e. executing
+
+        if isinstance(expr, Symbol):
+            # Evaluation of a symbol, like Plus isn't that interesting
+            return True
+
+        if orig_expr == expr:
+            # If the two expressions are the same, there is no point in
+            # repeating the output.
+            return True
 
     return False
 
 
 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]
+    method when TraceActivate["evaluate" -> True] or
+    running TraceEvaluation.
     """
 
     if evaluation.definitions.timing_trace_evaluation:
@@ -64,7 +73,8 @@ def print_evaluate(expr, evaluation, status: str, fn: Callable, orig_expr=None):
     indents = "  " * evaluation.recursion_depth
 
     if orig_expr is not None:
-        if fn.__name__ == "rewrite_apply_eval_step":
+        fn_name = fn.__name__ if hasattr(fn, "__name__") else None
+        if fn_name == "rewrite_apply_eval_step":
             assert isinstance(expr, tuple)
             if orig_expr != expr[0]:
                 if status == "Returning":
@@ -120,7 +130,13 @@ def wrapper(expr, evaluation) -> Any:
         if not skip_call:
             result = func(expr, evaluation)
             if trace_evaluate_on_return is not None and not was_boxing:
-                trace_evaluate_on_return(result, evaluation, "Returning", expr, result)
+                trace_evaluate_on_return(
+                    expr=result,
+                    evaluation=evaluation,
+                    status="Returning",
+                    fn=expr,
+                    orig_expr=expr,
+                )
             evaluation.is_boxing = was_boxing
         return result
 

test/builtin/test_trace.py

@@ -2,16 +2,17 @@
 """
 Unit tests for mathics.builtin.trace
 """
-from inspect import isfunction
-from test.helper import evaluate
-from typing import Callable
+from inspect import isfunction, ismethod
+from test.helper import evaluate, session
+from typing import Any, Callable
 
 import pytest
 
 import mathics.eval.tracing
 from mathics import version_info
 from mathics.core.evaluation import Evaluation
 from mathics.core.interrupt import AbortInterrupt
+from mathics.eval.tracing import TraceEvent
 
 trace_evaluation_calls = 0
 
@@ -68,3 +69,79 @@ def counting_print_evaluate(
         mathics.eval.tracing.print_evaluate = old_evaluation_hook
         old_recursion_limit = evaluate(f"$RecursionLimit = {old_recursion_limit.value}")
     assert mathics.eval.tracing.print_evaluate == old_evaluation_hook
+
+
+event_queue = []
+
+
+def test_skip_trivial_evaluation():
+    """
+    Test of TraceEvaluate[] to filter events
+    """
+
+    def empty_queue():
+        global event_queue
+        event_queue = []
+
+    def call_event_func(event: TraceEvent, fn: Callable, *args) -> bool:
+        """
+        Capture filtered calls in event_queue.
+        """
+        if isinstance(type(fn), type) or ismethod(fn) or isfunction(fn):
+            name = f"{fn.__module__}.{fn.__qualname__}"
+        else:
+            name = str(fn)
+        event_queue.append(f"{event.name} call  : {name}{args[:3]}")
+        return False
+
+    def return_event_func(event: TraceEvent, result: Any) -> Any:
+        """
+        A somewhat generic function to print a traced call's
+        return value.
+        """
+        event_queue.append(f"{event.name} result: {result}")
+        return result
+
+    def capture_print(s: str):
+        """
+        A somewhat generic function to print a traced call's
+        return value.
+        """
+        event_queue.append(s)
+
+    session.reset()
+    old_print_out = session.evaluation.print_out
+    session.evaluation.print_out = capture_print
+    empty_queue()
+
+    try:
+        session.evaluate("TraceEvaluation[2 3 + 4]")
+        assert [
+            "  Evaluating: System`Plus[System`Times[2, 3], 4]",
+            "    Evaluating: System`Times[2, 3]",
+            "      Returning: System`Times[2, 3] = (<Integer: 6>, False)",
+            "    Returning: System`Times[2, 3] = 6",
+            "    Returning: System`Plus[System`Times[2, 3], 4] = (<Integer: 10>, False)",
+            "  Returning: System`Plus[System`Times[2, 3], 4] = 10",
+        ] == event_queue
+        # print()
+        # for line in event_queue:
+        #     print(line)
+
+        empty_queue()
+        session.evaluate("TraceEvaluation[(2 + 3) 4]")
+        assert [
+            "  Evaluating: System`Times[System`Plus[2, 3], 4]"
+            "    Evaluating: System`Plus[2, 3]",
+            "      Returning: System`Plus[2, 3] = (<Integer: 5>, False)",
+            "    Returning: System`Plus[2, 3] = 5",
+            "  Returning: System`Times[System`Plus[2, 3], 4] = (<Integer: 20>, False)",
+        ]
+        # print()
+        # for line in event_queue:
+        #     print(line)
+
+    finally:
+        # Just in case, restore everything back to what it was before running this test.
+        session.evaluation.print_out = old_print_out
+        session.reset()