openstack team mailing list archive

[Justin Santa Barbara <justin@xxxxxxxxxxxx>]

Both the profiling & the multi-process work are great - good stuff!

Jay: Won't going multi-process just make it harder to profile?  I think
it's actually a good thing to profile without the multi-process patch, find
& fix and the bottlenecks in single-request performance, and then use
multi-process for great concurrent-request performance?

Justin




On Thu, Apr 12, 2012 at 6:49 AM, Jay Pipes <jaypipes@xxxxxxxxx> wrote:

> Hi Yun!
>
> Thanks very much for sharing this information. Can I ask you to pull the
> code in this branch:
>
> https://review.openstack.org/#**change,5762<https://review.openstack.org/#change,5762>
>
> And retry your test? On my test machines, the work that Huang Zhiteng has
> done to convert Nova's servers to use multiple operating system processes,
> each with its own greenthread service pool, resulted in a massive
> throughput improvement, turning a quickly-bottlenecked system into a server
> that could scale nearly linearly with the number of worker processes.
>
> Be sure to set osapi_workers to the number of cores your machine has...
> and also note that your code profiling technique is unlikely to be
> effective since cProfile wouldn't track the forked child worker processes'
> stacks, AFAIK. Still interested to see if the time to execute the 300 API
> calls is dramatically reduced, though.
>
> Looking forward to any results you might have.
>
> Best,
> -jay
>
>
> On 04/11/2012 04:48 PM, Yun Mao wrote:
>
>> Hi Stackers, I spent some time looking at nova-api today.
>>
>> Setup: everything-on-one-node devstack, essex trunk. I setup 1 user
>> with 10 tiny VMs.
>> Client: 3 python threads each doing a loop of "nova list" equivalent
>> for 100 times. So 300 API calls with concurrency=3.
>> how to profile: python -m cProfile -s time
>> /opt/stack/nova/bin/nova-api --flagfile=/etc/nova/nova.conf
>> --logdir=/var/log/nova --nodebug
>> The partial output is attached in the end.
>>
>> Observations:
>> * It takes about 60 seconds to finish. CPU of nova-api is around 70% to
>> 90%
>>
>> * Database access: Each "nova list" API call will issue 4 db APIs: 3
>> instance_get_all_by_filters(), 1
>> instance_fault_get_by_**instance_uuids(), so 1200 db API calls total
>> (note: not necessarily 1200 SQL statements, could be more). The 900
>> instance_get_all_by_filters() calls took 30.2 seconds (i.e. 0.03s
>> each)! The 300 instance_fault_get_by_**instance_uuids() calls only took
>> 1.129 seconds (0.004 each).
>>
>> You might think: MySQL sucks. Not so fast. Remember this is a tiny
>> database with only 10 VMs. Profile also shows that the actual
>> _mysql.connection.query() method only took 1.883 seconds in total. So,
>> we pretty much spend 29 seconds out of 60 seconds doing either
>> sqlalchemy stuff or our own wrapper. You can also see from the sheer
>> volume of sqlalchemy library calls involved.
>>
>> * the cfg.py library inefficiency. During 300 API calls,
>> common.cfg.ConfigOpts._get() is called 135005 times! and we paid 2.470
>> sec for that.
>>
>> Hopefully this is useful for whoever wants to improve the performance
>> of nova-api.
>>
>> Thanks,
>> Yun
>>
>> =======
>>
>>          23355694 function calls (22575841 primitive calls) in 77.874
>> seconds
>>
>>    Ordered by: internal time
>>
>>    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>>       812   25.725    0.032   25.725    0.032 {method 'poll' of
>> 'select.epoll' objects}
>>      2408    1.883    0.001    1.883    0.001 {method 'query' of
>> '_mysql.connection' objects}
>>     70380    1.667    0.000    7.187    0.000
>> expression.py:2263(**corresponding_column)
>>    135005    1.254    0.000    2.470    0.000 cfg.py:1058(_get)
>>     41027    1.043    0.000    1.907    0.000 schema.py:542(__init__)
>>     38802    1.008    0.000    1.219    0.000 __init__.py:451(format)
>>    162206    0.821    0.000    0.821    0.000 util.py:883(values)
>>   1530666    0.773    0.000    0.774    0.000 {isinstance}
>> 135046/134960    0.716    0.000    1.919    0.000 cfg.py:1107(_substitute)
>>      1205    0.713    0.001    1.369    0.001 base.py:2106(__init__)
>>    183600    0.690    0.000    0.796    0.000 interfaces.py:954(_reduce_*
>> *path)
>>     81002    0.687    0.000    2.492    0.000 compiler.py:312(visit_label)
>>     38802    0.650    0.000    6.087    0.000 log.py:227(format)
>>    319270    0.622    0.000    0.748    0.000 attributes.py:164(__get__)
>> 890242/884229    0.608    0.000    1.885    0.000 {getattr}
>>     40500    0.605    0.000    3.101    0.000 schema.py:955(_make_proxy)
>> 120783/120738    0.603    0.000    0.605    0.000 {method 'sub' of
>> '_sre.SRE_Pattern' objects}
>>     81000    0.601    0.000    2.156    0.000
>> interfaces.py:677(create_row_**processor)
>>     63000    0.590    0.000    0.707    0.000
>> times.py:44(DateTime_or_None)
>>     98102    0.588    0.000    0.886    0.000
>> compiler.py:337(visit_column)
>>    658098    0.580    0.000    0.581    0.000 {method 'intersection'
>> of 'set' objects}
>>    109802    0.562    0.000    0.562    0.000 expression.py:3625(_from_**
>> objects)
>> 231610/1202    0.551    0.000    5.813    0.005
>> visitors.py:58(_compiler_**dispatch)
>>    144002    0.510    0.000    0.693    0.000
>> compiler.py:622(_truncated_**identifier)
>> 135005/134960    0.485    0.000    4.872    0.000 cfg.py:860(__getattr__)
>>      2408    0.463    0.000    1.942    0.001 {built-in method fetch_row}
>>     71100    0.460    0.000    0.580    0.000
>> strategies.py:121(create_row_**processor)
>>    299031    0.437    0.000    0.437    0.000 {_codecs.utf_8_decode}
>>      6000    0.437    0.000    1.799    0.000 models.py:93(iteritems)
>> 36000/9000    0.409    0.000    4.791    0.001
>> mapper.py:2146(populate_state)
>>     81002    0.393    0.000    1.104    0.000
>> compiler.py:672(label_select_**column)
>> 45000/9000    0.390    0.000    5.148    0.001 mapper.py:2186(_instance)
>>      1202    0.366    0.000    5.797    0.005
>> compiler.py:701(visit_select)
>> 231610/1202    0.347    0.000    5.817    0.005 base.py:714(process)
>>    172800    0.341    0.000    1.148    0.000
>> interfaces.py:651(_get_**context_strategy)
>>     25868    0.339    0.000    0.339    0.000 {method 'write' of 'file'
>> objects}
>> 91800/52200    0.327    0.000    6.728    0.000 interfaces.py:673(setup)
>>
>>     22801    0.324    0.000    0.324    0.000 {method 'strftime' of
>> 'datetime.date' objects}
>>     78478    0.316    0.000    0.914    0.000
>> expression.py:2143(contains_**column)
>>     25868    0.314    0.000    0.314    0.000 {method 'flush' of 'file'
>> objects}
>>    299033    0.309    0.000    0.930    0.000 {method 'decode' of 'str'
>> objects}
>> 118969/118924    0.305    0.000    0.930    0.000
>> string.py:174(safe_substitute)
>> 143683/143658    0.304    0.000    4.518    0.000 util.py:1514(__get__)
>>    135008    0.303    0.000    0.303    0.000 {sorted}
>>     48495    0.295    0.000    0.307    0.000 util.py:928(__init__)
>>    288598    0.292    0.000    0.298    0.000 {hasattr}
>>    136567    0.292    0.000    0.435    0.000 {map}
>>     34260    0.287    0.000    0.538    0.000 expression.py:3584(_label)
>>    524700    0.285    0.000    0.285    0.000
>> strategies.py:129(new_execute)
>>    300000    0.282    0.000    1.160    0.000 models.py:84(next)
>> 27000/6000    0.280    0.000    0.280    0.000 model.py:31(__repr__)
>>     12934    0.273    0.000    0.536    0.000 __init__.py:242(__init__)
>>     31649    0.258    0.000    0.258    0.000 {posix.stat}
>>      3302    0.256    0.000    0.256    0.000 decoder.py:372(raw_decode)
>>      2408    0.241    0.000    0.241    0.000 {method 'store_result'
>> of '_mysql.connection' objects}
>>    287402    0.238    0.000    0.239    0.000 compiler.py:1541(quote)
>>     38802    0.212    0.000    9.059    0.000 __init__.py:731(handle)
>>     25868    0.210    0.000    4.979    0.000 __init__.py:830(emit)
>>    645763    0.206    0.000    0.206    0.000 {method 'get' of 'dict'
>> objects}
>>     41432    0.196    0.000    0.358    0.000 threading.py:141(release)
>>     41432    0.194    0.000    0.339    0.000 threading.py:121(acquire)
>>     81000    0.190    0.000    5.349    0.000
>> strategies.py:100(setup_query)
>>      3600    0.187    0.000    6.226    0.002
>> strategies.py:956(setup_query)
>>     12934    0.187    0.000    2.630    0.000 handlers.py:784(emit)
>>    299031    0.183    0.000    0.620    0.000 utf_8.py:15(decode)
>>    162206    0.183    0.000    1.045    0.000 util.py:886(itervalues)
>>      3600    0.176    0.000    0.413    0.000
>> strategies.py:1161(create_row_**processor)
>>     13835    0.174    0.000    0.174    0.000 {method 'send' of
>> '_socket.socket' objects}
>>     12934    0.171    0.000    0.707    0.000 __init__.py:1218(makeRecord)
>>    237032    0.169    0.000    0.169    0.000 {method 'split' of 'str'
>> objects}
>>     21493    0.167    0.000    0.232    0.000 posixpath.py:60(join)
>>      3600    0.165    0.000    2.391    0.001 mapper.py:2329(_populators)
>>     76353    0.164    0.000    0.280    0.000
>> expression.py:2138(__contains_**_)
>>      1202    0.161    0.000    0.161    0.000 {method 'rollback' of
>> '_mysql.connection' objects}
>>     24000    0.159    0.000    0.166    0.000 model.py:24(ensure_string_*
>> *keys)
>>    852818    0.158    0.000    0.158    0.000 {method 'pop' of 'dict'
>> objects}
>>    111585    0.156    0.000    0.208    0.000 thread.py:17(get_ident)
>>      4542    0.154    0.000    3.108    0.001
>> visitors.py:241(replacement_**traverse)
>>     12934    0.151    0.000    9.213    0.001
>> __init__.py:1284(callHandlers)
>>    158594    0.145    0.000    1.138    0.000 util.py:787(__iter__)
>> 230769/224673    0.144    0.000    0.266    0.000 {iter}
>>    253618    0.144    0.000    0.144    0.000 {method 'lower' of
>> 'unicode' objects}
>>      3000    0.144    0.000    5.696    0.002
>> common.py:293(get_networks_**for_instance_from_nw_info)
>>    733671    0.141    0.000    0.141    0.000 {method 'append' of
>> 'list' objects}
>>     41029    0.141    0.000    0.189    0.000 expression.py:3570(__init__)
>>     19840    0.141    0.000    0.214    0.000 corolocal.py:24(_patch)
>>   4506/21    0.140    0.000   57.981    2.761 socket.py:406(readline)
>>    133954    0.139    0.000    0.272    0.000
>> cfg.py:440(_get_from_config_**parser)
>>    216531    0.139    0.000    0.772    0.000 connections.py:206(string_*
>> *decoder)
>>     45000    0.138    0.000    0.151    0.000 mapper.py:2139(identity_key)
>>     13526    0.134    0.000    0.937    0.000 log.py:146(process)
>>    135003    0.134    0.000    0.134    0.000 cfg.py:770(get)
>> 50425/49225    0.129    0.000    0.986    0.000 {method 'join' of 'str'
>> objects}
>>     69300    0.129    0.000    7.303    0.000 util.py:621(_corresponding_
>> **column)
>>       600    0.129    0.000   23.205    0.039 api.py:1045(get_all)
>>
>> ______________________________**_________________
>> Mailing list: https://launchpad.net/~**openstack<https://launchpad.net/~openstack>
>> Post to     : openstack@xxxxxxxxxxxxxxxxxxx
>> Unsubscribe : https://launchpad.net/~**openstack<https://launchpad.net/~openstack>
>> More help   : https://help.launchpad.net/**ListHelp<https://help.launchpad.net/ListHelp>
>>
>
> ______________________________**_________________
> Mailing list: https://launchpad.net/~**openstack<https://launchpad.net/~openstack>
> Post to     : openstack@xxxxxxxxxxxxxxxxxxx
> Unsubscribe : https://launchpad.net/~**openstack<https://launchpad.net/~openstack>
> More help   : https://help.launchpad.net/**ListHelp<https://help.launchpad.net/ListHelp>
>