[Maxima-bugs] [ maxima-Bugs-859902 ] recursive calls not correctly accounted in timing

[SourceForge.net <no...@so...>]

Bugs item #859902, was opened at 2003-12-14 10:54
Message generated for change (Comment added) made by robert_dodier
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=104933&aid=859902&group_id=4933

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: Lisp Core
Group: None
Status: Open
Resolution: None
Priority: 5
Private: No
Submitted By: Robert Dodier (robert_dodier)
Assigned to: Nobody/Anonymous (nobody)
>Summary: recursive calls not correctly accounted in timing

Initial Comment:
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 ---

----------------------------------------------------------------------

>Comment By: Robert Dodier (robert_dodier)
Date: 2010-06-22 13:01

Message:
Looks like problem was misidentified before, therefore changing summary.

----------------------------------------------------------------------

Comment By: Robert Dodier (robert_dodier)
Date: 2010-06-22 10:35

Message:
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.

----------------------------------------------------------------------

Comment By: SourceForge Robot (sf-robot)
Date: 2009-11-17 19:20

Message:
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).

----------------------------------------------------------------------

Comment By: Dieter Kaiser (crategus)
Date: 2009-11-03 15:09

Message:
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

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=104933&aid=859902&group_id=4933