Summary

Profiler does not work correctly on recursive procedures

Metadata

Description

The profiler seems to calculate the time spent on recursive funtion calls incorrectly.

Here is a simple example program:

 (define (fib n)
     (if (or (equal? n 0) (equal? n 1))
         n
         (+ (fib (- n 1)) (fib ( - n 2)))))
 
 (define (main)
   (let loop [(i 100)]
     (if (> i 0)
 	(begin
 	  (fib 15)
 	  (loop (sub1 i))))))
 
 (main)

And here is a sample output from chicken-profiler:

 procedure   calls  seconds  average  percent
 --------------------------------------------
 fib        197300    4.695    0.000  100.000
 main            1    0.092    0.092    1.959

Changes and comments

[2011-07-06 08:21:09 UTC] felix wrote:

The percentages are indeed wrong. I've changed this in commit 9663b2e (master). The other numbers seem to be correct - the average gives the average time of one execution of a procedure over the total time the procedure used during execution of the complete program.

[2011-07-06 10:57:12 UTC] megane wrote:

Replying to felix: > The percentages are indeed wrong. I've changed this in commit 9663b2e (master). The other numbers seem to be correct - the average gives the average time of one execution of a procedure over the total time the procedure used during execution of the complete program.

The total seconds for fib is wrong, also. The program ran for a total of 0.092 seconds but the total time for fib is way bigger than that.

Sorry for not pointing this in the first post.

[2011-09-23 09:04:44 UTC] felix changed status from new to assigned

[2011-09-23 09:04:44 UTC] felix set owner to felix

[2011-09-23 10:28:59 UTC] felix changed status from assigned to closed

[2011-09-23 10:28:59 UTC] felix set resolution to fixed

[2011-09-23 10:28:59 UTC] felix wrote:

This should work now. There have been a few fixes in the internal profiling timing code and the timings from your example look ok.