Don't record time when self.timing is False

The expected behavior is when timing is True, then we record each
request's time, then we should call reset_timings() to release memory.

However, the shell, client.{HTTPClient,SessionClient} will record each
request's time no matter what timing is set, then after long running
time in service like ceilometer-agent-compute, the memory keeps increasing.

We'd better not record request's time when timing is set to False.
Users are not responiable to call reset_timings() when they don't want
timing functionality.

Change-Id: I3e7d2fadf9a21be018781d528a1b6562228da6dd
Closes-Bug: #1433491

novaclient/client.py

@@ -26,7 +26,6 @@ import hashlib
 import logging
 import re
 import socket
-import time
 
 from keystoneclient import adapter
 from oslo.utils import importutils
@@ -44,6 +43,7 @@ from six.moves.urllib import parse
 from novaclient import exceptions
 from novaclient.i18n import _
 from novaclient import service_catalog
+from novaclient import utils
 
 
 class TCPKeepAliveAdapter(adapters.HTTPAdapter):
@@ -76,22 +76,18 @@ class SessionClient(adapter.LegacyJsonAdapter):
 
     def __init__(self, *args, **kwargs):
         self.times = []
+        self.timings = kwargs.pop('timings', False)
         super(SessionClient, self).__init__(*args, **kwargs)
 
     def request(self, url, method, **kwargs):
         # NOTE(jamielennox): The standard call raises errors from
         # keystoneclient, where we need to raise the novaclient errors.
         raise_exc = kwargs.pop('raise_exc', True)
-        start_time = time.time()
-        resp, body = super(SessionClient, self).request(url,
-                                                        method,
-                                                        raise_exc=False,
-                                                        **kwargs)
-
-        end_time = time.time()
-        self.times.append(('%s %s' % (method, url),
-                          start_time, end_time))
-
+        with utils.record_time(self.times, self.timings, method, url):
+            resp, body = super(SessionClient, self).request(url,
+                                                            method,
+                                                            raise_exc=False,
+                                                            **kwargs)
         if raise_exc and resp.status_code >= 400:
             raise exceptions.from_response(resp, body, url, method)
 
@@ -393,10 +389,8 @@ class HTTPClient(object):
         return resp, body
 
     def _time_request(self, url, method, **kwargs):
-        start_time = time.time()
-        resp, body = self.request(url, method, **kwargs)
-        self.times.append(("%s %s" % (method, url),
-                           start_time, time.time()))
+        with utils.record_time(self.times, self.timings, method, url):
+            resp, body = self.request(url, method, **kwargs)
         return resp, body
 
     def _cs_request(self, url, method, **kwargs):
@@ -686,6 +680,7 @@ def _construct_http_client(username=None, password=None, project_id=None,
                              region_name=region_name,
                              service_name=service_name,
                              user_agent=user_agent,
+                             timings=timings,
                              **kwargs)
     else:
         # FIXME(jamielennox): username and password are now optional. Need

novaclient/shell.py

@@ -28,7 +28,6 @@ import logging
 import os
 import pkgutil
 import sys
-import time
 
 from keystoneclient.auth.identity.generic import password
 from keystoneclient.auth.identity.generic import token
@@ -717,25 +716,23 @@ class OpenStackComputeShell(object):
             project_name = args.os_project_name or args.os_tenant_name
             if use_session:
                 # Not using Nova auth plugin, so use keystone
-                start_time = time.time()
-                keystone_session = ksession.Session.load_from_cli_options(args)
-                keystone_auth = self._get_keystone_auth(
-                    keystone_session,
-                    args.os_auth_url,
-                    username=args.os_username,
-                    user_id=args.os_user_id,
-                    user_domain_id=args.os_user_domain_id,
-                    user_domain_name=args.os_user_domain_name,
-                    password=args.os_password,
-                    auth_token=args.os_auth_token,
-                    project_id=project_id,
-                    project_name=project_name,
-                    project_domain_id=args.os_project_domain_id,
-                    project_domain_name=args.os_project_domain_name)
-                end_time = time.time()
-                self.times.append(
-                    ('%s %s' % ('auth_url', args.os_auth_url),
-                     start_time, end_time))
+                with utils.record_time(self.times, args.timings,
+                                       'auth_url', args.os_auth_url):
+                    keystone_session = (ksession.Session
+                                        .load_from_cli_options(args))
+                    keystone_auth = self._get_keystone_auth(
+                        keystone_session,
+                        args.os_auth_url,
+                        username=args.os_username,
+                        user_id=args.os_user_id,
+                        user_domain_id=args.os_user_domain_id,
+                        user_domain_name=args.os_user_domain_name,
+                        password=args.os_password,
+                        auth_token=args.os_auth_token,
+                        project_id=project_id,
+                        project_name=project_name,
+                        project_domain_id=args.os_project_domain_id,
+                        project_domain_name=args.os_project_domain_name)
 
         if (options.os_compute_api_version and
                 options.os_compute_api_version != '1.0'):

