[Openstack] profiling nova-api

Jay Pipes jaypipes at gmail.com
Thu Apr 12 13:49:18 UTC 2012


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 at lists.launchpad.net
> Unsubscribe : https://launchpad.net/~openstack
> More help   : https://help.launchpad.net/ListHelp




More information about the Openstack mailing list