Issue #162 resolved

eventlet.green.profile can not accumulate profiling results

Anonymous created an issue

I have an issue of using eventlet profile. It can't generate accumulative profiling results. Here's the example code to show the incorrect results comparing to the python standard profile. You can uncomment the import code to use standard profile. You will see the 'ncalls' of function calls is not cumulated in eventlet profile as below.

# -----------  test.py  ---------
import pstats
import sys
import eventlet
from eventlet.green import urllib2
import time
from eventlet.green import profile
# uncomment this line to use standard profile
#import cProfile as profile

def some_long_calculation(id):  # or anything else making the server cpu bound
    x = 1.0
    for i in xrange(1, 50000000): # may need to be adjusted for your system
        x =  x +  1.0 / i
        #print "x = %d, i = %d" % (x, i)
    print "x = %f" % (x)

def some_work(id):
    print('start some_work')
    eventlet.sleep(1)
    print('end some_work')

def main():
    pile = eventlet.GreenPool(1000)
    pile.spawn(some_work, 1)
    pile.spawn(some_long_calculation, 2)
    pile.waitall()

if __name__ == '__main__':
    prof =  profile.Profile()
    for i in range(5):
        prof.runcall(main)
        file_name = './%d.profile' % i
        prof.dump_stats(file_name)
        stats = pstats.Stats(file_name)
        stats.print_stats('some')
# --------------end ---------------------
--------- eventlet profile output ---------
start some_work
x = 19.304749
end some_work
Tue Dec 10 16:25:05 2013    ./0.profile

         196 function calls in 4.812 seconds

   Random listing order was used
   List reduced from 83 to 2 due to restriction <'some'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:16(some_work)
        1    4.812    4.812    4.812    4.812 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:9(some_long_calculation)


start some_work
x = 19.304749
end some_work
Tue Dec 10 16:25:10 2013    ./1.profile

         149 function calls in 4.884 seconds

   Random listing order was used
   List reduced from 54 to 2 due to restriction <'some'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.004    0.004 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:16(some_work)
        1    4.872    4.872    4.872    4.872 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:9(some_long_calculation)


start some_work
x = 19.304749
end some_work
Tue Dec 10 16:25:15 2013    ./2.profile

         149 function calls in 4.708 seconds

   Random listing order was used
   List reduced from 54 to 2 due to restriction <'some'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:16(some_work)
        1    4.704    4.704    4.704    4.704 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:9(some_long_calculation)


start some_work
x = 19.304749
end some_work
Tue Dec 10 16:25:19 2013    ./3.profile

         149 function calls in 4.600 seconds

   Random listing order was used
   List reduced from 54 to 2 due to restriction <'some'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:16(some_work)
        1    4.596    4.596    4.596    4.596 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:9(some_long_calculation)


start some_work
x = 19.304749
end some_work
Tue Dec 10 16:25:24 2013    ./4.profile

         149 function calls in 4.692 seconds

   Random listing order was used
   List reduced from 54 to 2 due to restriction <'some'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:16(some_work)
        1    4.688    4.688    4.688    4.688 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:9(some_long_calculation)

---------------end------------------------
--------- standard profile output ---------
start some_work
x = 19.304749
end some_work
Tue Dec 10 16:37:23 2013    ./0.profile

         192 function calls (181 primitive calls) in 4.514 seconds

   Random listing order was used
   List reduced from 79 to 2 due to restriction <'some'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    4.512    4.512    4.512    4.512 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:9(some_long_calculation)
        1    0.001    0.001    4.513    4.513 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:16(some_work)


start some_work
x = 19.304749
end some_work
Tue Dec 10 16:37:28 2013    ./1.profile

         337 function calls (318 primitive calls) in 9.314 seconds

   Random listing order was used
   List reduced from 80 to 2 due to restriction <'some'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        2    9.311    4.655    9.311    4.655 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:9(some_long_calculation)
        2    0.001    0.000    9.312    4.656 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:16(some_work)


start some_work
x = 19.304749
end some_work
Tue Dec 10 16:37:32 2013    ./2.profile

         482 function calls (455 primitive calls) in 13.920 seconds

   Random listing order was used
   List reduced from 80 to 2 due to restriction <'some'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        3   13.917    4.639   13.917    4.639 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:9(some_long_calculation)
        3    0.001    0.000   13.918    4.639 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:16(some_work)


