# Timing functions with Sow / Reap and AbsoluteTiming

I have a main function f[x] that calls three sub-functions:

f1[x_] := x^2;
f2[x_] := x + 5;
f3[x_] := Sin[x];

f[x_] := f1[x] + f2[f3[x]]


(In my real application, the functions are more complicated.)

I would like to time how long f1, f2, and f3 take to execute, without re-defining them or f.

One idea is to temporarily replace f1 with a function that times f1 and uses Sow to return the time, like this:

With[
{
f1[x_] := Block[{t, z}, {t, z} = AbsoluteTiming[f1[x]]; Sow[t]; Return[z]]
},
Reap[f[x]]
]


Or this:

Block[
{
f1 = Function[x, Block[{t, z}, {t, z} = AbsoluteTiming[f1[x]]; Sow[t]; Return[z]]]
},
Reap[f[x]]
]


(And do the same for f2 and f3)

However, both these forms produce errors.

Is there a way to temporarily "inject" AbsoluteTiming into a function, and use Sow/Reap to obtain timing information?

Update

It seems that TraceScan was just what I needed:

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]
]


returns

{h[x],0.201649s}
{g[x],0.100481s}


Thanks Carl Woll for your example use of TracePrintEvaluate!

• i think you need to elaborate on what you are actually trying to accomplish. If you are modifying the calling code with Reap why not just directly use AbsolutTiming ? Oct 2, 2017 at 20:31
• I have a big complicated function that calls several other complicated sub-functions. The big function runs slowly, so I'd like to append a section to my notebook that performs a timing analysis. However, I would prefer to not re-write my functions to include AbsoluteTiming because I feel it would distract the reader from the main goal of my code. That is, I would like to perform a timing investigation after the functions have been defined and demonstrated, without modifying them with timing code. Oct 7, 2017 at 12:45

One idea is to use my TracePrintEvaluate function:

TracePrintEvaluate[f[x], _f1|_f2|_f3, "Timing"->True]


f1[x]

f2[f3[x]]

f3[x]

f2[Sin[x]]

5 + x^2 + Sin[x]

Clicking on any of the trace outputs will show what the expression evaluated to, and then the time it took to do the evaluation. Below, I show the output after clicking on each of the trace outputs twice:

TracePrintEvaluate[f[x], _f1|_f2|_f3, "Timing"->True]


0.000077

0.000404

0.000038

0.000032

5 + x^2 + Sin[x]

Note that using TracePrintEvaluate, just like using any Trace* function, will instrument the evaluation process, hence the timings shown will be larger than the actual timings. However, it will give you an idea of where slow points are so that you can speed up those portions of the code.

• Thanks Carl, that's a neat tool. Reading your code inspired me to explore TraceScan, and I think it will work. I've added my findings to my post. Oct 7, 2017 at 14:08