mzscheme103 profiler

[Alexander Taranov <tay@jet.msk.su>]

Hi,
I've tried to use mzscheme profiler.
Results are very unclear to me.

Here are code snippets and results

(define (print-profiling-results)
  (for-each 
   (lambda (rec) 
     (printf "~a	~a	~a	~a	~a~n"
	     (list-ref rec 2);name
             (list-ref rec 0);num calls
	     (list-ref rec 1);time
	      ":"
	     (list-ref rec 3);filename
	     ))
   (get-profile-results)
   ))

(require-library "errortrace.ss" "errortrace")
(instrumenting-enabled #t) ;switch on errortrace
(profiling-enabled #t) ;switch on profiling

;; 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?

-AT