504 from keystone during token-create-and-use-for-auth rally scenario

[Leontii Istomin]

During token-create-and-use-for-auth rally scenario we faced with the exception from keystone client:
http://paste.openstack.org/show/304673/

test tries get token and authenticates 470000 times with 94 requests per second.
test has been failed during 134094 iteration.

rabbitmq was failed from 18T15:52:15 to 18T15:56:35 due the bug https://bugs.launchpad.net/fuel/5.1.x/+bug/1460762

Configuration:
Baremetal,Ubuntu,IBP,HA,Neutron-gre,Ceph-all,Nova-debug,Nova-quotas,6.1-522 Controllers:3 Computes+Ceph:47

api: '1.0'
astute_sha: 1ea8017fe8889413706d543a5b9f557f5414beae
auth_required: true
build_id: 2015-06-16_13-53-26
build_number: '522'
feature_groups:
- mirantis
fuel-library_sha: 3528dddbd0c961290909d5e3e256f55ff75cd2fc
fuel-ostf_sha: 8fefcf7c4649370f00847cc309c24f0b62de718d
fuelmain_sha: 42020c36d6dec9fedf61faa68aa3674156d41977
nailgun_sha: fa8dec50f3df2626c97f6c38a897cf4e0f80b39d
openstack_version: 2014.2.2-6.1
production: docker
python-fuelclient_sha: 4fc55db0265bbf39c369df398b9dc7d6469ba13b
release: '6.1'

Rally log of the scenario and rally report are attached.
Diagnostic Snapshot here, but keystone logs have been deleted by logrotate: http://mos-scale-share.mirantis.com/fuel-snapshot-2015-06-19_10-52-44.tar.xz

[Leontii Istomin (listomin)]

marked as invalid, because logs have been deleted by logrotate.
Boris Bobrov prepare additional logging and we'll try to reproduce the issue with custom rally test.

[Leontii Istomin (listomin)]

has been reproduced with 6.1-525 build.

Only one rally scenario was running - token-create-and-use-for-auth

from rally.log: http://paste.openstack.org/show/331675/
root@node-74:~# awk '$11==504' /var/log/messages
<134>Jun 30 18:40:23 node-74 haproxy[6134]: 192.168.0.250:44854 [30/Jun/2015:18:39:23.719] keystone-1 keystone-1/node-74 0/0/0/-1/60000 504 194 - - sH-- 1175/362/362/345/0 0/0 "POST /v2.0/tokens HTTP/1.1"

keystone services keep up to 850% from 1200% processor time
atop from node-74 at the time: http://paste.openstack.org/show/331657/
atop from node-76 at the time: http://paste.openstack.org/show/331664/
atop from node-81 at the time: http://paste.openstack.org/show/331665/

configuration of the environment:
Baremetal,Ubuntu,IBP,HA,Neutron-gre,Сeph-all,Nova-debug,Nova-quotas,6.1_525
Controllers:3 Computes+Ceph:24

api: '1.0'
astute_sha: 1ea8017fe8889413706d543a5b9f557f5414beae
auth_required: true
build_id: 2015-06-19_13-02-31
build_number: '525'
feature_groups:
- mirantis
fuel-library_sha: 2e7a08ad9792c700ebf08ce87f4867df36aa9fab
fuel-ostf_sha: 8fefcf7c4649370f00847cc309c24f0b62de718d
fuelmain_sha: a3998372183468f56019c8ce21aa8bb81fee0c2f
nailgun_sha: dbd54158812033dd8cfd7e60c3f6650f18013a37
openstack_version: 2014.2.2-6.1
production: docker
python-fuelclient_sha: 4fc55db0265bbf39c369df398b9dc7d6469ba13b
release: '6.1'

Diagnostic snapshot is here: http://mos-scale-share.mirantis.com/fuel-snapshot-2015-07-01_09-31-23.tar.xz

Will try to reproduce with additional "prints" and profiling. Boris Bobrov has prepared them already

[Leontii Istomin (listomin)]

