Updating of instance metadata occasionally leads to a Database deadlock

Bug #1250836 reported by Roman Podoliaka
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Expired
Undecided
Unassigned

Bug Description

During the tempest tests run I got the following error:

2013-11-13 10:09:18.814 ERROR nova.api.openstack [req-a3172f97-0d7c-4f8b-a7a5-bec6aad2b549 ServerMetadataTestJSON-tempest-1285971638-user ServerMetadataTestJSON-tempest-1285971638-tenant] Caught error: (OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') 'INSERT INTO instance_metadata (created_at, updated_at, deleted_at, deleted, `key`, value, instance_uuid) VALUES (%s, %s, %s, %s, %s, %s, %s)' (datetime.datetime(2013, 11, 13, 10, 9, 18, 811419), None, None, 0, 'key3', 'value3', 'ba645a19-78c5-439d-9408-68f413c200f4')
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack Traceback (most recent call last):
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/__init__.py", line 119, in __call__
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack return req.get_response(self.application)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1296, in send
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack application, catch_exc_info=False)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/request.py", line 1260, in call_application
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack app_iter = application(self.environ, start_response)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack return resp(environ, start_response)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/python-keystoneclient/keystoneclient/middleware/auth_token.py", line 571, in __call__
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack return self.app(env, start_response)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack return resp(environ, start_response)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack return resp(environ, start_response)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/usr/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack response = self.app(environ, start_response)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 144, in __call__
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack return resp(environ, start_response)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 130, in __call__
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack resp = self.call_func(req, *args, **self.kwargs)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack return self.func(req, *args, **kwargs)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 939, in __call__
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack content_type, body, accept)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 998, in _process_stack
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack action_result = self.dispatch(meth, request, action_args)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/wsgi.py", line 1079, in dispatch
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack return method(req=request, **action_args)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/compute/server_metadata.py", line 67, in create
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack delete=False)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/api/openstack/compute/server_metadata.py", line 120, in _update_instance_metadata
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack delete)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/compute/api.py", line 197, in wrapped
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack return func(self, context, target, *args, **kwargs)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/compute/api.py", line 187, in inner
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack return function(self, context, instance, *args, **kwargs)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/compute/api.py", line 168, in inner
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack return f(self, context, instance, *args, **kw)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/compute/api.py", line 2843, in update_instance_metadata
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack _metadata, True)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/db/api.py", line 1577, in instance_metadata_update
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack metadata, delete)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 129, in wrapper
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack return f(*args, **kwargs)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/db/sqlalchemy/api.py", line 4615, in instance_metadata_update
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack return metadata
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 456, in __exit__
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack self.commit()
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 368, in commit
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack self._prepare_impl()
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 347, in _prepare_impl
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack self.session.flush()
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/openstack/common/db/sqlalchemy/session.py", line 529, in _wrap
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack _raise_if_deadlock_error(e, get_engine().name)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack File "/opt/stack/new/nova/nova/openstack/common/db/sqlalchemy/session.py", line 516, in _raise_if_deadlock_error
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack raise exception.DBDeadlock(operational_error)
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack DBDeadlock: (OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') 'INSERT INTO instance_metadata (created_at, updated_at, deleted_at, deleted, `key`, value, instance_uuid) VALUES (%s, %s, %s, %s, %s, %s, %s)' (datetime.datetime(2013, 11, 13, 10, 9, 18, 811419), None, None, 0, 'key3', 'value3', 'ba645a19-78c5-439d-9408-68f413c200f4')
2013-11-13 10:09:18.814 22804 TRACE nova.api.openstack

Tags: db
Revision history for this message
Sean Dague (sdague) wrote :

not a tempest bug

no longer affects: tempest
Revision history for this message
Sean Dague (sdague) wrote :

I think the current db architecture means this has to be mitigated against, not sure there is an easy win here.

summary: - Updating of instance metadata occasionally leads to a deadlock
+ Updating of instance metadata occasionally leads to a Database deadlock
Changed in nova:
status: New → Confirmed
importance: Undecided → Medium
Revision history for this message
Markus Zoeller (markus_z) (mzoeller) wrote : Cleanup EOL bug report

This is an automated cleanup. This bug report has been closed because it
is older than 18 months and there is no open code change to fix this.
After this time it is unlikely that the circumstances which lead to
the observed issue can be reproduced.

If you can reproduce the bug, please:
* reopen the bug report (set to status "New")
* AND add the detailed steps to reproduce the issue (if applicable)
* AND leave a comment "CONFIRMED FOR: <RELEASE_NAME>"
  Only still supported release names are valid (LIBERTY, MITAKA, OCATA, NEWTON).
  Valid example: CONFIRMED FOR: LIBERTY

Changed in nova:
importance: Medium → Undecided
status: Confirmed → Expired
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.