Python cProfile - most of time spent in method 'enable' of '_lsprof.Profiler'

Question

I am trying to perform some high-level profiling of a rather complex Python program. However, when using cProfile, almost all time is measured in:

{method 'enable' of '_lsProf.Profiler' objects}

It happens if I profile the whole program python -m cProfile ... as well as when I perform profiling within the Python code (with profile.enable()/.disable()/.create_stats...)

Any pointers to what I could be doing wrong?

Archbishopric

Hopefully this is useful to some people. I had this issue, which was a result of attempting to profile a generator. Once switching to return instead of yield, the output file became useful – Seneschal

Answer 1

It's because somewhere in your code you have something like

import cProfile
pr = cProfile.Profile()
pr.enable()

That's for manually saving the results or printing them, if you are calling the profiler like you said with python -m cProfile -o program.prof my_program.py you don't need to use cProfile inside the program.

Accede

This doesn't address the issue (at least not clearly to me). I have seen the same thing. Instead of getting a profile of what is being executed I get a single line as mentioned in the original post here. In other words the profiler seems to swallow the stuff it should be profiling. – Ulmer

Answer 2

This looks like a bug or limitation. Nested profilers do not work. here is a repro:

import cProfile
import pstats
import time
import cStringIO as StringIO

def do():
    for i in range(100):
       time.sleep(0.01)

def do_more():
    for i in range(100):
        time.sleep(0.01)

def do_all():
    all_profiler = cProfile.Profile()
    all_profiler.enable()

    profiler = cProfile.Profile()
    profiler.enable()

    do()

    profiler.disable()
    strio = StringIO.StringIO()
    stats = pstats.Stats(profiler, stream=strio)
    stats.sort_stats("cumulative")
    stats.print_stats(10)
    print "do profile:\n{}".format(strio.getvalue())

    do_more()

    all_profiler.disable()
    strio = StringIO.StringIO()
    stats = pstats.Stats(all_profiler, stream=strio)
    stats.sort_stats("cumulative")
    stats.print_stats(10)
    print "all profile:\n{}".format(strio.getvalue())


do_all()

Added to tmp.py and run in the shell, output is:

do profile:
         103 function calls in 1.009 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.009    1.009 tmp.py:6(do)
      100    1.008    0.010    1.008    0.010 {time.sleep}
        1    0.000    0.000    0.000    0.000 {range}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}



all profile:
         1 function calls in 2.018 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    2.018    2.018    2.018    2.018 {method 'enable' of '_lsprof.Profiler' objects}

Note the "all_profiler" only shows the other profiler.

EDIT: it is possible this is only an issue with the summary printing. I didn't try dumping the stats to use with a profile viewer like converting for use with kCachegrind, for example.

Ulmer