Problems with profiling results (hotshot or normal) : almost allare 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)

[Bengt Richter]

On Wed, 03 Nov 2004 00:43:31 +0100, Irmen de Jong <[e-mail]> wrote:

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.

Traceback (most recent call last):
File "C:\pywk\clp\irmen2.py", line 86, in ?
import hotshot, hotshot.stats, wait
ImportError: No module named wait

Where does wait come from?

Regards,
Bengt Richter

[Irmen de Jong]

Bengt Richter wrote:

On Wed, 03 Nov 2004 00:43:31 +0100, Irmen de Jong <[e-mail]> wrote:

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.

Traceback (most recent call last):
File "C:\pywk\clp\irmen2.py", line 86, in ?
import hotshot, hotshot.stats, wait
ImportError: No module named wait

Where does wait come from?

Aww, terribly sorry. Should test any code that I post.
(I called the test script "wait.py" on my system, that's
why it worked here, locally)

Here's a fixed version:

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
import profile, pstats

print "HOTSHOT profiling..."
prof = hotshot.Profile("wait.prof")
prof.runcall(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('test()', 'wait.prof')
print "profile done"
stats = pstats.Stats('wait.prof')
stats.strip_dirs()
stats.sort_stats('time', 'calls')
stats.print_stats(40)