yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1259827] [NEW] keystone execute SQL statments so many times?

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: nethawk <13951798214@xxxxxxx>
Date: Wed, 11 Dec 2013 06:10:18 -0000
Reply-to: Bug 1259827 <1259827@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

When I login horizon,I found keystone query database tables many times.

>From keystone.log,I can see the steps like this: 
step1:keystone recieve request like this :{"auth": {"passwordCredentials":{"username": "admin", "password":"*"}}} step2:keystone query user table by username and domain id 
stpe3:keystone query user table by user id 
step4:keystone query user table by user id 
step5:keystone query user_group_membership table 
step6:keystone query domain table 
step7:keystone create a new token and insert it into token table

>From above steps,we can see keystone query the user table tree times,I
think once is enough. Especially the step3 and step4 are repeated.

So many sql statments will reduce the performance of database.

Here are the keystone logs:

2013-12-11 09:41:21    DEBUG [keystone.common.wsgi] {"auth": {"passwordCredentials":{"username": "admin", "password":"***"}}}
2013-12-11 09:41:21    DEBUG [keystone.common.wsgi]
2013-12-11 09:41:21    DEBUG [keystone.common.wsgi] arg_dict: {}
2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] SELECT user.id AS user_id, user.name AS user_name, user.domain_id AS user_domain_id, user.password AS user_password, user.enabled AS user_enabled, user.extra AS user_extra
FROM user
WHERE user.name = %s AND user.domain_id = %s
2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] ('admin', 'default')
2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] SELECT user.id AS user_id, user.name AS user_name, user.domain_id AS user_domain_id, user.password AS user_password, user.enabled AS user_enabled, user.extra AS user_extra
FROM user
WHERE user.id = %s
 LIMIT %s
2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] ('5463d155acf642f1b0354036f7a8a84b', 1)
2013-12-11 09:41:21     INFO [passlib.registry] registered crypt handler 'sha512_crypt': <class 'passlib.handlers.sha2_crypt.sha512_crypt'>
2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] SELECT user.id AS user_id, user.name AS user_name, user.domain_id AS user_domain_id, user.password AS user_password, user.enabled AS user_enabled, user.extra AS user_extra
FROM user
WHERE user.id = %s
 LIMIT %s
2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] ('5463d155acf642f1b0354036f7a8a84b', 1)
2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] SELECT user_group_membership.user_id AS user_group_membership_user_id, user_group_membership.group_id AS user_group_membership_group_id
FROM user_group_membership
WHERE user_group_membership.user_id = %s
2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] ('5463d155acf642f1b0354036f7a8a84b',)
2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] SELECT domain.id AS domain_id, domain.name AS domain_name, domain.enabled AS domain_enabled, domain.extra AS domain_extra
FROM domain
WHERE domain.id = %s
 LIMIT %s
