← Back to team overview

yahoo-eng-team team mailing list archive

[Bug 1687073] [NEW] Keystone Memory usage remains high

 

Public bug reported:

I found something interesting while doing a quick load test of keystone
/ newton . When I started the load test the memory usage for keystone
processes (admin and public wsgi) went up – and it never came down even
hours after the test is stopped.  Also found few errors in the log
(given below ) .  E

Also, found that many functions in resource/backends/sql.py are not closing the sessions once open . 
Do we need to close the sessions explicitly ? Is that the reason for persistent high memory usage ? 
Below error is thrown during the test . I guess the error may be due to settings in keystone.conf. Not sure it has anything to do with memory cleanup .
Attached is the script to execute stress test . It will launch 40 threads, and hit keystone at the same time 
----------------------------------
Error-

2017-04-28 14:17:20.702 653 INFO keystone.common.wsgi [req-651d1776-9e5c-405c-82d2-3efe7dbcd5f3 - - - - -] POST http://10.10.10.2:5000/v3/auth/tokens
2017-04-28 14:17:20.878 691 INFO keystone.common.wsgi [req-8bd6baa6-976d-41b5-817a-554b3a7d6c54 - - - - -] GET http://192.168.204.2:35357/v3/
2017-04-28 14:17:20.898 691 INFO keystone.common.wsgi [req-da74eaeb-34d9-4190-8477-fd14a16fab3f b94369832d4d41cea555a9e98c216dd7 f9f5aa29f7994730b0fc845aaba5ade5 - default default] GET http://192.168.204.2:35357/v3/projects
2017-04-28 14:17:20.915 692 INFO keystone.common.wsgi [req-38122a48-2c97-4b41-b3a0-b2a9062c68ac - - - - -] POST http://10.10.10.2:5000/v3/auth/tokens
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi [req-2208fddc-6801-4a9c-a6fd-22cfd310427d - - - - -] QueuePool limit of size 1 overflow 10 reached, connection timed out, timeout 30
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi Traceback (most recent call last):
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 225, in __call__
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     result = method(req, **params)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/auth/controllers.py", line 397, in authenticate_for_token
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     auth_info = AuthInfo.create(auth=auth)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/auth/controllers.py", line 137, in create
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     auth_info._validate_and_normalize_auth_data(scope_only)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/auth/controllers.py", line 310, in _validate_and_normalize_auth_data
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     self._validate_and_normalize_scope_data()
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/auth/controllers.py", line 252, in _validate_and_normalize_scope_data
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     project_ref = self._lookup_project(self.auth['scope']['project'])
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/auth/controllers.py", line 215, in _lookup_project
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     domain_ref = self._lookup_domain(project_info['domain'])
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/auth/controllers.py", line 189, in _lookup_domain
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     domain_ref = self.resource_api.get_domain(domain_id)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/manager.py", line 124, in wrapped
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     __ret_val = __f(*args, **kwargs)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 1220, in decorate
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     should_cache_fn)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 825, in get_or_create
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     async_creator) as value:
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/lock.py", line 154, in __enter__
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return self._enter()
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/lock.py", line 94, in _enter
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     generated = self._enter_create(createdtime)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/lock.py", line 145, in _enter_create
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     created = self.creator()
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 792, in gen_value
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     created_value = creator()
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 1216, in creator
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return fn(*arg, **kw)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/resource/core.py", line 705, in get_domain
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     project = self.driver.get_project(domain_id)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/resource/backends/sql.py", line 49, in get_project
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return self._get_project(session, project_id).to_dict()
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/resource/backends/sql.py", line 42, in _get_project
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     project_ref = session.query(Project).get(project_id)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 831, in get
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return self._get_impl(ident, loading.load_on_ident)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 864, in _get_impl
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return fallback_fn(self, key)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/loading.py", line 219, in load_on_ident
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return q.one()
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2693, in one
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     ret = list(self)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2736, in __iter__
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return self._execute_and_instances(context)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2749, in _execute_and_instances
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     close_with_result=True)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2740, in _connection_from_session
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     **kw)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 905, in connection
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     execution_options=execution_options)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 910, in _connection_for_bind
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     engine, execution_options)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 334, in _connection_for_bind
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     conn = bind.contextual_connect()
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 2039, in contextual_connect
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     self._wrap_pool_connect(self.pool.connect, None),
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 2074, in _wrap_pool_connect
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return fn()
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 376, in connect
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return _ConnectionFairy._checkout(self)
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 713, in _checkout
2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     fairy = _ConnectionRecord.checkout(pool)
2017-04-28 14:17:
2017-04-28 14:17:21.176 691 INFO keystone.common.wsgi [req-09fdd07f-4b7c-4a4c-8115-4e4164eea3e5 fbe1c86982b042f8bc942ad45a2bbcbe 5db2b66a3ea34a1ea9899ad9cfe8b2dd - default default] GET http://192.168.204.2:35357/v3/auth/tokens

** Affects: keystone
     Importance: Undecided
         Status: New


** Tags: keystone memory

** Attachment added: "Load test script"
   https://bugs.launchpad.net/bugs/1687073/+attachment/4869249/+files/main_test.py

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Identity (keystone).
https://bugs.launchpad.net/bugs/1687073

