From 59a20e473994e4e06d3019c022a6987983cd1402 Mon Sep 17 00:00:00 2001 From: "R. Bernstein" Date: Mon, 16 Dec 2024 21:24:11 -0500 Subject: [PATCH] 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] -> ([, , ]>, True) -> System`Exponent[Global`x, 1, System`Max] Rewriting: System`Max[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 | 10 ++++-- mathics/core/builtin.py | 2 +- mathics/core/expression.py | 5 +-- mathics/core/symbols.py | 4 --- mathics/eval/tracing.py | 64 +++++++++++++++++++++++++++++++++----- test/builtin/test_trace.py | 18 ++++++++--- 6 files changed, 80 insertions(+), 23 deletions(-) diff --git a/mathics/builtin/trace.py b/mathics/builtin/trace.py index 8a2233bbc..8bde31641 100644 --- a/mathics/builtin/trace.py +++ b/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): diff --git a/mathics/core/builtin.py b/mathics/core/builtin.py index 62ceccc79..0e54a2d94 100644 --- a/mathics/core/builtin.py +++ b/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 diff --git a/mathics/core/expression.py b/mathics/core/expression.py index 0e7b54206..927791f70 100644 --- a/mathics/core/expression.py +++ b/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. diff --git a/mathics/core/symbols.py b/mathics/core/symbols.py index 53ed3c5fa..18d7ce12e 100644 --- a/mathics/core/symbols.py +++ b/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 diff --git a/mathics/eval/tracing.py b/mathics/eval/tracing.py index f911c4169..3333831ce 100644 --- a/mathics/eval/tracing.py +++ b/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,6 +94,7 @@ 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 @@ -54,14 +102,14 @@ def wrapper(expr, evaluation) -> Any: ): # 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) diff --git a/test/builtin/test_trace.py b/test/builtin/test_trace.py index 0a1f96122..7f061a4d0 100644 --- a/test/builtin/test_trace.py +++ b/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: