create_userrc.sh is sllllooww

[Adam Gandelman]

I'm not sure this is a new thing, since log data does not go back that far, but we've been seeing occasional failures of the ironic job due to a slowdown in what devstack is doing between startings n-cpu and ir-api, see Bug #1441007. In looking through logs, it looks like the primary cause in the lag between starting n-cpu and ir-api is the create_userrc.sh script, specifically calls to 'openstack ec2 credentials create' + 'openstack ec2 credentials list', each command taking about 3 secs to complete:

2015-04-06 16:46:19.085 | + openstack ec2 credentials create --user 855dcf30897447ddb1d4562d375844c9 --project 02678d546d5642349a300a34dcf5e02d
2015-04-06 16:46:22.071 | +------------+----------------------------------+
2015-04-06 16:46:22.071 | | Field | Value |
2015-04-06 16:46:22.071 | +------------+----------------------------------+
2015-04-06 16:46:22.071 | | access | 588292339dcf49a79f133d6b32122406 |
2015-04-06 16:46:22.071 | | project_id | 02678d546d5642349a300a34dcf5e02d |
2015-04-06 16:46:22.071 | | secret | 2dba25517d004613ae4b4fcbe34aa29b |
2015-04-06 16:46:22.071 | | trust_id | None |
2015-04-06 16:46:22.072 | | user_id | 855dcf30897447ddb1d4562d375844c9 |
2015-04-06 16:46:22.072 | +------------+----------------------------------+
2015-04-06 16:46:22.205 | ++ openstack ec2 credentials list --user 855dcf30897447ddb1d4562d375844c9
2015-04-06 16:46:22.206 | ++ grep ' 02678d546d5642349a300a34dcf5e02d '
2015-04-06 16:46:25.275 | + line='| 588292339dcf49a79f133d6b32122406 | 2dba25517d004613ae4b4fcbe34aa29b | 02678d546d5642349a300a34dcf5e02d | 855dcf30897447ddb1d4562d375844c9 |'
2015-04-06 16:46:25.275 | + local ec2_access_key ec2_secret_key
2015-04-06 16:46:25.275 | + read ec2_access_key ec2_secret_key
2015-04-06 16:46:25.275 | ++ echo '|' 588292339dcf49a79f133d6b32122406 '|' 2dba25517d004613ae4b4fcbe34aa29b '|' 02678d546d5642349a300a34dcf5e02d '|' 855dcf30897447ddb1d4562d375844c9 '|'
2015-04-06 16:46:25.276 | ++ awk '{print $2 " " $4 }'

Between create and list, create_userrc.sh is calling 24 osc ec2 commands (at least for this specific job), sometimes burning almost 2 mins. The ironic issue can be worked around with a bump to its API retries, but there may be something else new going on here causing the slowdown.

Example log @ http://logs.openstack.org/39/170439/2/gate/gate-tempest-dsvm-ironic-agent_ssh/66849d2/logs/devstacklog.txt.gz#_2015-04-06_16_46_19_085 and excerpts attached here for posterity.

[Steve Martinelli (stevemar)]

possibly related to https://bugs.launchpad.net/python-openstackclient/+bug/1431649

[Steve Martinelli (stevemar)]

I'm going to mark this as a duplicate of 1431649, which should also be fixed. We essentially now do lazy importing of specific packages that we know are heavier (the python-*clients). If you get a chance, check to see if you're getting the same results (2 minutes for 24 osc ec2 commands), if the problem is still lingering we can open a new bug.