openstack client is slow to start (initializing all plugins)

[Thomas Morin]

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)]

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)]

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.

[Thomas Morin (tmmorin-orange)]

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)]

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)]

Setuptools has merged a fix for this issue [1].
This is released as part of setuptools 36.6.1 [2]

[1] https://github.com/pypa/setuptools/commit/4ee5c6510006d384f9ddd444824367ccaf67f0c9
[2] https://github.com/pypa/setuptools/commit/4995726bbdc92ab1f4235dfc8b9ee08c9f365d3e

[Thomas Morin (tmmorin-orange)]

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

[Steve Martinelli (stevemar)]

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

[Thomas Morin (tmmorin-orange)]

setuptools now has a release with this improvement

[Thomas Morin (tmmorin-orange)]

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.