Great work!
About a year ago I found out than config was in the very top of
profiling table. It is there again.
That time there was a small misprint that led to constant config
reloading. This time i tried to add caching since our config became so
dynamic.
My efforts can be found here: https://review.openstack.org/6534 . My
benchmark showed time loss up to 40% in 'nova list' case. All three
lines from cfg.py have disappeared from top-10 of pstats. As well as
from top-40 :)
Looking forward to reviews.
Kind regards, Yuriy.
On Thu, Apr 12, 2012 at 00:48, Yun Mao <yun...@gmail.com> 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