Title:
  Keystone Memory usage remains high

Status in OpenStack Identity (keystone):
  New

Bug description:
  I found something interesting while doing a quick load test of
  keystone / newton . When I started the load test the memory usage for
  keystone processes (admin and public wsgi) went up – and it never came
  down even hours after the test is stopped.  Also found few errors in
  the log (given below ) .  E

  Also, found that many functions in resource/backends/sql.py are not closing the sessions once open . 
  Do we need to close the sessions explicitly ? Is that the reason for persistent high memory usage ? 
  Below error is thrown during the test . I guess the error may be due to settings in keystone.conf. Not sure it has anything to do with memory cleanup .
  Attached is the script to execute stress test . It will launch 40 threads, and hit keystone at the same time 
  ----------------------------------
  Error-

  2017-04-28 14:17:20.702 653 INFO keystone.common.wsgi [req-651d1776-9e5c-405c-82d2-3efe7dbcd5f3 - - - - -] POST http://10.10.10.2:5000/v3/auth/tokens
  2017-04-28 14:17:20.878 691 INFO keystone.common.wsgi [req-8bd6baa6-976d-41b5-817a-554b3a7d6c54 - - - - -] GET http://192.168.204.2:35357/v3/
  2017-04-28 14:17:20.898 691 INFO keystone.common.wsgi [req-da74eaeb-34d9-4190-8477-fd14a16fab3f b94369832d4d41cea555a9e98c216dd7 f9f5aa29f7994730b0fc845aaba5ade5 - default default] GET http://192.168.204.2:35357/v3/projects
  2017-04-28 14:17:20.915 692 INFO keystone.common.wsgi [req-38122a48-2c97-4b41-b3a0-b2a9062c68ac - - - - -] POST http://10.10.10.2:5000/v3/auth/tokens
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi [req-2208fddc-6801-4a9c-a6fd-22cfd310427d - - - - -] QueuePool limit of size 1 overflow 10 reached, connection timed out, timeout 30
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi Traceback (most recent call last):
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 225, in __call__
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     result = method(req, **params)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/auth/controllers.py", line 397, in authenticate_for_token
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     auth_info = AuthInfo.create(auth=auth)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/auth/controllers.py", line 137, in create
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     auth_info._validate_and_normalize_auth_data(scope_only)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/auth/controllers.py", line 310, in _validate_and_normalize_auth_data
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     self._validate_and_normalize_scope_data()
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/auth/controllers.py", line 252, in _validate_and_normalize_scope_data
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     project_ref = self._lookup_project(self.auth['scope']['project'])
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/auth/controllers.py", line 215, in _lookup_project
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     domain_ref = self._lookup_domain(project_info['domain'])
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/auth/controllers.py", line 189, in _lookup_domain
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     domain_ref = self.resource_api.get_domain(domain_id)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/manager.py", line 124, in wrapped
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     __ret_val = __f(*args, **kwargs)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 1220, in decorate
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     should_cache_fn)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 825, in get_or_create
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     async_creator) as value:
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/lock.py", line 154, in __enter__
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return self._enter()
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/lock.py", line 94, in _enter
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     generated = self._enter_create(createdtime)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/lock.py", line 145, in _enter_create
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     created = self.creator()
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 792, in gen_value
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     created_value = creator()
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 1216, in creator
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return fn(*arg, **kw)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/resource/core.py", line 705, in get_domain
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     project = self.driver.get_project(domain_id)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/resource/backends/sql.py", line 49, in get_project
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return self._get_project(session, project_id).to_dict()
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/resource/backends/sql.py", line 42, in _get_project
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     project_ref = session.query(Project).get(project_id)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 831, in get
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return self._get_impl(ident, loading.load_on_ident)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 864, in _get_impl
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return fallback_fn(self, key)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/loading.py", line 219, in load_on_ident
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return q.one()
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2693, in one
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     ret = list(self)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2736, in __iter__
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return self._execute_and_instances(context)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2749, in _execute_and_instances
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     close_with_result=True)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2740, in _connection_from_session
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     **kw)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 905, in connection
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     execution_options=execution_options)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 910, in _connection_for_bind
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     engine, execution_options)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 334, in _connection_for_bind
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     conn = bind.contextual_connect()
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 2039, in contextual_connect
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     self._wrap_pool_connect(self.pool.connect, None),
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 2074, in _wrap_pool_connect
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return fn()
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 376, in connect
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     return _ConnectionFairy._checkout(self)
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 713, in _checkout
  2017-04-28 14:17:21.001 653 ERROR keystone.common.wsgi     fairy = _ConnectionRecord.checkout(pool)
  2017-04-28 14:17:
  2017-04-28 14:17:21.176 691 INFO keystone.common.wsgi [req-09fdd07f-4b7c-4a4c-8115-4e4164eea3e5 fbe1c86982b042f8bc942ad45a2bbcbe 5db2b66a3ea34a1ea9899ad9cfe8b2dd - default default] GET http://192.168.204.2:35357/v3/auth/tokens

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


Follow ups