#471 recursive calls not correctly accounted in timing

[Robert Dodier]

TIMER_INFO gets units of time mixed up -- in the
example below, should show 0.25 seconds instead of 25
seconds; setting TIMER_DEVALUE:TRUE before calling
FF(200) makes the time come out as 0.25 seconds as
expected.

Note that the time reported for GG is 25 seconds while
the time for FF is 0.25 seconds -- the two should be
identical or nearly so.

See also bug report #572835 ("timer_info gives
incorrect time").

Maxima 5.9.0 cvs version of 20031128, clisp 2.31,
redhat linux 7.1 (kernel 2.4.2).

--- begin example about timing_info ---
(C1) GG(n):=if equal(n,0) then 0 else n+GG(n-1);
(D1) GG(n) := IF EQUAL(n, 0) THEN 0 ELSE n + GG(n - 1)
(C2) FF(n):=GG(n);
(D2) FF(n) := GG(n)
(C3) timer(FF,GG);
(D3) [FF, GG]
(C4) timer_info();
[ FUNCTION TIME//CALL CALLS RUNTIME
GCTIME ]
[
]
[ GG 0 0 0
0 ]
(D4) [
]
[ FF 0 0 0
0 ]
[
]
[ TOTAL 0 0 0
0 ]
(C5) FF(200);
(D5) 20100
(C6) timer_info();
[ FUNCTION TIME//CALL CALLS
RUNTIME GCTIME ]
[
]
[ GG .1262686567164179 SEC 201
25.38 SEC 0 ]
(D6) [
]
[ FF 0.25 SEC 1 0.25
SEC 0 ]
[
]
[ TOTAL .1268811881188119 SEC 202
25.63 SEC 0 ]
--- end example about timing_info ---

[Dieter Kaiser]

I think we have no longer a problem with the function timer_info. The time per call for the reported example is not very accurate, but the values are sumed correctly.

(%i3) GG(n):=if equal(n,0) then 0 else GG(n-1)+n
(%i4) FF(n):=GG(n)
(%i5) timer(FF,GG)
(%i6) FF(500)
(%i7) timer_info()
(%o7) matrix([function,time\/\/call,calls,runtime,gctime],
[GG,.07129367864271456*sec,501,35.718133*sec,0],
[FF,0.144009*sec,1,0.144009*sec,0],
[total,.07143852988047808*sec,502,35.862142*sec,0])

This is an example for a function which needs much more time:

(%i8) ff(x):=block([fpprec:x],gamma_incomplete(5.0b-1,1.0b0),done)

The first call is needed to initialize internal values:

(%i9) ff(1024)
(%i10) untimer(FF,GG)
(%i11) timer(ff)

On my (slow) computer the function needs about 2.7 seconds per call. This is displayed correctly:

(%i12) ff(1024)
(%i13) timer_info()
(%o13) matrix([function,time\/\/call,calls,runtime,gctime],
[ff,2.684167*sec,1,2.684167*sec,0],
[total,2.684167*sec,1,2.684167*sec,0])

Further calls are added up correctly:

(%i14) ff(1024)
(%i15) timer_info()
(%o15) matrix([function,time\/\/call,calls,runtime,gctime],
[ff,2.708169*sec,2,5.416338*sec,0],
[total,2.708169*sec,2,5.416338*sec,0])
(%i16) ff(1024)
(%i17) timer_info()
(%o17) matrix([function,time\/\/call,calls,runtime,gctime],
[ff,2.654832333333333*sec,3,7.964497*sec,0],
[total,2.654832333333333*sec,3,7.964497*sec,0])

Setting the status to "pending" and "works for me".

Dieter Kaiser

[SourceForge Robot]

This Tracker item was closed automatically by the system. It was
previously set to a Pending status, and the original submitter
did not respond within 14 days (the time period specified by
the administrator of this Tracker).

[Robert Dodier]

Reopening this report. On looking at this again, it appears that the problem is that Maxima is not correctly accounting for time spent in recursive calls in GG, and that this problem still exists.

[Robert Dodier]

Looks like problem was misidentified before, therefore changing summary.