openstack client is slow to start (initializing all plugins)

Bug #1702483 reported by Thomas Morin on 2017-07-05
26
This bug affects 5 people
Affects Status Importance Assigned to Milestone
python-openstackclient
Confirmed
High
Unassigned

Bug Description

I have been observing that openstack client is slow to start, a handful of second for a simple command.

I ran the pyflame profiler on a simple command (keystone user creation) and observed that a very large fraction of the time is spent by the plugin initialization code (openstackclient/common/clientmanager.py:get_plugin_modules) in call to pkg_resource.iter_entry_points (see attached profiling traces), which itself is spending most of its time in parsing requirements (pkg_resources/__init__.py:parse_requirements).

I don't actually have an idea of how to fix this, but it seems to me that in the case where openstack client is used to run one command of one plugin, initializing all plugins may perhaps be avoided.

Note that I looked at this after observing that a devstack stack.sh on my typical environments takes a significant amount of time in the openstack client command:

=========================
DevStack Component Timing
=========================
Total runtime 896

run_process 10
test_with_retry 3
apt-get-update 2
pip_install 202
osc 186 <=====================
wait_for_service 16
dbsync 23
apt-get 113
=========================

I'm thinking that saving a large fraction of something that takes a significant fraction of stack.sh, itself taking a large fraction of a typical devstack job, may end up bringing a measurable improvement to the overall CPU load of the openstack CI.

Thomas Morin (tmmorin-orange) wrote :
Thomas Morin (tmmorin-orange) wrote :

I've investigated deeper and perhaps found a place in setuptools that could lead to a significant improvement to iter_entry_point performance (the hotpoint to which the flamegraph above is pointing at).

See https://github.com/pypa/setuptools/issues/1132

Applying the change proposed in this issue, on a devstack with only 5 osc extensions installed, results from "openstack user list" total runtime improving from 2.6s to 1.7s.

Dean Troyer (dtroyer) wrote :

Thanks for digging in to this, we know setuptools is a significant problem in startup times. One thing that may be helpful (in case you are not aware of it) is the --timing option that reports the round trip times for API calls. This would let you remove the servers from the total OSC run times and get rid of one variable.

Changed in python-openstackclient:
status: New → Confirmed
importance: Undecided → High
Thomas Morin (tmmorin-orange) wrote :

Thanks Dean.

Here are more relevant timing, using with the --timing option...

***** original setuptools code *****

stack@tm-devstack-master-01:~/devstack$ time openstack --timing user list
+----------------------------------+-----------+
| ID | Name |
+----------------------------------+-----------+
| 14a80a42d7b3438faae35d2368ea1932 | placement |
| 2b47ace878114a77aec6c40eecdc4f2e | demo |
| 3350c86df12f46b3ae3fe2650ff551ac | nova |
| 6b338058fbef4bec8d6914d068785f23 | alt_demo |
| 6c7432c0c0f146df94dfa1758851b4eb | admin |
| 78261b8f3d514434ae561736cb4ace88 | neutron |
| b77ca01c3fa84641ab6f9ee1742347d1 | cinder |
| e86b3c41d7d4411f9fbc7e42f4306ee7 | glance |
+----------------------------------+-----------+

+-----------------------------------------------------+----------+
| URL | Seconds |
+-----------------------------------------------------+----------+
| GET http://192.168.122.192/identity | 0.004805 |
| POST http://192.168.122.192/identity/v3/auth/tokens | 0.048747 |
| POST http://192.168.122.192/identity/v3/auth/tokens | 0.045331 |
| GET http://192.168.122.192/identity/v3/users | 0.052543 |
| Total | 0.151426 |
+-----------------------------------------------------+----------+

real 0m2.581s
user 0m2.220s
sys 0m0.124s

==> 2.43s runtime (not counting API calls)

***** After my proposed setuptools patch *****

stack@tm-devstack-master-01:~/devstack$ time openstack --timing user list
+----------------------------------+-----------+
| ID | Name |
+----------------------------------+-----------+
| 14a80a42d7b3438faae35d2368ea1932 | placement |
| 2b47ace878114a77aec6c40eecdc4f2e | demo |
| 3350c86df12f46b3ae3fe2650ff551ac | nova |
| 6b338058fbef4bec8d6914d068785f23 | alt_demo |
| 6c7432c0c0f146df94dfa1758851b4eb | admin |
| 78261b8f3d514434ae561736cb4ace88 | neutron |
| b77ca01c3fa84641ab6f9ee1742347d1 | cinder |
| e86b3c41d7d4411f9fbc7e42f4306ee7 | glance |
+----------------------------------+-----------+

+-----------------------------------------------------+----------+
| URL | Seconds |
+-----------------------------------------------------+----------+
| GET http://192.168.122.192/identity | 0.00484 |
| POST http://192.168.122.192/identity/v3/auth/tokens | 0.050452 |
| POST http://192.168.122.192/identity/v3/auth/tokens | 0.042775 |
| GET http://192.168.122.192/identity/v3/users | 0.052067 |
| Total | 0.150134 |
+-----------------------------------------------------+----------+

real 0m1.684s
user 0m1.324s
sys 0m0.148s

==> 1.53s runtime (not counting API calls)

So the patch brings a 0.9s win for a setup with only 5 osc extensions (real setups have much more).

Thomas Morin (tmmorin-orange) wrote :

Would there be some old time OpenStack guru having already had some interactions with setuptools folks and would may have a look, and possibly help push a pull request there ? [1]

[1] https://github.com/pypa/setuptools/pull/1144

Thomas Morin (tmmorin-orange) wrote :
Thomas Morin (tmmorin-orange) wrote :

Sorry, this *will* *be* released in 36.6.1 ...

Steve Martinelli (stevemar) wrote :

that's awesome to hear, thanks for sticking with this one thomas!

Thomas Morin (tmmorin-orange) wrote :

setuptools now has a release with this improvement

Thomas Morin (tmmorin-orange) wrote :

I have tried to estimate the improvement on CI devstack times with logstash, and came up with this nice graph, that show an approximate improvement of 3 minutes over 20~ for the legacy-tempest-dsvm-neutron-full job.

setuptools 37.x was released on nov 10th, and with see a clear shift of the different devstack runtime at this date.

See attached capture.

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.