# Profiling Recursive Routines

We will call any function that calls itself or that is eventually called by a child function recursive. In AQTime terms, a recursive function is one that belongs to its own descendants (children, grandchildren, etc.). For the Performance profiler, this poses an unavoidable problem regarding what AQTime should call Time with Childrenand what it should call Time (that is, without children) for this type of a function.

This topic explains the Time with Children problem for recursive functions, and the solution that is adopted by the Performance profiler.

 Note: Time with Children present in the Performance profiler results only if you use the Elapsed Time, User Time or User+Kernel Time counters. If you profile your application with any other counter, for example, with CPU Cache Misses or Hard Memory Page Faults, Time with Children as well as other “Timing” results (such as Average Time, Min Time, etc.) will be replaced with similar values: Misses With Children, Faults with Children, Average Misses, Average Faults, etc. AQTime calculates these values in the same way it calculates the “Time” values. In further explanations we will use “Time”, but since the results are similar, the explanations are also true for “Misses”, “Faults” and other results.

Time and Time with Children apply not to one call, but to the sum of calls throughout the profile run. Now, imagine that one function, `FuncA`, calls itself three times in a row, so that the original call, `FuncA1`, gives rise to three more, `FuncA2`, `FuncA3` and `FuncA4`. Imagine also that `FuncA` takes 2 seconds to execute its own code. If these are the only calls during the profile run, Time should be 8 seconds. But Time with Children?

FuncA4 = 2

FuncA3 = 4

FuncA2 = 6

FuncA1 = 8

Total = 20 seconds

Now, imagine that the entire run was simply the original `FuncA1` call. The entire run lasted 8 seconds, but Time with Children for `FuncA` is 20 seconds. This is grossly misleading. The reason is that one single execution, `FuncA4`, is counted separately as part of the child time for `FunA3`, `FuncA2` and `FuncA1`, and it is also counted once as its “own” time - it is counted four times in all. Likewise, `FuncA3` is counted three times and `FuncA2` is counted twice. These repeat counts for the same actual execution bloat up Time with Children as soon as there is recursion.

In the very simple example above, we also know what solution we would like to see; Time with Children should be identical to the run time, 8 seconds. That is, the same as Time itself, since both values count exactly the same calls (`FuncA1` through `FuncA4`).

The Performance profiler detects the recursive calls and counts Time and Time with Children for recursive functions properly. With our simple `FuncA` example, this means `FuncA2`, `FuncA3` and `FuncA4` contribute nothing to Time with Children, so it remains what it was for `FuncA1` alone, 8 seconds, the same as the run time. This is what we wanted.

Just to make sure everything is clear; here is a somewhat more complex example:

The timings are time spent executing the function itself.

The Performance profiler will report the following results:

Click the image to enlarge it.

Click the image to enlarge it.

Click the image to enlarge it.

The net time of `FuncA` is about 18 seconds (10 seconds for the first call plus 8 seconds for the second call). `FuncD` and `FuncB` are child routines of `FuncA`. The Time and Time with Children results for them corresponds to the actual execution time of these routines. `FuncC` is a parent routine for `FuncA`. As we can see, the net time of the `FuncA` call, which was made within `FuncC`, is about 8 seconds and Time with Children is 10 seconds. These values also match to the actual time of function calls.

 Note: If the first call to `FuncA` is not profiled for any reason (for instance, it is excluded by an off-trigger), the Performance profiler detects no recursion.
Highlight search results