diff --git a/mathics/builtin/trace.py b/mathics/builtin/trace.py index 517e7ba03..43856fdcb 100644 --- a/mathics/builtin/trace.py +++ b/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):
Evaluate $expr$ and print each step of the evaluation. - >> 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,12 +370,20 @@ 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 @@ -380,6 +391,9 @@ def eval(self, expr, evaluation: Evaluation, options: dict): 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 diff --git a/mathics/core/evaluation.py b/mathics/core/evaluation.py index f619705a2..263cc57ff 100644 --- a/mathics/core/evaluation.py +++ b/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") diff --git a/mathics/core/expression.py b/mathics/core/expression.py index 693b14bc2..b68a9a64c 100644 --- a/mathics/core/expression.py +++ b/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: diff --git a/mathics/core/symbols.py b/mathics/core/symbols.py index 536b759f6..76e90ecfd 100644 --- a/mathics/core/symbols.py +++ b/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) diff --git a/mathics/eval/makeboxes.py b/mathics/eval/makeboxes.py index 5437d039d..8198d4b55 100644 --- a/mathics/eval/makeboxes.py +++ b/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 diff --git a/mathics/eval/tracing.py b/mathics/eval/tracing.py index 7dc2d6907..e55a94300 100644 --- a/mathics/eval/tracing.py +++ b/mathics/eval/tracing.py @@ -5,10 +5,11 @@ """ 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) @@ -16,6 +17,56 @@ 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,