Hi Jay, I will take a look later when I find a box with multiple cores to take advantage it..
Agreed - cprofiling is not so useful this case. This would be a purely performance benchmark. If implemented correctly, we should see a notable gain. However, It will probably not that linear because we might hit keystone's performance issue later. It looks like the second CPU hogger behind nova-api. Is there a multiprocess keystone too? Yun On Thu, Apr 12, 2012 at 9:49 AM, Jay Pipes <jaypi...@gmail.com> 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 > > 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 >> Post to : openstack@lists.launchpad.net >> Unsubscribe : https://launchpad.net/~openstack >> More help : https://help.launchpad.net/ListHelp > > > _______________________________________________ > Mailing list: https://launchpad.net/~openstack > Post to : openstack@lists.launchpad.net > Unsubscribe : https://launchpad.net/~openstack > More help : https://help.launchpad.net/ListHelp _______________________________________________ Mailing list: https://launchpad.net/~openstack Post to : openstack@lists.launchpad.net Unsubscribe : https://launchpad.net/~openstack More help : https://help.launchpad.net/ListHelp
