sqlalchemy connection pool limit reached which causes overflow connection timeout

[David Peraza]

From time to time we get this error:

Still trying to figure out how connections are returned to the pool, I see that calling session close will do it, but there must be another way cause session.close is not called at all in nova.db.sqlalchemy.api.py and this is still a random error.

QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30 Which causes the api operation to fail.

Here is an example:

2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack File "/usr/lib/python2.6/site-packages/nova/db/api.py", line 180, in compute_node_get
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack return IMPL.compute_node_get(context, compute_id)
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack File "/usr/lib/python2.6/site-packages/nova/db/sqlalchemy/api.py", line 447, in compute_node_get
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack return _compute_node_get(context, compute_id)
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack File "/usr/lib/python2.6/site-packages/nova/db/sqlalchemy/api.py", line 454, in _compute_node_get
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack options(joinedload('stats')).\
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py", line 2156, in first
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack ret = list(self[0:1])
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py", line 2023, in __getitem__
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack return list(res)
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py", line 2227, in __iter__
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack return self._execute_and_instances(context)
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py", line 2240, in _execute_and_instances
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack close_with_result=True)
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py", line 2231, in _connection_from_session
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack **kw)
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/session.py", line 777, in connection
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack close_with_result=close_with_result)
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/session.py", line 783, in _connection_for_bind
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack return engine.contextual_connect(**kwargs)
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack File "/usr/lib64/python2.6/site-packages/sqlalchemy/engine/base.py", line 2489, in contextual_connect
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack self.pool.connect(),
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack File "/usr/lib64/python2.6/site-packages/sqlalchemy/pool.py", line 236, in connect
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack return _ConnectionFairy(self).checkout()
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack File "/usr/lib64/python2.6/site-packages/sqlalchemy/pool.py", line 401, in __init__
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack rec = self._connection_record = pool._do_get()
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack File "/usr/lib64/python2.6/site-packages/sqlalchemy/pool.py", line 738, in _do_get
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack (self.size(), self.overflow(), self._timeout))
2013-05-07 14:07:16.429 9049 TRACE nova.api.openstack TimeoutError: QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30

Here is another example:

File "/usr/lib/python2.6/site-packages/nova/compute/api.py", line 910, in create_db_entry_for_new_instance
self.security_group_api.ensure_default(context)
File "/usr/lib/python2.6/site-packages/nova/compute/api.py", line 2880, in ensure_default
existed, group = self.db.security_group_ensure_default(context)
File "/usr/lib/python2.6/site-packages/nova/db/api.py", line 1122, in security_group_ensure_default
return IMPL.security_group_ensure_default(context)
File "/usr/lib/python2.6/site-packages/nova/db/sqlalchemy/api.py", line 3177, in security_group_ensure_default
columns_to_join=[], session=session)
File "/usr/lib/python2.6/site-packages/nova/db/sqlalchemy/api.py", line 116, in wrapper
return f(*args, **kwargs)
File "/usr/lib/python2.6/site-packages/nova/db/sqlalchemy/api.py", line 3100, in security_group_get_by_name
result = query.first()
File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py", line 2156, in first
ret = list(self[0:1])
File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py", line 2023, in __getitem__
return list(res)
File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py", line 2227, in __iter__
return self._execute_and_instances(context)
File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py", line 2240, in _execute_and_instances
close_with_result=True)
File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py", line 2231, in _connection_from_session
**kw)
File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/session.py", line 777, in connection
close_with_result=close_with_result)
File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/session.py", line 783, in _connection_for_bind
return engine.contextual_connect(**kwargs)
File "/usr/lib64/python2.6/site-packages/sqlalchemy/engine/base.py", line 2489, in contextual_connect
self.pool.connect(),
File "/usr/lib64/python2.6/site-packages/sqlalchemy/pool.py", line 236, in connect
return _ConnectionFairy(self).checkout()
File "/usr/lib64/python2.6/site-packages/sqlalchemy/pool.py", line 401, in __init__
rec = self._connection_record = pool._do_get()
File "/usr/lib64/python2.6/site-packages/sqlalchemy/pool.py", line 738, in _do_get
(self.size(), self.overflow(), self._timeout))
TimeoutError: QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30

[MotoKen (motokentsai)]

it may be too many requests for db access at the same time.

The TimeoutError "QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30" means:
pool size: 5
overflow: 10
timeout: 30

The current connections reached 15 (5+10). The new request will wait 30 seconds (timeout) to acquire connection from the pool or raise the TimeoutError.

setting the flag sql_max_overflow to -1 or larger than 10 might solve this problem.

[Davanum Srinivas (DIMS) (dims-v)]

logstash has 1953 in the last 48 hours for ceilometer. please search for "QueuePool limit of size 5"

2013-11-01 02:39:05.950 5854 ERROR ceilometer.collector.dispatcher.database [req-1a14aa6c-d503-4489-9950-81744349681a None None] Failed to record metering data: QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30

[gordon chung (chungg)]

related bug: https://bugs.launchpad.net/ceilometer/+bug/1243251