[docs] Python 2.7 Profile module documentation

[Quentin de Metz]

Hello to the Python documentation team,

I work in a software company in the Silicon Valley and we are using Python
(2.7) for one of our upcoming releases.

I'm working on performance testing for this software and have been fiddling
quite a bit with the profiling modules available. I believe there is a lack
of information in the official documentation and would like to report it.

I've been trying to profile our software to see where CPU bottlenecks are.
Despite reports of being able to use cProfile to measure CPU time, all of
the documentation I found on the internet seems to portray cProfile
measuring "wall time" - that is, time elapsed during a function, regardless
of actual CPU usage. (Have a look at the UNIX "time" command if you don't
know what I'm talking about.)

For example, take the following snippet:

import cProfile
import time

def sleep():
    time.sleep(2)

def count():
    for i in xrange(100000000):
        pass

def test():
    sleep()
    count()

*profiler = cProfile.Profile()*
profiler.run('test()')
profiler.print_stats

Let's take a look at the functions defined here.
Obviously the sleep function uses no CPU time, however the count function
should generate some CPU usage.

The output I get from this script is the following:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    2.045    2.045    2.045    2.045 <stdin>:1(count)
        1    0.000    0.000    2.001    2.001 <stdin>:1(sleep)
*        1    0.000    0.000    4.046    4.046 <stdin>:1(test)*
        1    0.000    0.000    4.046    4.046 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of
'_lsprof.Profiler' objects}
        1    2.001    2.001    2.001    2.001 {time.sleep}

And reading the *line* corresponding to the "test" function does not show
the results I expect (I expect approx 2.045).
Once again I have scoured the Internet and found no clues as to how to
leverage cProfile to measure only CPU time.

I wrote to Mike Mueller from Python Academy who was able to provide me with
some useful information on how to obtain what I was looking for.

*On a UNIX system,* writing
profiler = cProfile.Profile(time.clock)
achieves the desired effet:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    1.988    1.988    1.988    1.988 <stdin>:1(count)
        1    0.000    0.000    0.000    0.000 <stdin>:1(sleep)
*        1    0.000    0.000    1.989    1.989 <stdin>:1(test)*
        1    0.000    0.000    1.989    1.989 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of
'_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 {time.sleep}


*On Windows*, one must first define:
def win_clock():     return os.times()[0]
and write
profiler = cProfile.Profile(win_clock)

which also achieves the desired effect:
ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    1    1.404    1.404    1.404    1.404 <stdin>:1(count)
    1    0.000    0.000    0.000    0.000 <stdin>:1(sleep)
*    1    0.000    0.000    1.404    1.404 <stdin>:1(test)*
    1    0.000    0.000    1.404    1.404 <string>:1(<module>)
    1    0.000    0.000    0.000    0.000 {method 'disable' of
'_lsprof.Profiler' objects}
    1    0.000    0.000    0.000    0.000 {time.sleep}


I sincerely believe some of this information belongs in the official Python
documentation. Without Mike Mueller I think I would never have found it. I
hope my description has been thorough and that you will have sufficient
information to complete the existing documentation which has never
disappointed me.

Thank you very much for your consideration,
Hoping to hear from you soon,

Quentin de Metz
Box, Inc
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.python.org/pipermail/docs/attachments/20130419/728e16a1/attachment-0001.html>