2014-04-11 17:39:09.591 15980 ERROR heat.openstack.common.rpc.amqp [req-96c183a9-39b3-4922-95e7-8e8de9d4f87c None] Exception during message handling
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp Traceback (most recent call last):
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/openstack/common/rpc/amqp.py", line 462, in _process_data
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp **args)
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/openstack/common/rpc/dispatcher.py", line 172, in dispatch
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp result = getattr(proxyobj, method)(ctxt, **kwargs)
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/engine/service.py", line 63, in wrapped
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp return func(self, ctx, *args, **kwargs)
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/engine/service.py", line 852, in describe_stack_resource
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp s = self._get_stack(cnxt, stack_identity)
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/engine/service.py", line 338, in _get_stack
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp show_deleted=show_deleted)
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/db/api.py", line 110, in stack_get
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp tenant_safe=tenant_safe)
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/heat/db/sqlalchemy/api.py", line 271, in stack_get
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp result = model_query(context, models.Stack).get(stack_id)
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 827, in get
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp return loading.load_on_ident(self, key)
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/loading.py", line 226, in load_on_ident
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp return q.one()
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2317, in one
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp ret = list(self)
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2360, in __iter__
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp return self._execute_and_instances(context)
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2373, in _execute_and_instances
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp close_with_result=True)
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 2364, in _connection_from_session
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp **kw)
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 799, in connection
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp close_with_result=close_with_result)
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 805, in _connection_for_bind
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp return engine.contextual_connect(**kwargs)
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1661, in contextual_connect
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp self.pool.connect(),
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/pool.py", line 326, in connect
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp return _ConnectionFairy(self).checkout()
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/pool.py", line 485, in __init__
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp rec = self._connection_record = pool._do_get()
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp File "/opt/stack/venvs/heat/local/lib/python2.7/site-packages/sqlalchemy/pool.py", line 766, in _do_get
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp (self.size(), self.overflow(), self._timeout))
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp TimeoutError: QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30
2014-04-11 17:39:09.591 15980 TRACE heat.openstack.common.rpc.amqp
During a deploy of ~30 instances with heat, we see heat engine take 100% of the cpu and load mysql up. This cause the stack to fail with the flowing:
| stack_status_reason | Resource CREATE failed: TimeoutError: QueuePool limit
| | of size 5 overflow 10 reached, connection timed out,
| | timeout 30
There are approx 300-400 reqs/sec hitting mysql from heat-engine, mostly SELECT from resource and from resource_data tables.
We can make thing better but not fix the issue my increasing the look time in the heat scheduler:
heat/engine/ scheduler. py line 196 completion( self, wait_time=20): change this form the default 1 to 20;
def run_to_
However this seems to only reduce the issue rather than fix it (i.e. we get further but the same happened).
We also see the loading stay high even after the failure and only at heat stack-delete do you see the load decrease.