Public bug reported:
Description
===========
nova.virt.libvirt./driver.py:LibvirtDriver._live_migration() spawn a thread to
execute _live_migration_operation(called after threadA).Original thread execute
_live_migration_monitor (called after threadB).
Assignment statement inst_type=instance.flavor call
nova/objects/instance.py:obj_load_attr in function _live_migration_operation.
Function _live_migration_monitor call func _live_migration_data_gb。Assignment
statement ram_gb = instance.flavor.memory_mb * units.Mi / units.Gi also call
nova/objects/instance.py:obj_load_attr.
Function temporary_mutation is called by obj_load_attr. The mistack caused by
the temporary_mutation is called by two threads simultaneously。
Time0: self._context[‘read_deleted’] is ‘no’
Time1: ThreadA called temporary_mutation, self._context[‘read_deleted’] is
assigned a value of ‘yes’. Old value is ‘no’.
Time2: ThreadB called temporary_mutation, self._context[‘read_deleted’] is
assigned a value of ‘yes’. Old value is ‘yes’.
Time3: ThreadA executing finally code of temporary_mutation, the value of
self._context[‘read_deleted’] is restored to ‘no’.
Time3: ThreadA executing finally code of temporary_mutation, the value of
self._context[‘read_deleted’] is restored to ‘yes’.
Result : Two calls to temporary_mutation cause the value of
self._context[‘read_deleted’] to change from ‘no’ to ‘yes’. When Source host
calling update_available_resource(ctxt) in _post_live_migration, calling of
objects.InstanceList.get_by_host_and_node() will read deleted instances, which
is time-consuming.
===========
Add the log
===========
Print self._context in obj_load_attr()
def obj_load_attr(self, attrname):
# NOTE(danms): We can't lazy-load anything without a context and a uuid
if not self._context:
raise exception.OrphanedObjectError(method='obj_load_attr',
objtype=self.obj_name())
if 'uuid' not in self:
raise exception.ObjectActionError(
action='obj_load_attr',
reason=_('attribute %s not lazy-loadable') % attrname)
- LOG.debug("Lazy-loading '%(attr)s' on %(name)s uuid %(uuid)s",
+ LOG.debug("Lazy-loading '%(attr)s' on %(name)s uuid %(uuid)s context
%(context)s",
{'attr': attrname,
'name': self.obj_name(),
'uuid': self.uuid,
+ 'context': self._context,
})
===========
Logs
===========
2021-08-23 18:36:25.838 7 DEBUG nova.objects.instance
[req-f3aa8a61-ca57-457e-a813-de5d226b2ff7 - - - - -] Lazy-loading 'flavor' on
Instance uuid 18e4e517-7556-40be-8833-35290127c2e7 context <Context {'domain':
None, 'project_name': u'admin', 'global_request_id': None, 'project_domain':
u'default', 'timestamp': '2021-08-23T10:32:53.582673', 'auth_token':
u'gAAAAABhI3lQbJgenzhpGw9daG5k1aUs3evWyZCQvujjhTZ0GZb2WIz_Eor4rlz9hPY-QxCBgH1z8nU2iTSMwPeJ5dEnEgPxmxrFq45XGXF9nLcrwCSUQfetie8k84OtEQYnhNVIE4uuPBJzRUNp9-rL6cRD8yhwXob9eSKsaZdtmTXxSBuOtJ8',
'remote_address': u'192.168.1.11', 'quota_class': None, 'resource_uuid': None,
'is_admin': True, 'user': u'5ca52b5e65df4d879dd490afa350a3f0',
'service_catalog': [{u'endpoints': [{u'adminURL': u'http://10.0.1.10:9292',
u'region': u'RegionOne', u'internalURL': u'http://10.0.1.10:9292',
u'publicURL': u'http://192.168.1.10:9292'}], u'type': u'image', u'name':
u'glance'}, {u'endpoints': [{u'adminURL': u'http://10.0.1.10:8780', u'region':
u'RegionOne', u'internalURL': u'http://10.0.1.10:8780', u'publicURL':
u'http://192.168.1.10:8780'}], u'type': u'placement', u'name': u'placement'},
{u'endpoints': [{u'adminURL':
u'http://10.0.1.10:8776/v3/76e23046831943bba571f0e3ea432182', u'region':
u'RegionOne', u'internalURL':
u'http://10.0.1.10:8776/v3/76e23046831943bba571f0e3ea432182', u'publicURL':
u'http://192.168.1.10:8776/v3/76e23046831943bba571f0e3ea432182'}], u'type':
u'volumev3', u'name': u'cinderv3'}, {u'endpoints': [{u'adminURL':
u'http://10.0.1.10:9696', u'region': u'RegionOne', u'internalURL':
u'http://10.0.1.10:9696', u'publicURL': u'http://192.168.1.10:9696'}], u'type':
u'network', u'name': u'neutron'}], 'tenant':
u'76e23046831943bba571f0e3ea432182', 'read_only': False, 'project_id':
u'76e23046831943bba571f0e3ea432182', 'user_id':
u'5ca52b5e65df4d879dd490afa350a3f0', 'show_deleted': False, 'system_scope':
None, 'user_identity': u'5ca52b5e65df4d879dd490afa350a3f0
76e23046831943bba571f0e3ea432182 - default default', 'is_admin_project': True,
'project': u'76e23046831943bba571f0e3ea432182', 'read_deleted': u'no',
'request_id': u'req-cc913d2d-d257-40fd-8aa3-7e12a6c02288', 'roles': [u'admin',
u'reader', u'heat_stack_owner', u'member'], 'user_domain': u'default',
'user_name': u'admin'}> obj_load_attr
/var/lib/kolla/venv/lib/python2.7/site-packages/nova/objects/instance.py:1111
2021-08-23 18:36:25.844 7 DEBUG nova.virt.libvirt.driver
[req-f3aa8a61-ca57-457e-a813-de5d226b2ff7 - - - - -] [instance:
18e4e517-7556-40be-8833-35290127c2e7] Starting monitoring of live migration
_live_migration
/var/lib/kolla/venv/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:8049
2021-08-23 18:36:25.846 7 DEBUG nova.objects.instance
[req-f3aa8a61-ca57-457e-a813-de5d226b2ff7 - - - - -] Lazy-loading 'flavor' on
Instance uuid 18e4e517-7556-40be-8833-35290127c2e7 context <Context {'domain':
None, 'project_name': u'admin', 'global_request_id': None, 'project_domain':
u'default', 'timestamp': '2021-08-23T10:32:53.582673', 'auth_token':
u'gAAAAABhI3lQbJgenzhpGw9daG5k1aUs3evWyZCQvujjhTZ0GZb2WIz_Eor4rlz9hPY-QxCBgH1z8nU2iTSMwPeJ5dEnEgPxmxrFq45XGXF9nLcrwCSUQfetie8k84OtEQYnhNVIE4uuPBJzRUNp9-rL6cRD8yhwXob9eSKsaZdtmTXxSBuOtJ8',
'remote_address': u'192.168.1.11', 'quota_class': None, 'resource_uuid': None,
'is_admin': True, 'user': u'5ca52b5e65df4d879dd490afa350a3f0',
'service_catalog': [{u'endpoints': [{u'adminURL': u'http://10.0.1.10:9292',
u'region': u'RegionOne', u'internalURL': u'http://10.0.1.10:9292',
u'publicURL': u'http://192.168.1.10:9292'}], u'type': u'image', u'name':
u'glance'}, {u'endpoints': [{u'adminURL': u'http://10.0.1.10:8780', u'region':
u'RegionOne', u'internalURL': u'http://10.0.1.10:8780', u'publicURL':
u'http://192.168.1.10:8780'}], u'type': u'placement', u'name': u'placement'},
{u'endpoints': [{u'adminURL':
u'http://10.0.1.10:8776/v3/76e23046831943bba571f0e3ea432182', u'region':
u'RegionOne', u'internalURL':
u'http://10.0.1.10:8776/v3/76e23046831943bba571f0e3ea432182', u'publicURL':
u'http://192.168.1.10:8776/v3/76e23046831943bba571f0e3ea432182'}], u'type':
u'volumev3', u'name': u'cinderv3'}, {u'endpoints': [{u'adminURL':
u'http://10.0.1.10:9696', u'region': u'RegionOne', u'internalURL':
u'http://10.0.1.10:9696', u'publicURL': u'http://192.168.1.10:9696'}], u'type':
u'network', u'name': u'neutron'}], 'tenant':
u'76e23046831943bba571f0e3ea432182', 'read_only': False, 'project_id':
u'76e23046831943bba571f0e3ea432182', 'user_id':
u'5ca52b5e65df4d879dd490afa350a3f0', 'show_deleted': False, 'system_scope':
None, 'user_identity': u'5ca52b5e65df4d879dd490afa350a3f0
76e23046831943bba571f0e3ea432182 - default default', 'is_admin_project': True,
'project': u'76e23046831943bba571f0e3ea432182', 'read_deleted': 'yes',
'request_id': u'req-cc913d2d-d257-40fd-8aa3-7e12a6c02288', 'roles': [u'admin',
u'reader', u'heat_stack_owner', u'member'], 'user_domain': u'default',
'user_name': u'admin'}> obj_load_attr
/var/lib/kolla/venv/lib/python2.7/site-packages/nova/objects/instance.py:1111
2021-08-23 18:36:25.937 7 DEBUG nova.compute.manager
[req-46572de8-769e-427d-b9c4-376a0e5c511a 35dd74911b384d3cb58dbec2e1afbdcd
c4076a45bcac411bacf20eb4fecb50e0 - default default] [instance:
18e4e517-7556-40be-8833-35290127c2e7] Received event
network-changed-c4615cdf-7ae0-4566-9402-c08b9544f04a external_instance_event
/var/lib/kolla/venv/lib/python2.7/site-packages/nova/compute/manager.py:8683
2021-08-23 18:36:25.938 7 DEBUG nova.compute.manager
[req-46572de8-769e-427d-b9c4-376a0e5c511a 35dd74911b384d3cb58dbec2e1afbdcd
c4076a45bcac411bacf20eb4fecb50e0 - default default] [instance:
18e4e517-7556-40be-8833-35290127c2e7] Refreshing instance network info cache
due to event network-changed-c4615cdf-7ae0-4566-9402-c08b9544f04a.
external_instance_event
/var/lib/kolla/venv/lib/python2.7/site-packages/nova/compute/manager.py:8687
2021-08-23 18:36:25.939 7 DEBUG oslo_concurrency.lockutils
[req-46572de8-769e-427d-b9c4-376a0e5c511a 35dd74911b384d3cb58dbec2e1afbdcd
c4076a45bcac411bacf20eb4fecb50e0 - default default] Acquired lock
"refresh_cache-18e4e517-7556-40be-8833-35290127c2e7" lock
/var/lib/kolla/venv/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:265
2021-08-23 18:36:25.940 7 DEBUG nova.network.neutronv2.api
[req-46572de8-769e-427d-b9c4-376a0e5c511a 35dd74911b384d3cb58dbec2e1afbdcd
c4076a45bcac411bacf20eb4fecb50e0 - default default] [instance:
18e4e517-7556-40be-8833-35290127c2e7] _get_instance_nw_info()
_get_instance_nw_info
/var/lib/kolla/venv/lib/python2.7/site-packages/nova/network/neutronv2/api.py:1846
===========
** Affects: nova
Importance: Undecided
Status: New
--
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1941851
Title:
InstanceList.get_by_host_and_node() is time-consuming because of the
value of context[‘read_deleted’] being ’yes’
Status in OpenStack Compute (nova):
New
Bug description:
Description
===========
nova.virt.libvirt./driver.py:LibvirtDriver._live_migration() spawn a thread
to execute _live_migration_operation(called after threadA).Original thread
execute _live_migration_monitor (called after threadB).
Assignment statement inst_type=instance.flavor call
nova/objects/instance.py:obj_load_attr in function _live_migration_operation.
Function _live_migration_monitor call func _live_migration_data_gb。Assignment
statement ram_gb = instance.flavor.memory_mb * units.Mi / units.Gi also call
nova/objects/instance.py:obj_load_attr.
Function temporary_mutation is called by obj_load_attr. The mistack caused by
the temporary_mutation is called by two threads simultaneously。
Time0: self._context[‘read_deleted’] is ‘no’
Time1: ThreadA called temporary_mutation, self._context[‘read_deleted’] is
assigned a value of ‘yes’. Old value is ‘no’.
Time2: ThreadB called temporary_mutation, self._context[‘read_deleted’] is
assigned a value of ‘yes’. Old value is ‘yes’.
Time3: ThreadA executing finally code of temporary_mutation, the value of
self._context[‘read_deleted’] is restored to ‘no’.
Time3: ThreadA executing finally code of temporary_mutation, the value of
self._context[‘read_deleted’] is restored to ‘yes’.
Result : Two calls to temporary_mutation cause the value of
self._context[‘read_deleted’] to change from ‘no’ to ‘yes’. When Source host
calling update_available_resource(ctxt) in _post_live_migration, calling of
objects.InstanceList.get_by_host_and_node() will read deleted instances, which
is time-consuming.
===========
Add the log
===========
Print self._context in obj_load_attr()
def obj_load_attr(self, attrname):
# NOTE(danms): We can't lazy-load anything without a context and a uuid
if not self._context:
raise exception.OrphanedObjectError(method='obj_load_attr',
objtype=self.obj_name())
if 'uuid' not in self:
raise exception.ObjectActionError(
action='obj_load_attr',
reason=_('attribute %s not lazy-loadable') % attrname)
- LOG.debug("Lazy-loading '%(attr)s' on %(name)s uuid %(uuid)s",
+ LOG.debug("Lazy-loading '%(attr)s' on %(name)s uuid %(uuid)s context
%(context)s",
{'attr': attrname,
'name': self.obj_name(),
'uuid': self.uuid,
+ 'context': self._context,
})
===========
Logs
===========
2021-08-23 18:36:25.838 7 DEBUG nova.objects.instance
[req-f3aa8a61-ca57-457e-a813-de5d226b2ff7 - - - - -] Lazy-loading 'flavor' on
Instance uuid 18e4e517-7556-40be-8833-35290127c2e7 context <Context {'domain':
None, 'project_name': u'admin', 'global_request_id': None, 'project_domain':
u'default', 'timestamp': '2021-08-23T10:32:53.582673', 'auth_token':
u'gAAAAABhI3lQbJgenzhpGw9daG5k1aUs3evWyZCQvujjhTZ0GZb2WIz_Eor4rlz9hPY-QxCBgH1z8nU2iTSMwPeJ5dEnEgPxmxrFq45XGXF9nLcrwCSUQfetie8k84OtEQYnhNVIE4uuPBJzRUNp9-rL6cRD8yhwXob9eSKsaZdtmTXxSBuOtJ8',
'remote_address': u'192.168.1.11', 'quota_class': None, 'resource_uuid': None,
'is_admin': True, 'user': u'5ca52b5e65df4d879dd490afa350a3f0',
'service_catalog': [{u'endpoints': [{u'adminURL': u'http://10.0.1.10:9292',
u'region': u'RegionOne', u'internalURL': u'http://10.0.1.10:9292',
u'publicURL': u'http://192.168.1.10:9292'}], u'type': u'image', u'name':
u'glance'}, {u'endpoints': [{u'adminURL': u'http://10.0.1.10:8780', u'region':
u'RegionOne', u'internalURL': u'http://10.0.1.10:8780', u'publicURL':
u'http://192.168.1.10:8780'}], u'type': u'placement', u'name': u'placement'},
{u'endpoints': [{u'adminURL':
u'http://10.0.1.10:8776/v3/76e23046831943bba571f0e3ea432182', u'region':
u'RegionOne', u'internalURL':
u'http://10.0.1.10:8776/v3/76e23046831943bba571f0e3ea432182', u'publicURL':
u'http://192.168.1.10:8776/v3/76e23046831943bba571f0e3ea432182'}], u'type':
u'volumev3', u'name': u'cinderv3'}, {u'endpoints': [{u'adminURL':
u'http://10.0.1.10:9696', u'region': u'RegionOne', u'internalURL':
u'http://10.0.1.10:9696', u'publicURL': u'http://192.168.1.10:9696'}], u'type':
u'network', u'name': u'neutron'}], 'tenant':
u'76e23046831943bba571f0e3ea432182', 'read_only': False, 'project_id':
u'76e23046831943bba571f0e3ea432182', 'user_id':
u'5ca52b5e65df4d879dd490afa350a3f0', 'show_deleted': False, 'system_scope':
None, 'user_identity': u'5ca52b5e65df4d879dd490afa350a3f0
76e23046831943bba571f0e3ea432182 - default default', 'is_admin_project': True,
'project': u'76e23046831943bba571f0e3ea432182', 'read_deleted': u'no',
'request_id': u'req-cc913d2d-d257-40fd-8aa3-7e12a6c02288', 'roles': [u'admin',
u'reader', u'heat_stack_owner', u'member'], 'user_domain': u'default',
'user_name': u'admin'}> obj_load_attr
/var/lib/kolla/venv/lib/python2.7/site-packages/nova/objects/instance.py:1111
2021-08-23 18:36:25.844 7 DEBUG nova.virt.libvirt.driver
[req-f3aa8a61-ca57-457e-a813-de5d226b2ff7 - - - - -] [instance:
18e4e517-7556-40be-8833-35290127c2e7] Starting monitoring of live migration
_live_migration
/var/lib/kolla/venv/lib/python2.7/site-packages/nova/virt/libvirt/driver.py:8049
2021-08-23 18:36:25.846 7 DEBUG nova.objects.instance
[req-f3aa8a61-ca57-457e-a813-de5d226b2ff7 - - - - -] Lazy-loading 'flavor' on
Instance uuid 18e4e517-7556-40be-8833-35290127c2e7 context <Context {'domain':
None, 'project_name': u'admin', 'global_request_id': None, 'project_domain':
u'default', 'timestamp': '2021-08-23T10:32:53.582673', 'auth_token':
u'gAAAAABhI3lQbJgenzhpGw9daG5k1aUs3evWyZCQvujjhTZ0GZb2WIz_Eor4rlz9hPY-QxCBgH1z8nU2iTSMwPeJ5dEnEgPxmxrFq45XGXF9nLcrwCSUQfetie8k84OtEQYnhNVIE4uuPBJzRUNp9-rL6cRD8yhwXob9eSKsaZdtmTXxSBuOtJ8',
'remote_address': u'192.168.1.11', 'quota_class': None, 'resource_uuid': None,
'is_admin': True, 'user': u'5ca52b5e65df4d879dd490afa350a3f0',
'service_catalog': [{u'endpoints': [{u'adminURL': u'http://10.0.1.10:9292',
u'region': u'RegionOne', u'internalURL': u'http://10.0.1.10:9292',
u'publicURL': u'http://192.168.1.10:9292'}], u'type': u'image', u'name':
u'glance'}, {u'endpoints': [{u'adminURL': u'http://10.0.1.10:8780', u'region':
u'RegionOne', u'internalURL': u'http://10.0.1.10:8780', u'publicURL':
u'http://192.168.1.10:8780'}], u'type': u'placement', u'name': u'placement'},
{u'endpoints': [{u'adminURL':
u'http://10.0.1.10:8776/v3/76e23046831943bba571f0e3ea432182', u'region':
u'RegionOne', u'internalURL':
u'http://10.0.1.10:8776/v3/76e23046831943bba571f0e3ea432182', u'publicURL':
u'http://192.168.1.10:8776/v3/76e23046831943bba571f0e3ea432182'}], u'type':
u'volumev3', u'name': u'cinderv3'}, {u'endpoints': [{u'adminURL':
u'http://10.0.1.10:9696', u'region': u'RegionOne', u'internalURL':
u'http://10.0.1.10:9696', u'publicURL': u'http://192.168.1.10:9696'}], u'type':
u'network', u'name': u'neutron'}], 'tenant':
u'76e23046831943bba571f0e3ea432182', 'read_only': False, 'project_id':
u'76e23046831943bba571f0e3ea432182', 'user_id':
u'5ca52b5e65df4d879dd490afa350a3f0', 'show_deleted': False, 'system_scope':
None, 'user_identity': u'5ca52b5e65df4d879dd490afa350a3f0
76e23046831943bba571f0e3ea432182 - default default', 'is_admin_project': True,
'project': u'76e23046831943bba571f0e3ea432182', 'read_deleted': 'yes',
'request_id': u'req-cc913d2d-d257-40fd-8aa3-7e12a6c02288', 'roles': [u'admin',
u'reader', u'heat_stack_owner', u'member'], 'user_domain': u'default',
'user_name': u'admin'}> obj_load_attr
/var/lib/kolla/venv/lib/python2.7/site-packages/nova/objects/instance.py:1111
2021-08-23 18:36:25.937 7 DEBUG nova.compute.manager
[req-46572de8-769e-427d-b9c4-376a0e5c511a 35dd74911b384d3cb58dbec2e1afbdcd
c4076a45bcac411bacf20eb4fecb50e0 - default default] [instance:
18e4e517-7556-40be-8833-35290127c2e7] Received event
network-changed-c4615cdf-7ae0-4566-9402-c08b9544f04a external_instance_event
/var/lib/kolla/venv/lib/python2.7/site-packages/nova/compute/manager.py:8683
2021-08-23 18:36:25.938 7 DEBUG nova.compute.manager
[req-46572de8-769e-427d-b9c4-376a0e5c511a 35dd74911b384d3cb58dbec2e1afbdcd
c4076a45bcac411bacf20eb4fecb50e0 - default default] [instance:
18e4e517-7556-40be-8833-35290127c2e7] Refreshing instance network info cache
due to event network-changed-c4615cdf-7ae0-4566-9402-c08b9544f04a.
external_instance_event
/var/lib/kolla/venv/lib/python2.7/site-packages/nova/compute/manager.py:8687
2021-08-23 18:36:25.939 7 DEBUG oslo_concurrency.lockutils
[req-46572de8-769e-427d-b9c4-376a0e5c511a 35dd74911b384d3cb58dbec2e1afbdcd
c4076a45bcac411bacf20eb4fecb50e0 - default default] Acquired lock
"refresh_cache-18e4e517-7556-40be-8833-35290127c2e7" lock
/var/lib/kolla/venv/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:265
2021-08-23 18:36:25.940 7 DEBUG nova.network.neutronv2.api
[req-46572de8-769e-427d-b9c4-376a0e5c511a 35dd74911b384d3cb58dbec2e1afbdcd
c4076a45bcac411bacf20eb4fecb50e0 - default default] [instance:
18e4e517-7556-40be-8833-35290127c2e7] _get_instance_nw_info()
_get_instance_nw_info
/var/lib/kolla/venv/lib/python2.7/site-packages/nova/network/neutronv2/api.py:1846
===========
To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1941851/+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
