Differences between cProfile and profile —why no profile.Profile.enable() method?

Question

In both Python 2.7 and Python 3.6, I find that this works:

from cProfile import Profile; p = Profile(); p.enable()

...whereas this raises an exception:

from profile import Profile; p = Profile(); p.enable()

# -->  AttributeError: 'Profile' object has no attribute 'enable'

This surprises me, because I thought (and the official docs for both Python 3 and Python 2 state) that the two modules were supposed to provide identical programmer's interfaces:

Both the profile and cProfile modules provide the following functions:

...

class profile.Profile(timer=None, timeunit=0.0, subcalls=True, builtins=True)

...

enable()

Start collecting profile data.

What am I missing? And what is the correct way to use a profile.Profile() instance?

Answer 1

As of Python 3.8 and newer documentation, they have fixed this to specify that enable() and disable() are only available with cProfile. With profile.Profile, you need to use the run() invocation as opposed to enable() and disable(). Below are samples for each:

cProfile.Profile:

# cProfile.Profile -- control with enable() and disable()
from datetime import datetime
import cProfile, pstats, io
sortby = 'cumulative'
pr1 = cProfile.Profile(lambda: int(datetime.now().timestamp()*1000000), 0.000001)
pr1.enable()
list(x for x in range(int(10*10*10*10/10*10+10)))
pr1.disable()
s1 = io.StringIO()
ps1 = pstats.Stats(pr1, stream=s1).sort_stats(sortby)
ps1.print_stats()
print(s1.getvalue())

profile.Profile:

# profile.Profile -- control with run()
from datetime import datetime
import profile, pstats, io
sortby = 'cumulative'
pr2 = profile.Profile(datetime.now().timestamp, 0.000001)
pr2.run('list(x for x in range(int(10*10*10*10/10*10+10)))')
s2 = io.StringIO()
ps2 = pstats.Stats(pr2, stream=s2).sort_stats(sortby)
ps2.print_stats()
print(s2.getvalue())

Here are some behavioral differences I observed between the two forms:

• cProfile will push profiled functions' output to stdout, whereas profile will not.

• The final report's filename:lineno(function) column will have slightly different output. cProfile generally will display built-in functions more readably.

  • In the example I provided here, however, the passed in function is actually identifiable in profile's output and not in cProfile's -- but if using a named function, it is identifiable in both profilers' output (although the passed in arguments to the function are only visible from profile's output).

• Running identical functions thru both cProfile and profile provides slightly different results. It seems cProfile generates about two less function calls generally, and will provide more efficient times for the same function.

• Using the profilers' optional custom timer and timeunit parameters can offer the benefit of gaining microsecond precision vs the default millisecond precision. However, it seems that attempting to use these comes with some caveats:

  • cProfile's timeunit function requires an integer, whereas profile expects a floating point number. This means you can't use datetime.now().timestamp() directly with cProfile, but must rather wrap it in a lambda to convert it to a full integer first.
  • Additionally, for some reason profile seems to not work correctly with datetime.now().timestamp() even though that's in the format it's expecting. It will print out negative time values -- I show this below. Switching to the lambda form to convert it to integer doesn't help, as profile expects the floating point number.

• Below is the output of profile.Profile with the datetime.now().timestamp() timer for microsecond provision.

   print(s2.getvalue())
         10015 function calls in -0.020 seconds`
  
   Ordered by: cumulative time
  
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        0    0.000             0.000          profile:0(profiler)
        1    0.000    0.000    0.000    0.000 :0(setprofile)
    10011   -0.010   -0.000   -0.010   -0.000 <string>:1(<genexpr>)
        1   -0.010   -0.010   -0.020   -0.020 <string>:1(<module>)
        1   -0.000   -0.000   -0.020   -0.020 :0(exec)
        1   -0.000   -0.000   -0.020   -0.020 profile:0(list(x for x in range(int(10*10*10*10/10*10+10))))
  

• However, this problem can be fixed by providing a custom timer function (which can even wrap around datetime.now() to provide the exact same output format as datetime.now().timestamp()), for reasons I can't explain.

e.g. If we define:

def timenow():
   now = datetime.now()
   return (((now.year-1970) * 31557600) + (now.month * 2629800) + 
           (now.day * 86400) + (now.hour * 3600) + (now.minute * 60) +
           now.second + (now.microsecond * 0.000001))

We can now use pr2 = profile.Profile(timenow, 0.000001), and this will output the following (sane) report:

>>> print(s2.getvalue())
         10015 function calls in 0.041 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.006    0.006    0.041    0.041 profile:0(list(x for x in range(int(10*10*10*10/10*10+10))))
        1    0.000    0.000    0.035    0.035 :0(exec)
        1    0.017    0.017    0.035    0.035 <string>:1(<module>)
    10011    0.018    0.000    0.018    0.000 <string>:1(<genexpr>)
        1    0.001    0.001    0.001    0.001 :0(setprofile)
        0    0.000             0.000          profile:0(profiler)

Comparing with the output of cProfile (using the custom lambda timer as defined above), we have:

>>> print(s1.getvalue())
         10013 function calls in 0.031 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    10011    0.031    0.000    0.031    0.000 <stdin>:1(<genexpr>)
        1    0.000    0.000    0.000    0.000 <stdin>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

As to why our custom timer function gives sensible results and datetime.now().timestamp() does not with profile, first it must be noted that timenow doesn't provide timings to datetime.now().timestamp(). Although it provides close to epoch time, it is off by small amount (nothing that should affect normal profile runs as the deltas will be identical on the same system). The manual conversion used in timenow also surely isn't as efficient as in datetime.now().timestamp(). I can only speculate that the latter is too efficient and that somehow the profile source code doesn't properly measure as a result.

TL;DR

Use cProfile unless you have a specific reason not to. The official Python docs also state that the recommended module is cProfile. Although no specific justification is provided, the doc seems to imply that cProfile might be better behaved and suitable for most users' purposes (even though it is a slightly more verbose syntax).