start some_work
x = 19.304749
end some_work
Tue Dec 10 16:37:37 2013    ./3.profile

         627 function calls (592 primitive calls) in 18.446 seconds

   Random listing order was used
   List reduced from 80 to 2 due to restriction <'some'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        4   18.442    4.611   18.442    4.611 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:9(some_long_calculation)
        4    0.001    0.000   18.444    4.611 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:16(some_work)


start some_work
x = 19.304749
end some_work
Tue Dec 10 16:37:42 2013    ./4.profile

         772 function calls (729 primitive calls) in 23.589 seconds

   Random listing order was used
   List reduced from 80 to 2 due to restriction <'some'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        5   23.585    4.717   23.585    4.717 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:9(some_long_calculation)
        5    0.001    0.000   23.587    4.717 /opt/stack/eventlet_profiler/test_eventlet_builtin_profile3.py:16(some_work)

---------------end------------------------

Comments (10)

  1. 华 张

    I have tested it by running both of the code above and openstack patch, it works! it should be safe to merge this patch from my end. Thanks for your help on this. :-)

  2. 华 张

    paste the test result here FYI.

    start some_work
    x = 19.304749
    end some_work
    Wed Mar 12 12:55:39 2014    ./0.profile
    
             196 function calls in 4.576 seconds
    
       Random listing order was used
       List reduced from 83 to 2 due to restriction <'some'>
    
       ncalls  tottime  percall  cumtime  percall filename:lineno(function)
            1    0.000    0.000    0.000    0.000 /opt/stack/eventlet_profiler/test_eventlet_profile_cumulation.py:17(some_work)
            1    4.576    4.576    4.576    4.576 /opt/stack/eventlet_profiler/test_eventlet_profile_cumulation.py:10(some_long_calculation)
    
    
    start some_work
    x = 19.304749
    end some_work
    Wed Mar 12 12:55:43 2014    ./1.profile
    
             345 function calls in 9.161 seconds
    
       Random listing order was used
       List reduced from 83 to 2 due to restriction <'some'>
    
       ncalls  tottime  percall  cumtime  percall filename:lineno(function)
            2    0.000    0.000    0.000    0.000 /opt/stack/eventlet_profiler/test_eventlet_profile_cumulation.py:17(some_work)
            2    9.157    4.578    9.157    4.578 /opt/stack/eventlet_profiler/test_eventlet_profile_cumulation.py:10(some_long_calculation)
    
    
    start some_work
    x = 19.304749
    end some_work
    Wed Mar 12 12:55:48 2014    ./2.profile
    
             494 function calls in 13.909 seconds
    
       Random listing order was used
       List reduced from 83 to 2 due to restriction <'some'>
    
       ncalls  tottime  percall  cumtime  percall filename:lineno(function)
            3    0.000    0.000    0.000    0.000 /opt/stack/eventlet_profiler/test_eventlet_profile_cumulation.py:17(some_work)
            3   13.901    4.634   13.901    4.634 /opt/stack/eventlet_profiler/test_eventlet_profile_cumulation.py:10(some_long_calculation)
    
    
    start some_work
    x = 19.304749
    end some_work
    Wed Mar 12 12:55:52 2014    ./3.profile
    
             643 function calls in 18.489 seconds
    
       Random listing order was used
       List reduced from 83 to 2 due to restriction <'some'>
    
       ncalls  tottime  percall  cumtime  percall filename:lineno(function)
            4    0.000    0.000    0.000    0.000 /opt/stack/eventlet_profiler/test_eventlet_profile_cumulation.py:17(some_work)
            4   18.477    4.619   18.477    4.619 /opt/stack/eventlet_profiler/test_eventlet_profile_cumulation.py:10(some_long_calculation)
    
    
    start some_work
    x = 19.304749
    end some_work
    Wed Mar 12 12:55:56 2014    ./4.profile
    
             792 function calls in 23.433 seconds
    
       Random listing order was used
       List reduced from 83 to 2 due to restriction <'some'>
    
       ncalls  tottime  percall  cumtime  percall filename:lineno(function)
            5    0.000    0.000    0.004    0.001 /opt/stack/eventlet_profiler/test_eventlet_profile_cumulation.py:17(some_work)
            5   23.413    4.683   23.413    4.683 /opt/stack/eventlet_profiler/test_eventlet_profile_cumulation.py:10(some_long_calculation)
    
  3. Log in to comment