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 -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : [email protected] Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp
