Example Prof_profiler-recursion (H7E3)

In the following example, recursive is a recursive function which simply stays in a loop for half a second, and then recurses if not in the base case. Thus, the total running time should be approximately (n + 1) / 2 seconds, where n is the parameter to the function.

> procedure delay(s)
>     t := Cputime();
>     repeat
>       _ := 1+1;
>     until Cputime(t) gt s;
> end procedure;
>
> procedure recursive(n)
>     if n ne 0 then
>       recursive(n - 1);
>     end if;
>
>     delay(0.5);
> end procedure;
>
> SetProfile(true);
> recursive(1);
> SetProfile(false);
> G := ProfileGraph();

Printing the profile results by total time yield no surprises:

> ProfilePrintByTotalTime(G);
Index Name                                                     Time    Count
1     <main>                                                   1.020   1
2     recursive                                                1.020   2
5     delay                                                    1.020   2
8     Cputime(<FldReElt> T) -> FldReElt                        0.130   14880
7     +(<RngIntElt> x, <RngIntElt> y) -> RngIntElt             0.020   14880
9     gt(<FldReElt> x, <FldReElt> y) -> BoolElt                0.020   14880
3     ne(<RngIntElt> x, <RngIntElt> y) -> BoolElt              0.000   2
4     -(<RngIntElt> x, <RngIntElt> y) -> RngIntElt             0.000   1
6     Cputime() -> FldReElt                                    0.000   2
10    SetProfile(<BoolElt> v)                                  0.000   1

However, printing the children of recursive, and displaying the results in percentages, does yield a surprise:

> ProfilePrintChildrenByTime(G, 2 : Percentage);
Function: recursive
Function Time: 1.020
Function Count: 2
Index Name                                                     Time    Count
5     delay                                                    100.00  33.33
2     recursive (*)                                            50.00   16.67
3     ne(<RngIntElt> x, <RngIntElt> y) -> BoolElt              0.00    33.33
4     -(<RngIntElt> x, <RngIntElt> y) -> RngIntElt             0.00    16.67
* A recursive call is made through this child

At first glance, this doesn't appear to make sense, as the sum of the time column is 150%! The reason for this behavior is because some time is "double counted": the total time for the first call to recursive includes the time for the recursive call, which is also counted separately. In more detail:

> V := Vertices(G);
> E := Edges(G);
> Label(V!1)`Name;
<main>
> Label(V!2)`Name;
recursive
> Label(E![1,2])`Time;
1.019999999999999795718
> Label(E![2,2])`Time;
0.51000000000000000888
> Label(V!2)`Time;
1.019999999999999795718

As can seen in the above, the total time for recursive is approximately one second, as expected. The double-counting of the recursive call can be seen in the values of Time for the edges [1,2] and [2,2].