cProfiler Question

[Brian Stinar]

Hello,

I am not certain if I understand the .enable() and .disable() methods
correctly, but it seems like they should make a profiling object stop
collecting profiling information. When I run the below python program,
I am seeing results that I am not expecting. If anyone has insight
into why my expectations and reality are not meeting up (just with
regards to the below program, not all my hopes and dreams), I would be
happy to hear them.


--------------------------------------------------- Begin Example Code

from cProfile import *
from pstats import *

p=Profile()

def foo():
a=[]
for i in xrange(1000):
bar()
a.append(i)
#print a

def bar():
d={}
a=[]
p.disable()
for i in xrange(1000):
d=[i+1]
a.append(i)
p.enable()

def main():
p.run("foo()")
#p.print_stats()
p.dump_stats("foo.prof")
s=Stats("foo.prof")
s.print_stats()
s.print_callers()


if __name__ == "__main__":
main()


--------------------------------------------------- End Example Code

OK, so I want to profile the a.append(i) within foo, and not profile
the a.append(i) within bar. Here are the results I receive:



--------------------------------------------------- Begin Results for Example

brian.stinar@lambda ~/spider_project $ ./profiler_tester.py
Mon Oct 20 20:13:51 2008 foo.prof

3003 function calls in 0.002 CPU seconds

Random listing order was used

ncalls tottime percall cumtime percall filename:lineno(function)
1000 0.001 0.000 0.001 0.000 ./profiler_tester.py:18(bar)
1000 0.000 0.000 0.000 0.000 {method 'append' of
'list' objects}
1001 0.000 0.000 0.000 0.000 {method 'disable' of
'_lsprof.Profiler' objects}
1 0.000 0.000 0.000 0.000 ./profiler_tester.py:11(foo)
1 0.000 0.000 0.000 0.000 <string>:1(<module>)


Random listing order was used

Function was called by...
ncalls tottime cumtime
../profiler_tester.py:18(bar) <- 1 0.000
0.000 ./profiler_tester.py:11(foo)
{method 'append' of 'list' objects} <-
{method 'disable' of '_lsprof.Profiler' objects} <- 1000 0.000
0.000 ./profiler_tester.py:18(bar)
../profiler_tester.py:11(foo) <- 1 0.000
0.000 <string>:1(<module>)
<string>:1(<module>) <-



--------------------------------------------------- End Results for Example

The results from s.print_stats() look OK. 1000 calls to append. This
makes sense, since foo is calling it 1000 times. However, when we look
at the s.print_callers() I become confused by append. The data for
append looks like it is missing.

When I comment out the disable and enable profiling commands, I get
what I am expecting:


--------------------------------------------------- Begin Results for
Commented Out disable and enable

Mon Oct 20 20:21:33 2008 foo.prof

1002003 function calls in 1.243 CPU seconds

Random listing order was used

ncalls tottime percall cumtime percall filename:lineno(function)
1000 0.895 0.001 1.153 0.001 ./profiler_tester.py:18(bar)
1001000 0.258 0.000 0.258 0.000 {method 'append' of
'list' objects}
1 0.000 0.000 0.000 0.000 {method 'disable' of
'_lsprof.Profiler' objects}
1 0.089 0.089 1.243 1.243 ./profiler_tester.py:11(foo)
1 0.000 0.000 1.243 1.243 <string>:1(<module>)


Random listing order was used

Function was called by...
ncalls tottime cumtime
../profiler_tester.py:18(bar) <- 1000 0.895
1.153 ./profiler_tester.py:11(foo)
{method 'append' of 'list' objects} <- 1000 0.000
0.000 ./profiler_tester.py:11(foo)
1000000 0.258
0.258 ./profiler_tester.py:18(bar)
{method 'disable' of '_lsprof.Profiler' objects} <-
../profiler_tester.py:11(foo) <- 1 0.089
1.243 <string>:1(<module>)
<string>:1(<module>) <-



--------------------------------------------------- End Results for
Commend Out disable and enable


So, when I avoid using enable or disable, the results from everything
look like what we are expecting.


Am I doing something wrong (or excepting something wrong), or is
cProfile doing something wrong?

Thanks,

-Brian J. Stinar-