openstack team mailing list archive

[Yuriy Taraday <yorik.sar@xxxxxxxxx>]

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 <yunmao@xxxxxxxxx> 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@xxxxxxxxxxxxxxxxxxx
> Unsubscribe : https://launchpad.net/~openstack
> More help   : https://help.launchpad.net/ListHelp