Re: mzscheme103 profiler

[Matthew Flatt <mflatt@cs.utah.edu>]

At 05 Apr 2002 18:14:43 +0400, Alexander Taranov wrote:
> ;; procedure that takes some time...
> (define (fufl) 
>   (with-input-from-file "/usr/dict/words"
>     (lambda () (let loop ((a (read-line)))
> 		 (if (eof-object? a) #f (loop (read-line)))))))
> 
> Documentation says that profiler gives
> 
>  * the number of milliseconds consumed by the procedure's body across
>    all calls (including the time consumed by any nested non-tail call
>    within the procedure, but not including time consumed by a
>    tail-call from the procedure).
> 
> 
> bash-2.03$ mzscheme -f prof-test.scm
> Welcome to MzScheme version 103.1 (using locale), Copyright (c) 1995-2000 PLT 
> (Matthew Flatt)
> > (time (fufl))
> cpu time: 1770 real time: 1770 gc time: 20
> #f
> > (print-profiling-results)
> fufl	1	0	:	#f
> (#%lambda () ((#%letrec-values (((loop) (#%lambda (a) (#%if (eof-object? a) #f 
> (loop (read-line)))))) loop) (read-line)))	1	0	:	#f
> (#%lambda () (fufl))	1	0	:	#f
> loop	25144	960	:	#f
> > (exit)
> 
> So:
> -- `loop' calls are tail-recursive, but they were counted
> -- toplevel call (fufl) as well as inner #%lambda and #%lambda generated
> by `time' macro took no time at all?

This seems consistent to me:

 * Tail recursion doesn't affect the call count, which merely counts
   the number of entries into the procedure.

 * Although `loop' is always called tail-recusrively, it does a lot of
   work (via `read-line') that is not in tail position. All of that
   work contributes to the time charged to `loop'.

 * The `lambda' generated by `time' gets no charges because all of its
   work is in a tail-call to `fufl'.

 * If I understand what you mean by the "inner lambda", it has the name
  `loop' for its profile results.

I don't mean to claim that the results are clear! :)

Robby is connecting the profiler to DrScheme so that results are
presented on top of the program source. Natually, that makes the
results much clearer.

Matthew