Problems with profiling results (hotshot or normal) : almost all are incorrect

[Irmen de Jong]

Okay I tried some profiling, but am uncertain about the
results I'm getting. They confuse the hell out of me.

I have a test program (see below) that essentially has
two loops that get called repeatedly. One that is an idle
wait loop, and one that is a busy-wait CPU hogger.
I wanted to see what profiling results that would give.
The total runtime of the program is 10 seconds, where 5
seconds are spent in the CPU-loop and 5 seconds in the idle
wait loop.

But what I'm getting is not what I expected.

For instance, with python2.3.4 on windows, it says:
(hotshot:)  21 function calls in 35.772 CPU seconds
(normal: )  23 function calls in 10.008 CPU seconds
Python 2.4b1 on windows gives:
(hotshot:)  21 function calls in 0.001 CPU seconds
(normal: )  260362 function calls in 6.724 CPU seconds

I know that timing information on Windows is sometimes
difficult to get, but the above is really weird. Anyway
so I also tried it on my Linux (mandrake 10) computer:

Python 2.3.4 on linux:
(hotshot:)  21 function calls in 17.542 CPU seconds
(normal: )  23 function calls in 5.000 CPU seconds
Python 2.4b1 on linux:
(hotshot:) 21 function calls in 0.000 CPU seconds
(normal: ) 52474 function calls in 1.650 CPU seconds

Conclusion: only *one* of the above test runs gives the
right summary (in my opinion): the normal profiler of
python 2.3.4 on linux (5 CPU seconds).
The normal profiler of python 2.3.4 on windows also counts
the idle loop time apparently, and gives 10 CPU seconds.
But all the others are waaaay off!

(and I haven't event talked about the detailed function
call profiling statistics).

Can anybody please help me out? Am I doing something wrong,
or is the profiler just not reliable yet?

Confused-ly y'rs,
--Irmen de Jong


PS using the 'time' command on linux, when running the test
program, gives 0:20.19elapsed 50%CPU which is what I expected.


-------------------- test program ---------------
import time

def foo():
     # idle wait loop
     time.sleep(0.5)
def bar():
     # busy (CPU) wait loop
     s=time.time()
     while time.time()<(s+0.5):
         pass

def test():
     for i in range(10):
         foo()
         bar()

if __name__=="__main__":
     import hotshot, hotshot.stats, wait
     import profile, pstats

     print "HOTSHOT profiling..."
     prof = hotshot.Profile("wait.prof")
     prof.runcall(wait.test)
     prof.close()
     print "PROFILE DONE"
     stats = hotshot.stats.load("wait.prof")
     stats.strip_dirs()
     stats.sort_stats('time', 'calls')
     stats.print_stats(40)

     print "Normal profiler..."
     profile.run('wait.test()', 'wait.prof')
     print "profile done"
     stats = pstats.Stats('wait.prof')
     stats.strip_dirs()
     stats.sort_stats('time', 'calls')
     stats.print_stats(40)