Login | Register For Free | Help
Search for: (Advanced)

Mailing List Archive: OpenStack: Dev

profiling nova-api

  

 
OpenStack dev RSS feed   Index | Next | Previous | View Threaded


yunmao at gmail

Apr 11, 2012, 1:48 PM

Post #1 of 9 (127 views)
Permalink
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 [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp


harlowja at yahoo-inc

Apr 11, 2012, 2:32 PM

Post #2 of 9 (125 views)
Permalink
Re: profiling nova-api [In reply to]
Awesome, great stuff to know!

On 4/11/12 1:48 PM, "Yun Mao" <yunmao [at] gmail> 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
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp


jaypipes at gmail

Apr 12, 2012, 6:49 AM

Post #3 of 9 (122 views)
Permalink
Re: profiling nova-api [In reply to]
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
> Unsubscribe : https://launchpad.net/~openstack
> More help : https://help.launchpad.net/ListHelp

_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to : openstack [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp


justin at fathomdb

Apr 12, 2012, 7:39 AM

Post #4 of 9 (129 views)
Permalink
Re: profiling nova-api [In reply to]
Both the profiling & the multi-process work are great - good stuff!

Jay: Won't going multi-process just make it harder to profile? I think
it's actually a good thing to profile without the multi-process patch, find
& fix and the bottlenecks in single-request performance, and then use
multi-process for great concurrent-request performance?

Justin




On Thu, Apr 12, 2012 at 6:49 AM, Jay Pipes <jaypipes [at] gmail> wrote:

> 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<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<https://launchpad.net/~openstack>
>> Post to : openstack [at] lists
>> Unsubscribe : https://launchpad.net/~**openstack<https://launchpad.net/~openstack>
>> More help : https://help.launchpad.net/**ListHelp<https://help.launchpad.net/ListHelp>
>>
>
> ______________________________**_________________
> Mailing list: https://launchpad.net/~**openstack<https://launchpad.net/~openstack>
> Post to : openstack [at] lists
> Unsubscribe : https://launchpad.net/~**openstack<https://launchpad.net/~openstack>
> More help : https://help.launchpad.net/**ListHelp<https://help.launchpad.net/ListHelp>
>


jaypipes at gmail

Apr 12, 2012, 7:43 AM

Post #5 of 9 (126 views)
Permalink
Re: profiling nova-api [In reply to]
On 04/12/2012 10:39 AM, Justin Santa Barbara wrote:
> Both the profiling & the multi-process work are great - good stuff!
>
> Jay: Won't going multi-process just make it harder to profile?

Yep, that's why I said "also note that your code profiling technique is
unlikely to be effective since cProfile wouldn't track the forked child
worker processes' stacks" ;)

> I think
> it's actually a good thing to profile without the multi-process patch,
> find & fix and the bottlenecks in single-request performance, and then
> use multi-process for great concurrent-request performance?

Agreed!

-jay

_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to : openstack [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp


stanislaw.pitucha at hp

Apr 12, 2012, 8:23 AM

Post #6 of 9 (126 views)
Permalink
Re: profiling nova-api [In reply to]
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 [at] lists [mailto:openstack-bounces+stanislaw.pitucha=hp.com [at] lists] On Behalf Of Yun Mao
Sent: Wednesday, April 11, 2012 9:48 PM
To: openstack [at] lists
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 [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp
_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to : openstack [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp


sdague at linux

Apr 12, 2012, 8:29 AM

Post #7 of 9 (127 views)
Permalink
Re: profiling nova-api [In reply to]
On 04/11/2012 04:48 PM, Yun Mao wrote:
<snip>
> * 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.

Reducing the sqlalchemy 50% is probably going to involve being smarter
about assembling the queries in a more complex way, that prevents us
from going to the db quite so often.

On the MySQL query 50% of the time, it would be good if you can figure
out if we are table scanning in the instance_get_all_by_filters. My
inspection so far definitely shows a lot of things we do WHERE clauses
on that don't have indexes, which is generally bad form.

This bug also has a previous, slightly different, look at digging out
some of these issues - https://bugs.launchpad.net/nova/+bug/964824.

-Sean

--
Sean Dague
IBM Linux Technology Center
email: sldague [at] us
alt-email: sdague [at] linux


_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to : openstack [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp


yunmao at gmail

Apr 12, 2012, 11:54 AM

Post #8 of 9 (128 views)
Permalink
Re: profiling nova-api [In reply to]
Hi Jay,

I will take a look later when I find a box with multiple cores to take
advantage it..

Agreed - cprofiling is not so useful this case. This would be a purely
performance benchmark. If implemented correctly, we should see a
notable gain. However, It will probably not that linear because we
might hit keystone's performance issue later. It looks like the second
CPU hogger behind nova-api. Is there a multiprocess keystone too?

Yun

On Thu, Apr 12, 2012 at 9:49 AM, Jay Pipes <jaypipes [at] gmail> wrote:
> 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
>> Unsubscribe : https://launchpad.net/~openstack
>> More help   : https://help.launchpad.net/ListHelp
>
>
> _______________________________________________
> Mailing list: https://launchpad.net/~openstack
> Post to     : openstack [at] lists
> Unsubscribe : https://launchpad.net/~openstack
> More help   : https://help.launchpad.net/ListHelp

_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to : openstack [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp


yorik.sar at gmail

Apr 13, 2012, 12:25 PM

Post #9 of 9 (126 views)
Permalink
Re: profiling nova-api [In reply to]
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 [at] gmail> 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
> Unsubscribe : https://launchpad.net/~openstack
> More help   : https://help.launchpad.net/ListHelp

_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to : openstack [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp

OpenStack dev RSS feed   Index | Next | Previous | View Threaded
 
 


Interested in having your list archived? Contact Gossamer Threads
 
  Web Applications & Managed Hosting Powered by Gossamer Threads Inc.