Merge "Log excessive lazy-loading behavior"

nova/objects/base.py

@@ -20,6 +20,7 @@ import functools
 import traceback
 
 import netaddr
+from oslo_log import log as logging
 import oslo_messaging as messaging
 from oslo_utils import versionutils
 from oslo_versionedobjects import base as ovoo_base
@@ -30,6 +31,9 @@ from nova.objects import fields as obj_fields
 from nova import utils
 
 
+LOG = logging.getLogger(__name__)
+
+
 def all_things_equal(obj_a, obj_b):
     if obj_b is None:
         return False
@@ -97,6 +101,34 @@ NovaObjectDictCompat = ovoo_base.VersionedObjectDictCompat
 NovaTimestampObject = ovoo_base.TimestampedObject
 
 
+def object_id(obj):
+    """Try to get a stable identifier for an object"""
+    if 'uuid' in obj:
+        ident = obj.uuid
+    elif 'id' in obj:
+        ident = obj.id
+    else:
+        ident = 'anonymous'
+    return '%s<%s>' % (obj.obj_name(), ident)
+
+
+def lazy_load_counter(fn):
+    """Increment lazy-load counter and warn if over threshold"""
+    @functools.wraps(fn)
+    def wrapper(self, attrname):
+        try:
+            return fn(self, attrname)
+        finally:
+            if self._lazy_loads is None:
+                self._lazy_loads = []
+            self._lazy_loads.append(attrname)
+            if len(self._lazy_loads) > 1:
+                LOG.debug('Object %s lazy-loaded attributes: %s',
+                          object_id(self), ','.join(self._lazy_loads))
+
+    return wrapper
+
+
 class NovaObject(ovoo_base.VersionedObject):
     """Base class and object factory.
 
@@ -110,6 +142,12 @@ class NovaObject(ovoo_base.VersionedObject):
     OBJ_SERIAL_NAMESPACE = 'nova_object'
     OBJ_PROJECT_NAMESPACE = 'nova'
 
+    # Keep a running tally of how many times we've lazy-loaded on this object
+    # so we can warn if it happens too often. This is not serialized or part
+    # of the object that goes over the wire, so it is limited to a single
+    # service, which is fine for what we need.
+    _lazy_loads = None
+
     # NOTE(ndipanov): This is nova-specific
     @staticmethod
     def should_migrate_data():

nova/objects/block_device.py

@@ -328,6 +328,7 @@ class BlockDeviceMapping(base.NovaPersistentObject, base.NovaObject,
     def get_image_mapping(self):
         return block_device.BlockDeviceDict(self).get_image_mapping()
 
+    @base.lazy_load_counter
     def obj_load_attr(self, attrname):
         if not self._context:
             raise exception.OrphanedObjectError(method='obj_load_attr',

nova/objects/flavor.py

@@ -331,6 +331,7 @@ class Flavor(base.NovaPersistentObject, base.NovaObject,
                                                    self.flavorid)
         self.obj_reset_changes(['projects'])
 
+    @base.lazy_load_counter
     def obj_load_attr(self, attrname):
         # NOTE(danms): Only projects could be lazy-loaded right now
         if attrname != 'projects':

nova/objects/host_mapping.py

@@ -64,6 +64,7 @@ class HostMapping(base.NovaTimestampObject, base.NovaObject):
     def _load_cell_mapping(self):
         self.cell_mapping = self._get_cell_mapping()
 
+    @base.lazy_load_counter
     def obj_load_attr(self, attrname):
         if attrname == 'cell_mapping':
             self._load_cell_mapping()

nova/objects/instance.py

@@ -1122,6 +1122,7 @@ class Instance(base.NovaPersistentObject, base.NovaObject,
         if numa_topology is not None:
             self.numa_topology = numa_topology.clear_host_pinning()
 
+    @base.lazy_load_counter
     def obj_load_attr(self, attrname):
         # NOTE(danms): We can't lazy-load anything without a context and a uuid
         if not self._context:

nova/objects/instance_group.py

@@ -353,6 +353,7 @@ class InstanceGroup(base.NovaPersistentObject, base.NovaObject,
     def destroy_members_bulk(cls, context, instance_uuids):
         return cls._destroy_members_bulk_in_db(context, instance_uuids)
 
+    @base.lazy_load_counter
     def obj_load_attr(self, attrname):
         # NOTE(sbauza): Only hosts could be lazy-loaded right now
         if attrname != 'hosts':

nova/objects/instance_mapping.py

@@ -60,6 +60,7 @@ class InstanceMapping(base.NovaTimestampObject, base.NovaObject):
             if 'queued_for_delete' in primitive:
                 del primitive['queued_for_delete']
 
+    @base.lazy_load_counter
     def obj_load_attr(self, attrname):
         if attrname == 'user_id':
             LOG.error('The unset user_id attribute of an unmigrated instance '

nova/objects/migration.py

@@ -129,6 +129,7 @@ class Migration(base.NovaPersistentObject, base.NovaObject):
         if target_version < (1, 8):
             primitive.pop('dest_compute_id', None)
 
+    @base.lazy_load_counter
     def obj_load_attr(self, attrname):
         if attrname == 'migration_type':
             # NOTE(danms): The only reason we'd need to load this is if

nova/objects/pci_device.py

@@ -198,6 +198,7 @@ class PciDevice(base.NovaPersistentObject, base.NovaObject):
         self.parent_device = None
         self.child_devices = []
 
+    @base.lazy_load_counter
     def obj_load_attr(self, attr):
         if attr in ['extra_info']:
             # NOTE(danms): extra_info used to be defaulted during init,

nova/objects/request_spec.py

@@ -144,6 +144,7 @@ class RequestSpec(base.NovaObject):
             if 'requested_destination' in primitive:
                 del primitive['requested_destination']
 
+    @base.lazy_load_counter
     def obj_load_attr(self, attrname):
         if attrname not in REQUEST_SPEC_OPTIONAL_ATTRS:
             raise exception.ObjectActionError(

nova/objects/service.py

@@ -388,6 +388,7 @@ class Service(base.NovaPersistentObject, base.NovaObject,
 
         return service
 
+    @base.lazy_load_counter
     def obj_load_attr(self, attrname):
         if not self._context:
             raise exception.OrphanedObjectError(method='obj_load_attr',

nova/tests/unit/objects/test_objects.py

@@ -22,6 +22,7 @@ import pprint
 from unittest import mock
 
 import fixtures
+from oslo_utils.fixture import uuidsentinel as uuids
 from oslo_utils import timeutils
 from oslo_versionedobjects import base as ovo_base
 from oslo_versionedobjects import exception as ovo_exc
@@ -66,6 +67,7 @@ class MyObj(base.NovaPersistentObject, base.NovaObject,
         self._context = context
         return self
 
+    @base.lazy_load_counter
     def obj_load_attr(self, attrname):
         setattr(self, attrname, 'loaded!')
 
@@ -789,6 +791,35 @@ class TestObject(_LocalTest, _TestObject):
         self.assertTrue(obj.deleted)
 
 
+class TestObjectMisc(_BaseTestCase):
+    @mock.patch.object(base.LOG, 'debug')
+    def test_lazy_load_counter(self, mock_log):
+        obj = MyObj()
+        mock_log.assert_not_called()
+        self.assertIsNone(obj._lazy_loads)
+
+        obj.obj_load_attr('bar')
+        mock_log.assert_not_called()
+        self.assertEqual(['bar'], obj._lazy_loads)
+
+        obj.obj_load_attr('bar')
+        mock_log.assert_called_once_with(
+            'Object %s lazy-loaded attributes: %s', 'MyObj<anonymous>',
+            'bar,bar')
+        self.assertEqual(['bar', 'bar'], obj._lazy_loads)
+
+    def test_object_id(self):
+        obj1 = MyObj()
+        self.assertEqual('MyObj<anonymous>', base.object_id(obj1))
+
+        obj2 = objects.Instance(uuid=str(uuids.instance))
+        self.assertEqual('Instance<%s>' % str(uuids.instance),
+                         base.object_id(obj2))
+
+        obj3 = objects.Service(id=123)
+        self.assertEqual('Service<123>', base.object_id(obj3))
+
+
 class TestObjectSerializer(_BaseTestCase):
     def test_serialize_entity_primitive(self):
         ser = base.NovaObjectSerializer()