Yield profiling

yield-profiling.md

Demonstration of phenomenon, when caller cumulative time can be less than the callee, given it's the only caller. This may happen if callee is generator and caller returns callee object as is. Then profiler sees a lot of time spent in callee and almost no time at caller.

profile.out

100000
         600005 function calls (500005 primitive calls) in 0.961 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 :0(setprofile)
 100001/1    0.310    0.000    0.961    0.961 :0(sum)
   100000    0.099    0.000    0.099    0.000 main.py:12(medium)
   100000    0.250    0.000    0.712    0.000 main.py:16(oughter)
   100001    0.159    0.000    0.870    0.000 main.py:20(<genexpr>)
        1    0.000    0.000    0.961    0.961 main.py:4(<module>)
   200000    0.144    0.000    0.144    0.000 main.py:8(inner)
        1    0.000    0.000    0.961    0.961 profile:0(<code object <module> at 0x7fe4ec16ecb0, file "main.py", line 4>)
        0    0.000             0.000          profile:0(profiler)

yield-profiling.py

#!/usr/bin/python


def unused():
    pass


def inner():
    yield 1


def medium():
    return inner()


def oughter():
    return sum(medium())


print sum(oughter() for _ in xrange(100000))