New Interrupt handler shows a couple of places where we have slowness in loading Rubi

[rocky]

Recently, on the Mathics3 core side, I have been working on code to mimic WolframScript's interrupt handler

When there is a long pause in a computation in mathics you can run C-C and it will show you what it is currently working on.

Here is what I see...

Modifying 2817 integration rules to distribute coefficients over sums...
  C-c C-c
interrupt> s

  Function[FixIntRule[Slot[1],
     Part[Slot[1], 1, 1, 2, 1]]], {
    HoldPattern[Int[Times[-1, u:_], x:_ Symbol]] :>
    Times[Identity[-1], Int[u, x]], HoldPattern[Int[Times[Complex[0, a:_], u:_], x:_ Symbol]] :>
  					      Condition[Times[Complex[Identity[0], a], Int[u, x]], And[FreeQ[a, x], EqQ[Power[a, 2], 1]]], HoldPattern[Int[Times[Power[Plus[Times[Optional[a:_], Power[x:_, Optional[j:_]]], Times[Optional[b:_], Power[x:_, n:_]]], p:_], Power[Times[c:_, x:_], Optional[m:_]]], x:_ Symbol]] :> Condition[Times[Power[c, IntPart[m]], Power[Times[c, x], FracPart[m]], Power[Power[x, FracPart[m]], -1], Int[Times[Power[x, m], Power[Plus[Times[a, Power[x, j]], Times[b, Power[x, n]]], p]], x]], And[FreeQ[{a, b, c, j, m, n, p}, x], IntegerQ[Plus[p, Times[1, Power[2, -1]]]], NeQ[n, j], EqQ[Simplify[Plus[m, Times[j, p], 1]], 0]]], HoldPattern[Int[Times[Power[Plus[Times[Optional[a:_], Power[x:_, Optional[j:_]]], Times[Optional[b:_], Power[x:_, n:_]]], p:_], Power[Times[c:_, x:_], Optional[m:_]]], x:_ Symbol]] :> Condition[Times[Power[c, IntPart[m]], Power[Times[c, x], FracPart[m]], Power[Power[x, FracPart[m]], -1], Int[Times[Power[x, m], Power[Plus[Times[a, Power[x, j]], Times[b, Power[x, n]]], p]], x]], And[FreeQ[{a, b, c, j, m, n, p}, x], Not[IntegerQ[p]], NeQ[n, j], IntegerQ[Simplify[Times[j, Power[n, -1]]]], NeQ[m, -1], IntegerQ[Simplify[Times[n, Power[Plus[m, 1], -1]]]], Not[IntegerQ[n]]]], HoldPattern[Int[Times[Power[Plus[Times[Optional[a:_], Power[x:_, Optional[j:_]]], Times[Optional[b:_], Power[x:_, n:_]]], p:_], Power[Times[c:_, x:_], Optional[m:_]]], x:_ Symbol]] :> Condition[Times[Power[c, IntPart[m]], Power[Times[c, x], FracPart[m]], Power[Power[x, FracPart[m]], -1], Int[Times[Power[x, m], Power[Plus[Times[a, Power[x, j]], Times[b, Power[x, n]]], p]], x]], And[FreeQ[{a, b, c, j, m, n, p}, x], Not[IntegerQ[p]], NeQ[n, j], IntegerQ[Simplify[Times[j, Power[n, -1]]]], IntegerQ[Simplify[Times[Plus[m, 1], Power[n, -1]]]], NeQ[Power[n, 2], 1]]], HoldPattern[Int[Times[Power[Plus[Times[Optional[a:_], Power[x:_, Optional[j:_]]], Times[Optional[b:_], Power[x:_, Optional[n:_]]]], p:_], Power[Times[c:_, x:_], Optional[m:_]]], x:_ Symbol]] :> Condition[Times[Power[c, IntPart[m]], Power[Times[c, x], FracPart[m]], Power[Power[x, FracPart[m]], -1], Int[Times[Power[x, m], Power[Plus[Times[a, Power[x, j]], Times[b, Power[x, n]]], p]], x]], And[FreeQ[{a, b, c, j, m, n, p}, x], Not[IntegerQ[p]], NeQ[n, j], ILtQ[Simplify[Times[Plus[m, Times[n, p], n, Times[-1, j], 1], Power[Plus[n, Times[-1, j]], -1]]], 0]]], HoldPattern[Int[Times[Power[Plus[Times[Optional[a:_], Power[x:_, Optional[j:_]]], Times[Optional[b:_], Power[x:_, Optional[n:_]]]], p:_], Power[Times[Optional[c:_], x:_], m:_]], x:_ Symbol]] :> Condition[Plus[Times[Power[Times[c, x], Plus[m, 1]], Power[Plus[Times[a, Power[x, j]], Times[b, Power[x, n]]], p], Power[Times[c, Plus[m, Times[j, p], 1]], -1]], Times[-1, b, p, Plus[n, Times[-1, j]], Power[Times[Power[c, n], Plus[m, Times[j, p], 1]], -1], Int[Times[Power[Times[c, x], Plus[m, n]], Power[Plus[Times[a, Power[x, j]], Times[b, Power[x, n]]], Plus[p, -1]]], x]]], And[FreeQ[{a, b, c}, x], Not[IntegerQ[p]], LtQ[0, j, n], Or[IntegersQ[j, n], GtQ[c, 0]], GtQ[p, 0], LtQ[Plus[m, Times[j, p], 1], 0]]], HoldPattern[Int[Times[Power[Plus[Times[Optional[a:_], Power[x:_, Optional[j:_]]], Times[Optional[b:_], Power[x:_, Optional[n:_]]]], p:_], Power[Times[Optional[c:_], x:_], Optional[m:_]]], x:_ Symbol]] :> Condition[Times[Power[c, IntPart[m]], Power[Times[c, x], FracPart[m]], Power[Plus[Times[a, Power[x, j]], Times[b, Power[x, n]]], FracPart[p]], Power[Times[Power[x, Plus[FracPart[m], Times[j, FracPart[p]]]], Power[Plus[a, Times[b, Power[x, Plus[n, Times[-1, j]]]]], FracPart[p]]], -1], Int[Times[Power[x, Plus[m, Times[j, p]]], Power[Plus[a, Times[b, Power[x, Plus[n, Times[-1, j]]]]], p]], x]], And[FreeQ[{a, b, c, j, m, n, p}, x], Not[IntegerQ[p]], NeQ[n, j], PosQ[Plus[n, Times[-1, j]]]]], HoldPattern[Int[Times[Power[Plus[Times[Optional[a:_], Power[x:_, Optional[j:_]]], Times[Optional[b:_], Power[x:_, Optional[n:_]]]], p:_], Power[Times[Optional[c:_], x:_], Optional[m:_]]], x:_ Symbol]] :> Condition[Plus[Times[-1, Power[c, Plus[j, -1]], ...
(*This goes on for probably thousands of Rules *)

and after that:

Patching With[]...
  C-c C-c
interrupt> s
ReplaceAll[expr_, rules_]
System`ReplaceAll[System`DownValues[Rubi`Int], Rubi`Private`dvFixWith]

which probably comes from line 217 of Rubi.m:

DownValues[Int] = DownValues[Int] /. dvFixWith /. dvFixWithNoCond;

I don't have any ideas here as to what to do or how to fix. So I am just reporting what I see, in case others have thoughts or ideas.

[mmatera]

Assignment rule... I guess that much of the time spent here is related to the flakiness of Mathics dealing with these convolved assignments ...

[rocky]

Assignment rule... I guess that much of the time spent here is related to the flakiness of Mathics dealing with these convolved assignments ...

Now that we have the slowness a little more pinpointed, I surrounded some of the statements in TraceBuiltins[]. I did this twice sorting on times and then in another run by counts:

Time used:

Patching With[]...

TraceBuiltins[dvFixWith = RuleDelayed[...]
count     ms Builtin name
  137     68 CompoundExpression
   81     27 SetDelayed
   17     15 Block
   17     12 If
   76      8 Set
   74      5 MPMathFunction
   33      4 Power
   46      3 Unprotect
   44      3 Protect
   19      0 Times

TraceBuiltins[dvFixWithNoCond = RuleDelayed[...]
count     ms Builtin name
  137     65 CompoundExpression
   81     25 SetDelayed
   17     13 Block
   17      9 If
   76      8 Set
   74      4 MPMathFunction
   33      4 Power
   46      3 Unprotect
   44      3 Protect
   19      0 Times

TraceBuiltins[DownValues[Int] = ..

count     ms Builtin name
  137     68 CompoundExpression
   81     28 SetDelayed
   17     13 Block
   17      9 If
   76      8 Set
   74      5 MPMathFunction
   33      4 Power
   46      3 Unprotect
   44      3 Protect
   19      0 Times

Builtin counts:

Patching With[]...

TraceBuiltins[dvFixWith = RuleDelayed[...]
count     ms Builtin name
  137     68 CompoundExpression
  115      0 Rule_
   91      0 List
   81     27 SetDelayed
   76      8 Set
   74      5 MPMathFunction
   46      3 Unprotect
   46      0 ClearAttributes

TraceBuiltins[dvFixWithNoCond = RuleDelayed[...]
count     ms Builtin name
  137     65 CompoundExpression
  115      0 Rule_
   91      0 List
   81     25 SetDelayed
   76      8 Set
   74      5 MPMathFunction
   46      3 Unprotect
   46      0 ClearAttributes

TraceBuiltins[DownValues[Int] = ..

count     ms Builtin name
  137     67 CompoundExpression
  115      0 Rule_
   91      0 List
   81     27 SetDelayed
   76      7 Set
   74      5 MPMathFunction

However, please note that this information is not necessarily going to capture the amount of time for the internal Python functions, such as the time rebuilding a (homegrown, ill-advised) cache. The CompoundExpression time, I think, includes the time spent it calls SetDelayed, Block, If, Set, etc.

[rocky]

and after that:

Patching With[]...
  C-c C-c
interrupt> s
ReplaceAll[expr_, rules_]
System`ReplaceAll[System`DownValues[Rubi`Int], Rubi`Private`dvFixWith]

which probably comes from line 217 of Rubi.m:

DownValues[Int] = DownValues[Int] /. dvFixWith /. dvFixWithNoCond;

Looked at this with the Mathics3 debugger a little. We have a lot of calls in _rebuild_cached():

Patching With[]...
  C-c C-c
interrupt: ReplaceAll[DownValues[Int], dvFixWith]

(/tmpMathics3/mathics-core/mathics/core/expression.py:448 @188): _rebuild_cache
448         sym = set((self.get_head_name(),))
(Mathics3 Debug) backtrace -e
E>0 (0) Expression._rebuild_cache <class 'mathics.core.expression.Expression'>
         _rebuild_cache(Times[2, n],
	)
     called from file '/tmpMathics3/mathics-core/mathics/core/expression.py' at line 448
E:1 (1) Expression._rebuild_cache <class 'mathics.core.expression.Expression'>
         _rebuild_cache(Plus[Times[2, n], Times[-1, q]],
	)
     called from file '/tmpMathics3/mathics-core/mathics/core/expression.py' at line 453
E:2 (2) Expression._rebuild_cache <class 'mathics.core.expression.Expression'>
         _rebuild_cache(EqQ[j, Plus[Times[2, n], Times[-1, q]]],
	)
     called from file '/tmpMathics3/mathics-core/mathics/core/expression.py' at line 453
E:3 (3) Expression._rebuild_cache <class 'mathics.core.expression.Expression'>
         _rebuild_cache(And[FreeQ[{a, b, c, A, B}, x], EqQ[r, Plus[n, Times[-1, q]]], EqQ[j, Plus[Times[2, n], Times[-1, q]]...),
	)
     called from file '/tmpMathics3/mathics-core/mathics/core/expression.py' at line 453
E:4 (4) Expression._rebuild_cache <class 'mathics.core.expression.Expression'>
         _rebuild_cache(Condition[Int[Times[Plus[A:_, Times[Optional[B:_], Power[x:_, Optional[r:_]]]], Power[x:_, Optional[...),
	)
     called from file '/tmpMathics3/mathics-core/mathics/core/expression.py' at line 453
E:5 (5) Expression._rebuild_cache <class 'mathics.core.expression.Expression'>
         _rebuild_cache(HoldPattern[Condition[Int[Times[Plus[A:_, Times[Optional[B:_], Power[x:_, Optional[r:_]]]], Power[x:...),
	)
     called from file '/tmpMathics3/mathics-core/mathics/core/expression.py' at line 453
E:6 (6) Expression._rebuild_cache <class 'mathics.core.expression.Expression'>
         _rebuild_cache(HoldPattern[HoldPattern[Condition[Int[Times[Plus[A:_, Times[Optional[B:_], Power[x:_, Optional[r:_]]...),
	)
     called from file '/tmpMathics3/mathics-core/mathics/core/expression.py' at line 453
E:7 (7) Expression._rebuild_cache <class 'mathics.core.expression.Expression'>
         _rebuild_cache(HoldPattern[HoldPattern[Condition[Int[Times[Plus[A:_, Times[Optional[B:_], Power[x:_, Optional[r:_]]...),
	)
     called from file '/tmpMathics3/mathics-core/mathics/core/expression.py' at line 453
E:8 (8) Expression._rebuild_cache <class 'mathics.core.list.ListExpression'>
         _rebuild_cache({HoldPattern[HoldPattern[Int[Times[-1, u:_], x:_ Symbol]]] :> Simp[Times[Identity[-1], Int[u, x]], x...),
	)
     called from file '/tmpMathics3/mathics-core/mathics/core/expression.py' at line 453
E:9 (9) Expression.sequences <class 'mathics.core.list.ListExpression'>
         sequences({HoldPattern[HoldPattern[Int[Times[-1, u:_], x:_ Symbol]]] :> Simp[Times[Identity[-1], Int[u, x]], x...),
	)
     called from file '/tmpMathics3/mathics-core/mathics/core/expression.py' at line 1511
E:10 (10) Expression._flatten_sequence <class 'mathics.core.list.ListExpression'>
           _flatten_sequence({HoldPattern[HoldPattern[Int[Times[-1, u:_], x:_ Symbol]]] :> Simp[Times[Identity[-1], Int[u, x]], x...),
	sequence=<function Expression.flatten_pattern_sequence.<locals>.sequence at 0x757b3b5d3d80>)
     called from file '/tmpMathics3/mathics-core/mathics/core/expression.py' at line 403
E:11 (11) Expression.flatten_pattern_sequence <class 'mathics.core.list.ListExpression'>
           flatten_pattern_sequence({HoldPattern[HoldPattern[Int[Times[-1, u:_], x:_ Symbol]]] :> Simp[Times[Identity[-1], Int[u, x]], x...),
	)
     called from file '/tmpMathics3/mathics-core/mathics/core/expression.py' at line 646
E:12 (35) Expression.rewrite_apply_eval_step <class 'mathics.core.expression.Expression'>
           rewrite_apply_eval_step(ReplaceAll[DownValues[Int], dvFixWith],
	)
     called from file '/tmp/Mathics3/mathics-core/mathics/core/expression.py' at line 1427
(Mathics3 Debug)