Bug 1246084

Summary:	Too many connections when benchmarking Fernet/UUID Keystone Tokens at high concurrency
Product:	Red Hat OpenStack	Reporter:	Alex Krzos <akrzos>
Component:	rhosp-director	Assignee:	chris alfonso <calfonso>
Status:	CLOSED DUPLICATE	QA Contact:	yeylon <yeylon>
Severity:	high	Docs Contact:
Priority:	high
Version:	7.0 (Kilo)	CC:	hbrock, jtaleric, mburns, rhel-osp-director-maint, srevivo, yeylon
Target Milestone:	---	Keywords:	Reopened
Target Release:	8.0 (Liberty)
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2015-08-27 16:46:23 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Alex Krzos 2015-07-23 12:39:14 UTC

Description of problem:
Benchmarking Keystone on OSPD deployed multi-controller (3 controllers, 1 compute node) using rally to create and validate tokens, I ran into _mysql_exceptions.OperationalError Too many connections.  I tested both UUID and Fernet tokens in eventlet (OSP-D deployed Keystone in eventlet although it is deprecated) which both ran into this issue at high concurrency (512, 768, 1024 number of constant concurrent token creations + validations)  Reviewing the keystone log files on the controllers revealed the stack trace below.

I then arbitrarily raised the default of 1024 connections to 4096 in galera.cnf on all three nodes and retested.

Fernet tokens highly outperformed the UUID tokens and no longer had any test failures.  UUID tokens also no longer had the below stack trace however there was failures to connect to the Keystone service. (Authorization Failed: Unable to establish connection to http://....:5000/v2.0/tokens)

Performance difference between Fernet and UUID at 1024 Constant Concurrency:

Token    Min(s) Med(s)  90%(s)  95%(s)  Max(s)  Avg(s)	Success	Count
Fernet - 0.358	2.982	9.181	10.618	16.852	4.1	100.0%	10000
UUID -   1.032	19.501	44.458	51.357	62.507	22.06	95.9%	10000

Version-Release number of selected component (if applicable):
OSP

How reproducible:
In this environment it is reproducible

Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

Keystone.log

2015-07-21 18:11:21.816 18092 ERROR keystone.common.wsgi [-] (_mysql_exceptions.OperationalError) (1040, 'Too many connections')
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi Traceback (most recent call last):
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 239, in __call__
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     result = method(context, **params)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/token/controllers.py", line 101, in authenticate
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     context, auth)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/token/controllers.py", line 293, in _authenticate_local
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     username, CONF.identity.default_domain_id)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/identity/core.py", line 342, in wrapper
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     return f(self, *args, **kwargs)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/identity/core.py", line 353, in wrapper
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     return f(self, *args, **kwargs)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 1040, in decorate
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     should_cache_fn)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 651, in get_or_create
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     async_creator) as value:
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/core/dogpile.py", line 158, in __enter__
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     return self._enter()
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/core/dogpile.py", line 98, in _enter
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     generated = self._enter_create(createdtime)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/core/dogpile.py", line 149, in _enter_create
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     created = self.creator()
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 619, in gen_value
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     created_value = creator()
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 1036, in creator
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     return fn(*arg, **kw)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/identity/core.py", line 773, in get_user_by_name
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     ref = driver.get_user_by_name(user_name, domain_id)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/identity/backends/sql.py", line 143, in get_user_by_name
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     user_ref = query.one()
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2472, in one
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     ret = list(self)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2515, in __iter__
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     return self._execute_and_instances(context)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2528, in _execute_and_instances
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     close_with_result=True)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2519, in _connection_from_session
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     **kw)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 882, in connection
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     execution_options=execution_options)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 889, in _connection_for_bind
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     conn = engine.contextual_connect(**kw)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 2037, in contextual_connect
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     self._wrap_pool_connect(self.pool.connect, None),
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 2076, in _wrap_pool_connect
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     e, dialect, self)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1401, in _handle_dbapi_exception_noconnection
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     util.raise_from_cause(newraise, exc_info)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 199, in raise_from_cause
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     reraise(type(exception), exception, tb=exc_tb)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 2072, in _wrap_pool_connect
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     return fn()
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 376, in connect
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     return _ConnectionFairy._checkout(self)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 708, in _checkout
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     fairy = _ConnectionRecord.checkout(pool)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 480, in checkout
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     rec = pool._do_get()
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 1055, in _do_get
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     self._dec_overflow()
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     compat.reraise(exc_type, exc_value, exc_tb)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 1052, in _do_get
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     return self._create_connection()
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 323, in _create_connection
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     return _ConnectionRecord(self)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 449, in __init__
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     self.connection = self.__connect()
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 602, in __connect
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     connection = self.__pool._invoke_creator(self)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/strategies.py", line 97, in connect
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     return dialect.connect(*cargs, **cparams)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 385, in connect
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     return self.dbapi.connect(*cargs, **cparams)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/MySQLdb/__init__.py", line 81, in Connect
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     return Connection(*args, **kwargs)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi   File "/usr/lib64/python2.7/site-packages/MySQLdb/connections.py", line 187, in __init__
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi     super(Connection, self).__init__(*args, **kwargs2)
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi OperationalError: (_mysql_exceptions.OperationalError) (1040, 'Too many connections')
2015-07-21 18:11:21.816 18092 TRACE keystone.common.wsgi

Comment 3 Michael Bayer 2015-07-23 13:52:51 UTC

there's a lot of work going on regarding this and it involves the installer which ultimately configures the my.cnf files, as that number can't be hardcoded arbitrarily.  The issue where this is being dealt with is #1240826 and I propose this is a duplicate of that.

*** This bug has been marked as a duplicate of bug 1240826 ***

Comment 4 Alex Krzos 2015-08-21 19:55:24 UTC

Re-opening as the duplicate was fixed in OFI and not OSPD.  Installs from OSPD still have 1024 max-connections.

Comment 5 Michael Bayer 2015-08-21 20:31:37 UTC

OK.....OSPD is openstack-puppet?  This bug should be changed to reflect that component.   the mariadb-galera component does not include the openstack installer.

Comment 6 Mike Burns 2015-08-27 16:46:23 UTC

This is still a duplicate, just of a different bug number.  OSPd has a series of bugs that handle this.  We've provided methods for increasing this and there are also bugs for bumping the default and another which will dynamically calculate and set it.

*** This bug has been marked as a duplicate of bug 1240824 ***