Defer creation of router JSON in get_routers RPC

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
(cherry picked from commit 649599457e29b58ad0aec9ace990e0a2b59b05d0)

diff --git a/neutron/api/rpc/handlers/l3_rpc.py b/neutron/api/rpc/handlers/l3_rpc.py
index 9e2d47ed0021d7340b639f55774ac87add13f5a8..04459ec7f6269177c80bf90fc4b12e6843aa113d 100644 (file)
--- a/neutron/api/rpc/handlers/l3_rpc.py
+++ b/neutron/api/rpc/handlers/l3_rpc.py
@@ -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):

diff --git a/neutron/common/utils.py b/neutron/common/utils.py
index 2502c4d719442da243851d9055628bd27d530001..e1776ef3dfdc144f519c1907a2610f98098653b4 100644 (file)
--- a/neutron/common/utils.py
+++ b/neutron/common/utils.py
@@ -418,3 +418,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))

diff --git a/neutron/tests/unit/common/test_utils.py b/neutron/tests/unit/common/test_utils.py
index 7a370f13bbec7f492cc8b13317a89bb8f614b61f..b1f1568c064d11e5b59fc7695488b5109dae24bc 100644 (file)
--- a/neutron/tests/unit/common/test_utils.py
+++ b/neutron/tests/unit/common/test_utils.py
@@ -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)