From 58af5e101d30027549bda9308536e9f45ed0bfef Mon Sep 17 00:00:00 2001
From: Kevin Benton <blak111@gmail.com>
Date: Fri, 17 Apr 2015 03:53:45 -0700
Subject: [PATCH] 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)
---
 neutron/api/rpc/handlers/l3_rpc.py      |  3 ++-
 neutron/common/utils.py                 | 17 ++++++++++++++
 neutron/tests/unit/common/test_utils.py | 31 +++++++++++++++++++++++++
 3 files changed, 50 insertions(+), 1 deletion(-)

diff --git a/neutron/api/rpc/handlers/l3_rpc.py b/neutron/api/rpc/handlers/l3_rpc.py
index 9e2d47ed0..04459ec7f 100644
--- 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 2502c4d71..e1776ef3d 100644
--- 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 7a370f13b..b1f1568c0 100644
--- 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)
-- 
2.45.2