2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] ('default', 1)
2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] BEGIN (implicit)
2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] INSERT INTO token (id, expires, extra, valid, user_id, trust_id) VALUES (%s, %s, %s, %s, %s, %s)
2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] ('903e4d7e80573b2ec4a6dbc7a285b219', datetime.datetime(2013, 12, 12, 1, 41, 21, 845497), '{"key": "MIICbgYJKoZIhvcNAQcCoIICXzCCAlsCAQExCTAHBgUrDgMCGjCCAUcGCSqGSIb3DQEHAaCCATgEggE0eyJhY2Nlc3MiOiB7InRva2VuIjogeyJpc3N1ZWRfYXQiOiAiMjAxMy0xMi0xMVQwMTo0MToyMS44NDg1MjEiLCAiZXhwaXJlcyI6ICIyMDEzLTEyLTEyVDAxOjQxOjIxWiIsICJpZCI6ICJwbGFjZWhvbGRlciJ9LCAic2VydmljZUNhdGFsb2ciOiBbXSwgInVzZXIiOiB7InVzZXJuYW1lIjogImFkbWluIiwgInJvbGVzX2xpbmtzIjogW10sICJpZCI6ICI1NDYzZDE1NWFjZjY0MmYxYjAzNTQwMzZmN2E4YTg0YiIsICJyb2xlcyI6IFtdLCAibmFtZSI6ICJhZG1pbiJ9LCAibWV0YWRhdGEiOiB7ImlzX2FkbWluIjogMCwgInJvbGVzIjogW119fX0xgf8wgfwCAQEwXDBXMQswCQYDVQQGEwJVUzEOMAwGA1UECBMFVW5zZXQxDjAMBgNVBAcTBVVuc2V0MQ4wDAYDVQQKEwVVbnNldDEYMBYGA1UEAxMPd3d3LmV4YW1wbGUuY29tAgEBMAcGBSsOAwIaMA0GCSqGSIb3DQEBAQUABIGAKxDfbLnxLg+pZ2aTM28JIFiZLfGbubbiM+Edg9wbE+wV5uB0C7Q8nHLQxaMrRtYmOUmLLPnvp8uBdEcxWtnTazgt5k1i4LOQyn+teWGcIQeyoC8kl4eNmIgBeT+PqFVKpss4uBAaVlXIuqVUJXBRQIY6GhrKz3BUnVl8+w4keTY=", "user": {"email": "admin@xxxxxxx", "tenantId": "d5030c82dca9485082920b9d123618f4", "enabled": true, "name": "admin", "id": "5463d155acf642f1b0354036f7a8a84b"}, "tenant": null, "metadata": {"roles": []}}', 1, '5463d155acf642f1b0354036f7a8a84b', None)
2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] COMMIT

** Affects: keystone
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to Keystone.
https://bugs.launchpad.net/bugs/1259827

Title:
  keystone execute SQL statments so many times?

Status in OpenStack Identity (Keystone):
  New