novaclient/tests/unit/test_client.py

@@ -19,6 +19,7 @@ import logging
 import socket
 
 import fixtures
+from keystoneclient import adapter
 import mock
 import requests
 
@@ -388,3 +389,34 @@ class ClientTest(utils.TestCase):
         self.assertIn('RESP BODY: {"access": {"token": {"id":'
                       ' "{SHA1}4fc49c6a671ce889078ff6b250f7066cf6d2ada2"}}}',
                       output)
+
+    @mock.patch.object(novaclient.client.HTTPClient, 'request')
+    def test_timings(self, m_request):
+        m_request.return_value = (None, None)
+
+        client = novaclient.client.HTTPClient(user='zqfan', password='')
+        client._time_request("http://no.where", 'GET')
+        self.assertEqual(0, len(client.times))
+
+        client = novaclient.client.HTTPClient(user='zqfan', password='',
+                                              timings=True)
+        client._time_request("http://no.where", 'GET')
+        self.assertEqual(1, len(client.times))
+        self.assertEqual('GET http://no.where', client.times[0][0])
+
+
+class SessionClientTest(utils.TestCase):
+
+    @mock.patch.object(adapter.LegacyJsonAdapter, 'request')
+    def test_timings(self, m_request):
+        m_request.return_value = (mock.MagicMock(status_code=200), None)
+
+        client = novaclient.client.SessionClient(session=mock.MagicMock())
+        client.request("http://no.where", 'GET')
+        self.assertEqual(0, len(client.times))
+
+        client = novaclient.client.SessionClient(session=mock.MagicMock(),
+                                                 timings=True)
+        client.request("http://no.where", 'GET')
+        self.assertEqual(1, len(client.times))
+        self.assertEqual('GET http://no.where', client.times[0][0])

novaclient/tests/unit/test_shell.py

@@ -373,6 +373,16 @@ class ShellTest(utils.TestCase):
         except SystemExit as ex:
             self.assertEqual(ex.code, 130)
 
+    @mock.patch.object(novaclient.shell.OpenStackComputeShell, 'times')
+    @requests_mock.Mocker()
+    def test_timing(self, m_times, m_requests):
+        m_times.append.side_effect = RuntimeError('Boom!')
+        self.make_env()
+        self.register_keystone_discovery_fixture(m_requests)
+        self.shell('list')
+        exc = self.assertRaises(RuntimeError, self.shell, '--timings list')
+        self.assertEqual('Boom!', str(exc))
+
 
 class ShellTestKeystoneV3(ShellTest):
     def make_env(self, exclude=None, fake_env=FAKE_ENV):

novaclient/tests/unit/test_utils.py

@@ -355,3 +355,22 @@ class DoActionOnManyTestCase(test_utils.TestCase):
 
     def test_do_action_on_many_last_fails(self):
         self._test_do_action_on_many([None, Exception()], fail=True)
+
+
+class RecordTimeTestCase(test_utils.TestCase):
+
+    def test_record_time(self):
+        times = []
+
+        with utils.record_time(times, True, 'a', 'b'):
+            pass
+        self.assertEqual(1, len(times))
+        self.assertEqual(3, len(times[0]))
+        self.assertEqual('a b', times[0][0])
+        self.assertIsInstance(times[0][1], float)
+        self.assertIsInstance(times[0][2], float)
+
+        times = []
+        with utils.record_time(times, False, 'x'):
+            pass
+        self.assertEqual(0, len(times))

novaclient/utils.py

@@ -11,9 +11,11 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+import contextlib
 import json
 import re
 import textwrap
+import time
 import uuid
 
 from oslo.serialization import jsonutils
@@ -339,3 +341,23 @@ def validate_flavor_metadata_keys(keys):
                     'numbers, spaces, underscores, periods, colons and '
                     'hyphens.')
             raise exceptions.CommandError(msg % key)
+
+
+@contextlib.contextmanager
+def record_time(times, enabled, *args):
+    """Record the time of a specific action.
+
+    :param times: A list of tuples holds time data.
+    :type times: list
+    :param enabled: Whether timing is enabled.
+    :type enabled: bool
+    :param *args: Other data to be stored besides time data, these args
+                  will be joined to a string.
+    """
+    if not enabled:
+        yield
+    else:
+        start = time.time()
+        yield
+        end = time.time()
+        times.append((' '.join(args), start, end))