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]=[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 at 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-