← Back to team overview

yahoo-eng-team team mailing list archive

  1. yahoo-eng-team team
  2. Mailing list archive
  3. Message #87009

[Bug 1941851] [NEW] InstanceList.get_by_host_and_node() is time-consuming because of the value of context[‘read_deleted’] being ’yes’

  Thread Previous • Date Previous • • Thread Next 
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
  Thread Previous • Date Previous • • Thread Next