]> review.fuel-infra Code Review - openstack-build/neutron-build.git/commitdiff
Defer creation of router JSON in get_routers RPC
authorKevin Benton <blak111@gmail.com>
Fri, 17 Apr 2015 10:53:45 +0000 (03:53 -0700)
committerKevin Benton <blak111@gmail.com>
Tue, 21 Apr 2015 03:42:13 +0000 (20:42 -0700)
The get_routers method in the l3 RPC code has a log.debug
statement that formats all of the router data as indented
JSON. This method can be expensive if there are hundreds
of routers being synced and it happens even if debugging
is disabled since the function call result is the parameter
to the debug statement.

This patch adds and leverages a small helper class that takes a
callable and its args and defers calling it until the __str__ method
is called on it when it's actually trying to be rendered to a string.

Change-Id: I2bfceb286ce30f2a3595381b62bdc6dd71ed8483
Partial-Bug: #1445412

neutron/api/rpc/handlers/l3_rpc.py
neutron/common/utils.py
neutron/tests/unit/common/test_utils.py

index 016423af7457d664d60709d0e82400b3a208667d..23ccb3205c4ad6a8d780eb39456dd3d6f459c15f 100644 (file)
@@ -85,7 +85,8 @@ class L3RpcCallback(object):
             self.plugin, constants.PORT_BINDING_EXT_ALIAS):
             self._ensure_host_set_on_ports(context, host, routers)
         LOG.debug("Routers returned to l3 agent:\n %s",
-                  jsonutils.dumps(routers, indent=5))
+                  utils.DelayedStringRenderer(jsonutils.dumps,
+                                              routers, indent=5))
         return routers
 
     def _ensure_host_set_on_ports(self, context, host, routers):
index fb4a3ddf1997a1e6c6983e5641c799b46ae5cf6d..a88e8d63408e90f037839ebdcdef5c041f64ac5f 100644 (file)
@@ -405,3 +405,20 @@ def ip_version_from_int(ip_version_int):
     if ip_version_int == 6:
         return q_const.IPv6
     raise ValueError(_('Illegal IP version number'))
+
+
+class DelayedStringRenderer(object):
+    """Takes a callable and its args and calls when __str__ is called
+
+    Useful for when an argument to a logging statement is expensive to
+    create. This will prevent the callable from being called if it's
+    never converted to a string.
+    """
+
+    def __init__(self, function, *args, **kwargs):
+        self.function = function
+        self.args = args
+        self.kwargs = kwargs
+
+    def __str__(self):
+        return str(self.function(*self.args, **self.kwargs))
index 27f6604ab30b3de70795f07d16e2c4114d8f6891..48e59b428b28a6fd90cfd430eecc4b59fc6cf688 100644 (file)
@@ -24,6 +24,8 @@ from neutron.plugins.common import constants as p_const
 from neutron.plugins.common import utils as plugin_utils
 from neutron.tests import base
 
+from oslo_log import log as logging
+
 
 class TestParseMappings(base.BaseTestCase):
     def parse(self, mapping_list, unique_values=True):
@@ -632,3 +634,32 @@ class TestIpVersionFromInt(base.BaseTestCase):
         self.assertRaises(ValueError,
                           utils.ip_version_from_int,
                           8)
+
+
+class TestDelayedStringRederer(base.BaseTestCase):
+    def test_call_deferred_until_str(self):
+        my_func = mock.MagicMock(return_value='Brie cheese!')
+        delayed = utils.DelayedStringRenderer(my_func, 1, 2, key_arg=44)
+        self.assertFalse(my_func.called)
+        string = "Type: %s" % delayed
+        my_func.assert_called_once_with(1, 2, key_arg=44)
+        self.assertEqual("Type: Brie cheese!", string)
+
+    def test_not_called_with_low_log_level(self):
+        LOG = logging.getLogger(__name__)
+        # make sure we return logging to previous level
+        current_log_level = LOG.logger.getEffectiveLevel()
+        self.addCleanup(LOG.logger.setLevel, current_log_level)
+
+        my_func = mock.MagicMock()
+        delayed = utils.DelayedStringRenderer(my_func)
+
+        # set to warning so we shouldn't be logging debug messages
+        LOG.logger.setLevel(logging.logging.WARNING)
+        LOG.debug("Hello %s", delayed)
+        self.assertFalse(my_func.called)
+
+        # but it should be called with the debug level
+        LOG.logger.setLevel(logging.logging.DEBUG)
+        LOG.debug("Hello %s", delayed)
+        self.assertTrue(my_func.called)