openstack team mailing list archive
-
openstack team
-
Mailing list archive
-
Message #09965
Re: profiling nova-api
Just a small warning: since cProfile has its own overhead on entering/exiting every method and uses deterministic rather than statistical profiling, it may misrepresent tiny functions. They will take much more wall-clock time simply due to the profiling overhead * number of executions.
I'm not saying cfg is not slow, but in this case it may be worth confirming the actual time spend on each call by doing a minimalistic test with timeit, without any profiler (request the same variable 1000000 times and see how much it really takes per iteration).
Regards,
Stanisław Pitucha
Cloud Services
Hewlett Packard
-----Original Message-----
From: openstack-bounces+stanislaw.pitucha=hp.com@xxxxxxxxxxxxxxxxxxx [mailto:openstack-bounces+stanislaw.pitucha=hp.com@xxxxxxxxxxxxxxxxxxx] On Behalf Of Yun Mao
Sent: Wednesday, April 11, 2012 9:48 PM
To: openstack@xxxxxxxxxxxxxxxxxxx
Subject: [Openstack] profiling nova-api
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
References
