Re: A problem with statprof

[Mark H Weaver]

Hi,

Tommi Höynälänmaa <address@hidden> writes:

> It seems that statprof gives some second counts in some other units
> than seconds. I'm using guile 2.9.1. Consider the following program:
>
> ---cut here---
> (import (statprof))
>
> (define (factorial n)
>   (if (= n 0) 1 (* n (factorial (- n 1)))))
>
> (define (main args)
>   (statprof-reset 0 50000 #t)
>   (statprof-start)
>   (display "Hello\n")
>   (display (factorial 100000))
>   (newline)
>   (statprof-stop)
>   (statprof-display))
> ---cut here---
>
> This program gives the following output:
> ---cut here---
> ...
> %     cumulative   self
> time   seconds    seconds   calls   procedure
>  57.14      1.83      1.83                            anon #x55f314c21e40
>  41.07 111105.81      1.32
> /home/tohoyn/tyo/omat/ohj/scheme/muut/statprof-test2.scm:4:0:factorial
>   1.79      0.06      0.06                            anon #x55f314c27a38
>   0.00      3.21      0.00 ice-9/eval.scm:618:6
>   0.00      3.21      0.00 ice-9/boot-9.scm:701:0:call-with-prompt
>   0.00      3.21      0.00
> /home/tohoyn/tyo/omat/ohj/scheme/muut/statprof-test2.scm:7:0:main
>   0.00      3.21      0.00                            anon #x55f314c29930
>   0.00      1.83      0.00                            anon #x55f314c1f7e0
> ---
> Sample count: 56
> Total time: 3.206961337 seconds (1.765094628 seconds in GC)
> ---cut here---
>
> Obviously the cumulative time for procedure factorial is not given in
> seconds. OTOH the time for procedure main is correct. What is wrong
> here?

I'm not sure there's anything wrong here, but I agree that it's
counterintuitive.  Here's a paragraph from the "Implementation notes"
for statprof in the Guile manual:

     Later, when profiling stops, that log buffer is analyzed to produce
  the “self seconds” and “cumulative seconds” statistics.  A procedure
  at the top of the stack counts toward “self” samples, and everything
  on the stack counts towards “cumulative” samples.

In this case, while the program runs, the call stack will be full of a
very large number of stack frames associated with 'factorial'.  This has
a magnifying effect on the cumulative total for 'factorial'.

At the deepest point in the recursion, there will be 100 thousand active
stack frames for 'factorial' on the call stack.  To simplify things a
bit, suppose that the profiler finds that we spent 1 millisecond at that
stack depth.  How will that 1 millisecond contribute to the statistics?

According to the text above, it is supposed to add 1 millisecond of time
to the "self" total for the procedure on the top of the call stack
(factorial), and it's also supposed to add 1 millisecond to the
"cumulative" total of each procedure on the call stack.  In other words,
it loops over every stack frame, and for each one it adds 1 millisecond
to the associated procedure.  In this case, since there are 100 thousand
active stack frames for 'factorial', that single millisecond of real
time will lead to 100 thousand milliseconds (i.e. 100 seconds) being
added to the cumulative total of 'factorial'.

So, I believe that 'statprof' is working as it was designed to.  Whether
this design makes sense is another question.  I admit that I don't know
much about profilers, so I'm not yet prepared to have a useful opinion
on this question.

      Regards,
        Mark