11
$\begingroup$

[

Edit 2: The resource function TraceView gives a nice way to visualise the timing. This Resource function is also mentioned here :

https://mathematica.stackexchange.com/a/278723/86543

]

[

Edit: I searched the wolfram function repository and there is a nice function EvaluationTiming by a Wolfram Research member that makes a dataset from the timing data of a computation.

If we set data=ResourceFunction["EvaluationTiming"][f /@Range[5]], then data//Dataset gives summary statistics and data["ProfilingData"] // Dataset shows the raw data where one can check the stack that preceded the computation of a sub expression. It would be ideal if it looked at the details of the computations inside functions as is the case of the current solutions below.

The current version of that resource function seems to mainly look at the timing from user defined functions in the Global context and functions in the head of the expression. If this is true, one can not find which part/subexpression of the user defined functions was consuming time unless it was defined by a variable.

]


The purpose of this question is to have a visual way to see which parts of a computation use the most time. The code in my answer works nicely but it is slow. I will accept any answer that is faster than the code I provided (while being easy to read) regardless of whether it uses any parts of that code.

An example of how to use TraceScan for timing function evaluation is given here which I have copy pasted:

g[x_] := (Pause[.1]; Cos[x])
h[x_] := (Pause[.2]; Tan[x])
f[x_] := h[x] + Sin[g[x]]