Bug description:
  When I login horizon,I found keystone query database tables many
  times.

  From keystone.log,I can see the steps like this: 
  step1:keystone recieve request like this :{"auth": {"passwordCredentials":{"username": "admin", "password":"*"}}} step2:keystone query user table by username and domain id 
  stpe3:keystone query user table by user id 
  step4:keystone query user table by user id 
  step5:keystone query user_group_membership table 
  step6:keystone query domain table 
  step7:keystone create a new token and insert it into token table

  From above steps,we can see keystone query the user table tree times,I
  think once is enough. Especially the step3 and step4 are repeated.

  So many sql statments will reduce the performance of database.

  Here are the keystone logs:

  2013-12-11 09:41:21    DEBUG [keystone.common.wsgi] {"auth": {"passwordCredentials":{"username": "admin", "password":"***"}}}
  2013-12-11 09:41:21    DEBUG [keystone.common.wsgi]
  2013-12-11 09:41:21    DEBUG [keystone.common.wsgi] arg_dict: {}
  2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] SELECT user.id AS user_id, user.name AS user_name, user.domain_id AS user_domain_id, user.password AS user_password, user.enabled AS user_enabled, user.extra AS user_extra
  FROM user
  WHERE user.name = %s AND user.domain_id = %s
  2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] ('admin', 'default')
  2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] SELECT user.id AS user_id, user.name AS user_name, user.domain_id AS user_domain_id, user.password AS user_password, user.enabled AS user_enabled, user.extra AS user_extra
  FROM user
  WHERE user.id = %s
   LIMIT %s
  2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] ('5463d155acf642f1b0354036f7a8a84b', 1)
  2013-12-11 09:41:21     INFO [passlib.registry] registered crypt handler 'sha512_crypt': <class 'passlib.handlers.sha2_crypt.sha512_crypt'>
  2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] SELECT user.id AS user_id, user.name AS user_name, user.domain_id AS user_domain_id, user.password AS user_password, user.enabled AS user_enabled, user.extra AS user_extra
  FROM user
  WHERE user.id = %s
   LIMIT %s
  2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] ('5463d155acf642f1b0354036f7a8a84b', 1)
  2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] SELECT user_group_membership.user_id AS user_group_membership_user_id, user_group_membership.group_id AS user_group_membership_group_id
  FROM user_group_membership
  WHERE user_group_membership.user_id = %s
  2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] ('5463d155acf642f1b0354036f7a8a84b',)
  2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] SELECT domain.id AS domain_id, domain.name AS domain_name, domain.enabled AS domain_enabled, domain.extra AS domain_extra
  FROM domain
  WHERE domain.id = %s
   LIMIT %s
  2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] ('default', 1)
  2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] BEGIN (implicit)
  2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] INSERT INTO token (id, expires, extra, valid, user_id, trust_id) VALUES (%s, %s, %s, %s, %s, %s)
  2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] ('903e4d7e80573b2ec4a6dbc7a285b219', datetime.datetime(2013, 12, 12, 1, 41, 21, 845497), '{"key": "MIICbgYJKoZIhvcNAQcCoIICXzCCAlsCAQExCTAHBgUrDgMCGjCCAUcGCSqGSIb3DQEHAaCCATgEggE0eyJhY2Nlc3MiOiB7InRva2VuIjogeyJpc3N1ZWRfYXQiOiAiMjAxMy0xMi0xMVQwMTo0MToyMS44NDg1MjEiLCAiZXhwaXJlcyI6ICIyMDEzLTEyLTEyVDAxOjQxOjIxWiIsICJpZCI6ICJwbGFjZWhvbGRlciJ9LCAic2VydmljZUNhdGFsb2ciOiBbXSwgInVzZXIiOiB7InVzZXJuYW1lIjogImFkbWluIiwgInJvbGVzX2xpbmtzIjogW10sICJpZCI6ICI1NDYzZDE1NWFjZjY0MmYxYjAzNTQwMzZmN2E4YTg0YiIsICJyb2xlcyI6IFtdLCAibmFtZSI6ICJhZG1pbiJ9LCAibWV0YWRhdGEiOiB7ImlzX2FkbWluIjogMCwgInJvbGVzIjogW119fX0xgf8wgfwCAQEwXDBXMQswCQYDVQQGEwJVUzEOMAwGA1UECBMFVW5zZXQxDjAMBgNVBAcTBVVuc2V0MQ4wDAYDVQQKEwVVbnNldDEYMBYGA1UEAxMPd3d3LmV4YW1wbGUuY29tAgEBMAcGBSsOAwIaMA0GCSqGSIb3DQEBAQUABIGAKxDfbLnxLg+pZ2aTM28JIFiZLfGbubbiM+Edg9wbE+wV5uB0C7Q8nHLQxaMrRtYmOUmLLPnvp8uBdEcxWtnTazgt5k1i4LOQyn+teWGcIQeyoC8kl4eNmIgBeT+PqFVKpss4uBAaVlXIuqVUJXBRQIY6GhrKz3BUnVl8+w4keTY=", "user": {"email": "admin@xxxxxxx", "tenantId": "d5030c82dca9485082920b9d123618f4", "enabled": true, "name": "admin", "id": "5463d155acf642f1b0354036f7a8a84b"}, "tenant": null, "metadata": {"roles": []}}', 1, '5463d155acf642f1b0354036f7a8a84b', None)
  2013-12-11 09:41:21     INFO [sqlalchemy.engine.base.Engine] COMMIT

To manage notifications about this bug go to:
https://bugs.launchpad.net/keystone/+bug/1259827/+subscriptions
Follow ups

[Bug 1259827] Re: keystone execute SQL statements so many times?
From: Steve Martinelli, 2016-08-01
[Bug 1259827] [NEW] keystone execute SQL statments so many times?
From: nethawk, 2013-12-11
References

[Bug 1259827] [NEW] keystone execute SQL statments so many times?
From: nethawk, 2013-12-11