[plt-scheme] Question on profiling

At Thu, 5 Mar 2009 10:57:30 +0100, "Ballnat, Stefan" wrote:
> I was just profiling my code in DrScheme because of some performance
> problems. I read the documentation about "Using errortrace" but still
> have a problem.
> 
> I have a simple function like:
> 
> (define (slow-func x y)
>   (let* ((a (foo1 x))
>          (b (foo2 y)))
>     (foo3 a b)))
> 
> With some function definitions:
> 
> (define (foo1 x) ... )
> (define (foo2 y) ... )
> (define (foo3 a b) ... )
> 
> Now the output of the profile is (about):
> 
> slow-func 	- 6000ms 	- 1 call
> foo1		- 0ms 	- 1 call
> foo2		- 0ms 	- 1 call
> foo3 		- 0ms 	- 1 call
> 
> Now, I wonder how I should interpret these results? How can "slow-func"
> run so slow when the rest runs so fast?

This may be because the time attributed to a function does not include
tail calls from the function, and maybe your program is spending all
its time in library functions that are tail-called.

For example, profiling

 #lang scheme

 (define (all i)
   (if (zero? i)
       'done
       (begin
         (compute i)
         (all (sub1 i)))))

 (define (compute i)
   (build-list i add1))
 
 (all 10000)

shows that all the time is in `all', but almost no time is in
`compute'. Most of use would be inclined to say that all the time in
this program is in `compute' during the call to `build-list'. From the
profiler's perspective, however, the call to `build-list' is not inside
`compute', since it's a tail call.

> Is this behavior a result of the let*-expression and would it be
> of help, if I define "a" and "b" in some separate functions or writing
> "(foo3 (foo1 x) (foo2 y))" instead?

No, those kinds of transformations won't change the result. Changing
`foo1', `foo2', and `foo3' so that tail calls are non-tail (perhaps by
wrapping tail calls with `(values ...)') could change the result.