Hi, Tommi Höynälänmaa <tommi.hoynalan...@gmail.com> 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