Have found second failed test during the previous rally test (comment #2) due the bug - boot_and_list_server_batch_x10 rally scenario
from rally.log: http://paste.openstack.org/show/331894/

root@node-76:~# awk '$11==500' /var/log/messages | grep "30 14:57"
<134>Jun 30 14:57:24 node-76 haproxy[3856]: 172.16.44.12:56412 [30/Jun/2015:14:56:54.658] nova-api-2 nova-api-2/node-81 0/0/0/30202/30203 500 354 - - ---- 8/8/8/0/0 0/0 "GET /v2/a1d69a814aea45d0b7689eae16bdcb8d/servers/554ac853-16fd-4615-b681-634efcf0abaa HTTP/1.1"
<134>Jun 30 14:57:41 node-76 haproxy[3856]: 172.16.44.12:56435 [30/Jun/2015:14:57:10.934] nova-api-2 nova-api-2/node-74 0/0/0/30174/30175 500 354 - - ---- 9/9/9/2/0 0/0 "GET /v2/69cc8be1542e49cba39df505e46a5eb6/servers/357f18bc-d7c4-4c09-b02b-bd1eef14b826 HTTP/1.1"

from nova-all.log on node-81: http://paste.openstack.org/show/331893/
-30 seconds:
<183>Jun 30 14:56:56 node-81 nova-api
REQ: curl -i http://192.168.0.2:9696/v2.0/ports.json?device_id=14d84361-91dc-4b46-b85f-99960f1b328a -X GET -H "X-Auth-Token: 7401cb61585d47549619a295cbf23bdc" -H "User-Agent: python-neutronclient"
<183>Jun 30 14:56:56 node-81 nova-conductor Dynamic looping call <bound method Service.periodic_tasks of <nova.service.Service object at 0x7fd75753e750>> sleeping for 60.00 seconds
<183>Jun 30 14:56:56 node-81 nova-conductor Dynamic looping call <bound method Service.periodic_tasks of <nova.service.Service object at 0x7fd75753e750>> sleeping for 60.00 seconds

root@node-74:~# zgrep 14d84361-91dc-4b46-b85f-99960f1b328a /var/log/messages.2.gz
<134>Jun 30 14:57:15 node-74 haproxy[6134]: 192.168.0.12:52986 [30/Jun/2015:14:56:56.221] neutron neutron/node-81 0/0/0/19763/19764 200 221 - - ---- 642/45/45/12/0 0/0 "GET /v2.0/ports.json?device_id=14d84361-91dc-4b46-b85f-99960f1b328a HTTP/1.1"

atop from node-81 http://paste.openstack.org/show/332008/

[Boris Bobrov (bbobrov)]

Added repoze.profile as a middleware, asked Leontiy to launch tests again.

[Leontii Istomin (listomin)]

testg with the following patch which Boris Bobrov has prepared:
http://paste.openstack.org/show/362664/

[Leontii Istomin (listomin)]

pearformed token-create-and-use-for-auth rally scenario. Used the follwowing tests parameters:
times=2000000
rps=400
tenants=100
user_per_tenant=1
Results with default keystone:
Min (sec) Median (sec) 90%ile (sec) 95%ile (sec) Max (sec) Avg (sec) Success Count
1.676 6.276 7.324 7.405 7.581 5.74 100.0% 24

Results with patched keystone (http://paste.openstack.org/show/362664/):
Min (sec) Median (sec) 90%ile (sec) 95%ile (sec) Max (sec) Avg (sec) Success Count
0.125 0.208 0.246 0.261 12.847 0.225 100.0% 333335

rally results and logs are attached.
Diagnostic Snapshot is here: http://mos-scale-share.mirantis.com/fuel-snapshot-2015-07-11_21-31-32.tar.xz

[Fuel Devops McRobotson (fuel-devops-robot)]

Fix proposed to branch: openstack-ci/fuel-7.0/2015.1.0
Change author: Boris Bobrov <email address hidden>
Review: https://review.fuel-infra.org/10422

[Fuel Devops McRobotson (fuel-devops-robot)]

Reviewed: https://review.fuel-infra.org/10422
Submitter: mos-infra-ci <>
Branch: openstack-ci/fuel-7.0/2015.1.0

Commit: 190305cc3d28f2586b4d33a8179fcf8096e118ca
Author: Boris Bobrov <email address hidden>
Date: Fri Aug 14 00:41:26 2015

Make garbage collection work periodically, not on every request

Garbage collection happened on each request for new token, which had a
serious performance impact.

Make garbage collection happen only if tokens are too old or there are
too many of them and only in limited numbers.

Change-Id: I807e08f8321075282127830f953aaa1aa08a3ebc
Closes-Bug: 1466901

[Boris Bobrov (bbobrov)]

I'll ask scale team to verify this

[Fuel Devops McRobotson (fuel-devops-robot)]

Fix proposed to branch: openstack-ci/fuel-6.1/2014.2
Change author: Boris Bobrov <email address hidden>
Review: https://review.fuel-infra.org/11393

[Fuel Devops McRobotson (fuel-devops-robot)]

Fix proposed to branch: openstack-ci/fuel-6.0-updates/2014.2
Change author: Boris Bobrov <email address hidden>
Review: https://review.fuel-infra.org/11477

[Fuel Devops McRobotson (fuel-devops-robot)]

Reviewed: https://review.fuel-infra.org/11393
Submitter: Vitaly Sedelnik <email address hidden>
Branch: openstack-ci/fuel-6.1/2014.2

Commit: b38c6937feb0645114db2876a9f58e27a90a6f0a
Author: Boris Bobrov <email address hidden>
Date: Fri Sep 11 15:06:42 2015

Make garbage collection work periodically, not on every request

Garbage collection happened on each request for new token, which had a
serious performance impact.

Make garbage collection happen only if tokens are too old or there are
too many of them and only in limited numbers.

Change-Id: I807e08f8321075282127830f953aaa1aa08a3ebc
Closes-Bug: 1466901
(cherry picked from commit 190305cc3d28f2586b4d33a8179fcf8096e118ca)

[Fuel Devops McRobotson (fuel-devops-robot)]

Fix proposed to branch: openstack-ci/fuel-8.0/liberty
Change author: Boris Bobrov <email address hidden>
Review: https://review.fuel-infra.org/13353

[Fuel Devops McRobotson (fuel-devops-robot)]

Reviewed: https://review.fuel-infra.org/11477
Submitter: Vitaly Sedelnik <email address hidden>
Branch: openstack-ci/fuel-6.0-updates/2014.2

Commit: 42ea46b3aff8735179d71164a0e790a68801999e
Author: Boris Bobrov <email address hidden>
Date: Fri Oct 23 17:10:28 2015

Make garbage collection work periodically, not on every request

Garbage collection happened on each request for new token, which had a
serious performance impact.

Make garbage collection happen only if tokens are too old or there are
too many of them and only in limited numbers.

Change-Id: I807e08f8321075282127830f953aaa1aa08a3ebc
Closes-Bug: 1466901
(cherry picked from commit 190305cc3d28f2586b4d33a8179fcf8096e118ca)

[Fuel Devops McRobotson (fuel-devops-robot)]

Change abandoned by Alexander Makarov <email address hidden> on branch: openstack-ci/fuel-8.0/liberty
Review: https://review.fuel-infra.org/13353
Reason: not needed in 8.0

[Vadim Rovachev (vrovachev)]

Verified on Ubuntu 6.0
packages:
keystone,python-keystone
version:
1:2014.2-fuel6.0~mira18