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

[Irmen de Jong]

Hello
I haven't received any responses on my original posting,
and it could very well be that it never made it to the newsgroup
(because I can't find it back on my news server here).
So I'm posting this again. Sorry if it *did* make it to
the group.. Please consider trying my test-program that is given
here and let me know how it works on your python installation.

Thanks for any insight on this.

--Irmen

[original message follows]

Irmen de Jong wrote:
> 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)
>