Block[
 {list = {}, t},
 TraceScan[
  (t = Now) &,
  f[x],
  _g | _h,
  (AppendTo[list, {#, Now - t}];) &
  ];
 Column[list]
 ];

Are there any alternatives ?

Note: I never really understood the Mathematica debugger and so I do not know if the debugger can be used for that purpose (in an automatic way not looking at each individual function that one function calls).

$\endgroup$
0

2 Answers 2

8
+100
$\begingroup$

You can use TraceScan and SessionTime to get timing while calculating subexpressions only once.

ClearAll[inlineTiming]
SetAttributes[inlineTiming, HoldFirst]
inlineTiming[expr_, timestamp_ : TimeObject] :=
 Module[
  {res, times = {}, ts, t}
  , res =
   TraceScan[
    (ts = timestamp[]; t = SessionTime[];) &
    , expr
    , _[___]
    , (AppendTo[times, {HoldForm[#], ts, SessionTime[] - t}];) &
    ]
  ; {times, res}
  ]

inlineTiming gives the held expression, the timestamp when it was called, and the session time duration for it to be evaluated. The timestamp function is defaulted to TimeObject; DateObject is also a reasonable function to pass.

With

g[x_] := (Pause[.1]; Cos[π])
h[x_] := (Pause[.2]; Tan[x])
f[x_] := h[x] + Sin[g[x]]

inlineTiming[f[x]] takes similar time as f[x] and gives same result.

AbsoluteTiming[f[x]]
First@AbsoluteTiming[it = inlineTiming[f[x]];]
it[[2]]
{0.326913, -Sin[1] + Tan[x]}
0.343894
-Sin[1] + Tan[x]

View timings in BarChart.

BarChart[
 it[[1, All, -1]]
 , ChartLabels -> it[[1, All, 1]]
 , BarOrigin -> Left
 , AxesLabel -> {None, "seconds"}
 ]

enter image description here

Also with

q[g_] := (Pause[0.1]; qq)
t[g_] := (Pause[0.2]; tt)

inlineTiming takes similar time as expression and gives same result.

AbsoluteTiming[q[n]*2 + t[q[r]]]
First@AbsoluteTiming[it2 = inlineTiming[q[n]*2 + t[q[r]]];]
it2[[2]]
{0.44868, 2 qq + tt}
0.454456
2 qq + tt

View timings in BarChart.

BarChart[
 it2[[1, All, -1]]
 , ChartLabels -> it2[[1, All, 1]]
 , BarOrigin -> Left
 , AxesLabel -> {None, "seconds"}
 ]

enter image description here

Hope this helps.

$\endgroup$
7
  • $\begingroup$ I have been hoping/waiting for a day like this for the last 2 months. This looks great ! I will play with it a bit and wait a bit more before giving the bounty to see if anyone else wants to try. Thank you very much.+1 $\endgroup$ Oct 12, 2022 at 2:51
  • $\begingroup$ Hi, thanks again. Why is it that inlineTiming behaves so differently in the two examples ? I like what it shows in the second element as it shows which functions take the most time and what are the parts of those functions that are taking the time. It gives a hierarchical view by levels of detail of what is going on and attributes the total time weight of the entire evaluation (partly it does not compute the time for the total evaluation it seems). $\endgroup$ Oct 13, 2022 at 1:52
  • $\begingroup$ In the first example it seems to only show the timing of the elementary steps, for example it neglects the time to evaluate the functions h and g whereas it does count the time of q and t in the second example . Basically, it seems to not always accumulate the total time of all the sub-expressions and I am not sure why. $\endgroup$ Oct 13, 2022 at 6:19
  • 1
    $\begingroup$ Thank you again. It is my first time giving a bounty, if you did not receive the bounty I can check if there was any bug and how to fix it. $\endgroup$ Oct 13, 2022 at 21:26
  • 1
    $\begingroup$ @userrandrand Received with thanks. $\endgroup$
    – Edmund
    Oct 13, 2022 at 21:43
6
$\begingroup$

[

Edit: The resource function TraceView gives a nice way to visualise the timing. The output is obtained faster than with the code below. This Resource function is also mentioned here :

https://mathematica.stackexchange.com/a/278723/86543

]

/!\ Warning for codes that are CPU time intensive or memory intensive, the code below might cause the notebook to stop responding. Please save the notebook before trying the code below.

[EDIT: The code is the same I just rewrote the answer and question to make it easier to read]

I found an inefficient way to add the timing.

It uses the code provided in this answer to visualize the evaluation sequence. The only modification I made in that code (other than a color change) was to add

{"Time", First@AbsoluteTiming@ReleaseHold[e]} 

next to

{"Result", r}

which leads to multiple evaluations of the same computation and thus significantly increases the time to obtain the visualization.

new code :

ClearAll@traceView8;
traceView8[expr_] := 
 Module[{steps = {}, stack = {}, pre, post, show, dynamic}, 
  pre[e_] := (stack = {steps, stack}; steps = {}); 
  post[e_, r_] := (steps = 
     First@stack~Join~{show[e, HoldForm[r], steps]}; 
    stack = stack[[2]]); SetAttributes[post, HoldAllComplete]; 
  show[e_, r_, steps_] := 
   Grid[steps /. {{} -> {{"Expr  ", 
         Row[{e, " ", 
           Style["inert", {Italic, Small}]}]}}, _ -> {{"Expr  ", 
         e}, {"Steps", steps /.
          {{} -> Style["no definitions apply", Italic], _ :> 
            OpenerView[{Length@steps, 
              dynamic@Column[steps]}]}}, {"Time", 
         First@AbsoluteTiming@ReleaseHold[e]}, {"Result", r}}}, 
    Alignment -> Left, Frame -> All, 
    Background -> {{Lighter[Green]}, None}]; 
  TraceScan[pre, expr, ___, post]; 
  Deploy@Pane[steps[[1]] /. dynamic -> Dynamic, ImageSize -> 10000]]
SetAttributes[traceView8, {HoldAllComplete}]

example :

Block[{q, qq, t, tt, n, r}, q[g_] := (Pause[0.1]; qq); 
 t[g_] := (Pause[0.2]; tt); 
 traceView8[q[n]*2 + t[q[r]]]]

gives the following output :

result

However, it takes about 3 seconds to obtain that result when it takes around 0.5 seconds with traceview2. If the code to be profiled takes too long for traceView8 to be of practical use, then maybe the code here (described in the next sentence) could be used, perhaps in conjunction with traceView2. The code provided in that last link gives the evaluation time for each step (after clicking the respective step) as in the case of traceView8 but it displays all the steps at once. If a pattern is used a subset of the steps is shown.

$\endgroup$

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.