<HTML>
<HEAD>
<TITLE>Re: [Openstack] profiling nova-api</TITLE>
</HEAD>
<BODY>
<FONT FACE="Calibri, Verdana, Helvetica, Arial"><SPAN STYLE='font-size:11pt'>Awesome, great stuff to know!<BR>
<BR>
On 4/11/12 1:48 PM, "Yun Mao" <<a href="yunmao@gmail.com">yunmao@gmail.com</a>> wrote:<BR>
<BR>
</SPAN></FONT><BLOCKQUOTE><FONT FACE="Calibri, Verdana, Helvetica, Arial"><SPAN STYLE='font-size:11pt'>Hi Stackers, I spent some time looking at nova-api today.<BR>
<BR>
Setup: everything-on-one-node devstack, essex trunk. I setup 1 user<BR>
with 10 tiny VMs.<BR>
Client: 3 python threads each doing a loop of "nova list" equivalent<BR>
for 100 times. So 300 API calls with concurrency=3.<BR>
how to profile: python -m cProfile -s time<BR>
/opt/stack/nova/bin/nova-api --flagfile=/etc/nova/nova.conf<BR>
--logdir=/var/log/nova --nodebug<BR>
The partial output is attached in the end.<BR>
<BR>
Observations:<BR>
* It takes about 60 seconds to finish. CPU of nova-api is around 70% to 90%<BR>
<BR>
* Database access: Each "nova list" API call will issue 4 db APIs: 3<BR>
instance_get_all_by_filters(), 1<BR>
instance_fault_get_by_instance_uuids(), so 1200 db API calls total<BR>
(note: not necessarily 1200 SQL statements, could be more). The 900<BR>
instance_get_all_by_filters() calls took 30.2 seconds (i.e. 0.03s<BR>
each)! The 300 instance_fault_get_by_instance_uuids() calls only took<BR>
1.129 seconds (0.004 each).<BR>
<BR>
You might think: MySQL sucks. Not so fast. Remember this is a tiny<BR>
database with only 10 VMs. Profile also shows that the actual<BR>
_mysql.connection.query() method only took 1.883 seconds in total. So,<BR>
we pretty much spend 29 seconds out of 60 seconds doing either<BR>
sqlalchemy stuff or our own wrapper. You can also see from the sheer<BR>
volume of sqlalchemy library calls involved.<BR>
<BR>
* the cfg.py library inefficiency. During 300 API calls,<BR>
common.cfg.ConfigOpts._get() is called 135005 times! and we paid 2.470<BR>
sec for that.<BR>
<BR>
Hopefully this is useful for whoever wants to improve the performance<BR>
of nova-api.<BR>
<BR>
Thanks,<BR>
Yun<BR>
<BR>
=======<BR>
<BR>
23355694 function calls (22575841 primitive calls) in 77.874 seconds<BR>
<BR>
Ordered by: internal time<BR>
<BR>
ncalls tottime percall cumtime percall filename:lineno(function)<BR>
812 25.725 0.032 25.725 0.032 {method 'poll' of<BR>
'select.epoll' objects}<BR>
2408 1.883 0.001 1.883 0.001 {method 'query' of<BR>
'_mysql.connection' objects}<BR>
70380 1.667 0.000 7.187 0.000<BR>
expression.py:2263(corresponding_column)<BR>
135005 1.254 0.000 2.470 0.000 cfg.py:1058(_get)<BR>
41027 1.043 0.000 1.907 0.000 schema.py:542(__init__)<BR>
38802 1.008 0.000 1.219 0.000 __init__.py:451(format)<BR>
162206 0.821 0.000 0.821 0.000 util.py:883(values)<BR>
1530666 0.773 0.000 0.774 0.000 {isinstance}<BR>
135046/134960 0.716 0.000 1.919 0.000 cfg.py:1107(_substitute)<BR>
1205 0.713 0.001 1.369 0.001 base.py:2106(__init__)<BR>
183600 0.690 0.000 0.796 0.000 interfaces.py:954(_reduce_path)<BR>
81002 0.687 0.000 2.492 0.000 compiler.py:312(visit_label)<BR>
38802 0.650 0.000 6.087 0.000 log.py:227(format)<BR>
319270 0.622 0.000 0.748 0.000 attributes.py:164(__get__)<BR>
890242/884229 0.608 0.000 1.885 0.000 {getattr}<BR>
40500 0.605 0.000 3.101 0.000 schema.py:955(_make_proxy)<BR>
120783/120738 0.603 0.000 0.605 0.000 {method 'sub' of<BR>
'_sre.SRE_Pattern' objects}<BR>
81000 0.601 0.000 2.156 0.000<BR>
interfaces.py:677(create_row_processor)<BR>
63000 0.590 0.000 0.707 0.000 times.py:44(DateTime_or_None)<BR>
98102 0.588 0.000 0.886 0.000 compiler.py:337(visit_column)<BR>
658098 0.580 0.000 0.581 0.000 {method 'intersection'<BR>
of 'set' objects}<BR>
109802 0.562 0.000 0.562 0.000 expression.py:3625(_from_objects)<BR>
231610/1202 0.551 0.000 5.813 0.005<BR>
visitors.py:58(_compiler_dispatch)<BR>
144002 0.510 0.000 0.693 0.000<BR>
compiler.py:622(_truncated_identifier)<BR>
135005/134960 0.485 0.000 4.872 0.000 cfg.py:860(__getattr__)<BR>
2408 0.463 0.000 1.942 0.001 {built-in method fetch_row}<BR>
71100 0.460 0.000 0.580 0.000<BR>
strategies.py:121(create_row_processor)<BR>
299031 0.437 0.000 0.437 0.000 {_codecs.utf_8_decode}<BR>
6000 0.437 0.000 1.799 0.000 models.py:93(iteritems)<BR>
36000/9000 0.409 0.000 4.791 0.001 mapper.py:2146(populate_state)<BR>
81002 0.393 0.000 1.104 0.000<BR>
compiler.py:672(label_select_column)<BR>
45000/9000 0.390 0.000 5.148 0.001 mapper.py:2186(_instance)<BR>
1202 0.366 0.000 5.797 0.005 compiler.py:701(visit_select)<BR>
231610/1202 0.347 0.000 5.817 0.005 base.py:714(process)<BR>
172800 0.341 0.000 1.148 0.000<BR>
interfaces.py:651(_get_context_strategy)<BR>
25868 0.339 0.000 0.339 0.000 {method 'write' of 'file' objects}<BR>
91800/52200 0.327 0.000 6.728 0.000 interfaces.py:673(setup)<BR>
<BR>
22801 0.324 0.000 0.324 0.000 {method 'strftime' of<BR>
'datetime.date' objects}<BR>
78478 0.316 0.000 0.914 0.000<BR>
expression.py:2143(contains_column)<BR>
25868 0.314 0.000 0.314 0.000 {method 'flush' of 'file' objects}<BR>
299033 0.309 0.000 0.930 0.000 {method 'decode' of 'str' objects}<BR>
118969/118924 0.305 0.000 0.930 0.000 string.py:174(safe_substitute)<BR>
143683/143658 0.304 0.000 4.518 0.000 util.py:1514(__get__)<BR>
135008 0.303 0.000 0.303 0.000 {sorted}<BR>
48495 0.295 0.000 0.307 0.000 util.py:928(__init__)<BR>
288598 0.292 0.000 0.298 0.000 {hasattr}<BR>
136567 0.292 0.000 0.435 0.000 {map}<BR>
34260 0.287 0.000 0.538 0.000 expression.py:3584(_label)<BR>
524700 0.285 0.000 0.285 0.000 strategies.py:129(new_execute)<BR>
300000 0.282 0.000 1.160 0.000 models.py:84(next)<BR>
27000/6000 0.280 0.000 0.280 0.000 model.py:31(__repr__)<BR>
12934 0.273 0.000 0.536 0.000 __init__.py:242(__init__)<BR>
31649 0.258 0.000 0.258 0.000 {posix.stat}<BR>
3302 0.256 0.000 0.256 0.000 decoder.py:372(raw_decode)<BR>
2408 0.241 0.000 0.241 0.000 {method 'store_result'<BR>
of '_mysql.connection' objects}<BR>
287402 0.238 0.000 0.239 0.000 compiler.py:1541(quote)<BR>
38802 0.212 0.000 9.059 0.000 __init__.py:731(handle)<BR>
25868 0.210 0.000 4.979 0.000 __init__.py:830(emit)<BR>
645763 0.206 0.000 0.206 0.000 {method 'get' of 'dict' objects}<BR>
41432 0.196 0.000 0.358 0.000 threading.py:141(release)<BR>
41432 0.194 0.000 0.339 0.000 threading.py:121(acquire)<BR>
81000 0.190 0.000 5.349 0.000 strategies.py:100(setup_query)<BR>
3600 0.187 0.000 6.226 0.002 strategies.py:956(setup_query)<BR>
12934 0.187 0.000 2.630 0.000 handlers.py:784(emit)<BR>
299031 0.183 0.000 0.620 0.000 utf_8.py:15(decode)<BR>
162206 0.183 0.000 1.045 0.000 util.py:886(itervalues)<BR>
3600 0.176 0.000 0.413 0.000<BR>
strategies.py:1161(create_row_processor)<BR>
13835 0.174 0.000 0.174 0.000 {method 'send' of<BR>
'_socket.socket' objects}<BR>
12934 0.171 0.000 0.707 0.000 __init__.py:1218(makeRecord)<BR>
237032 0.169 0.000 0.169 0.000 {method 'split' of 'str' objects}<BR>
21493 0.167 0.000 0.232 0.000 posixpath.py:60(join)<BR>
3600 0.165 0.000 2.391 0.001 mapper.py:2329(_populators)<BR>
76353 0.164 0.000 0.280 0.000 expression.py:2138(__contains__)<BR>
1202 0.161 0.000 0.161 0.000 {method 'rollback' of<BR>
'_mysql.connection' objects}<BR>
24000 0.159 0.000 0.166 0.000 model.py:24(ensure_string_keys)<BR>
852818 0.158 0.000 0.158 0.000 {method 'pop' of 'dict' objects}<BR>
111585 0.156 0.000 0.208 0.000 thread.py:17(get_ident)<BR>
4542 0.154 0.000 3.108 0.001<BR>
visitors.py:241(replacement_traverse)<BR>
12934 0.151 0.000 9.213 0.001 __init__.py:1284(callHandlers)<BR>
158594 0.145 0.000 1.138 0.000 util.py:787(__iter__)<BR>
230769/224673 0.144 0.000 0.266 0.000 {iter}<BR>
253618 0.144 0.000 0.144 0.000 {method 'lower' of<BR>
'unicode' objects}<BR>
3000 0.144 0.000 5.696 0.002<BR>
common.py:293(get_networks_for_instance_from_nw_info)<BR>
733671 0.141 0.000 0.141 0.000 {method 'append' of<BR>
'list' objects}<BR>
41029 0.141 0.000 0.189 0.000 expression.py:3570(__init__)<BR>
19840 0.141 0.000 0.214 0.000 corolocal.py:24(_patch)<BR>
4506/21 0.140 0.000 57.981 2.761 socket.py:406(readline)<BR>
133954 0.139 0.000 0.272 0.000<BR>
cfg.py:440(_get_from_config_parser)<BR>
216531 0.139 0.000 0.772 0.000 connections.py:206(string_decoder)<BR>
45000 0.138 0.000 0.151 0.000 mapper.py:2139(identity_key)<BR>
13526 0.134 0.000 0.937 0.000 log.py:146(process)<BR>
135003 0.134 0.000 0.134 0.000 cfg.py:770(get)<BR>
50425/49225 0.129 0.000 0.986 0.000 {method 'join' of 'str' objects}<BR>
69300 0.129 0.000 7.303 0.000 util.py:621(_corresponding_column)<BR>
600 0.129 0.000 23.205 0.039 api.py:1045(get_all)<BR>
<BR>
_______________________________________________<BR>
Mailing list: <a href="https://launchpad.net/~openstack">https://launchpad.net/~openstack</a><BR>
Post to : <a href="openstack@lists.launchpad.net">openstack@lists.launchpad.net</a><BR>
Unsubscribe : <a href="https://launchpad.net/~openstack">https://launchpad.net/~openstack</a><BR>
More help : <a href="https://help.launchpad.net/ListHelp">https://help.launchpad.net/ListHelp</a><BR>
<BR>
</SPAN></FONT></BLOCKQUOTE>
</BODY>
</HTML>