Collect timing information for API calls

python-openstackclient does this in a wrapper class around Session,
and openstacksdk does something similar that could be removed if support
were directly in keystoneauth.

Add this so that we can remove the custom wrapper/manipulation in
openstackclient and openstacksdk.

Change-Id: Icf00c66f57d20d2cef724c233160d3b1e0d52102

5 files changed, 102 insertions, 2 deletions

diff --git a/keystoneauth1/loading/session.py b/keystoneauth1/loading/session.py
index 5d21f03..1e58064 100644
--- a/keystoneauth1/loading/session.py
+++ b/keystoneauth1/loading/session.py
@@ -118,12 +118,19 @@ class Session(base.BaseLoader):
             metavar='<seconds>',
             help='Set request timeout (in seconds).')
 
+        session_group.add_argument(
+            '--collect-timing',
+            default=False,
+            action='store_true',
+            help='Collect per-API call timing information.')
+
     def load_from_argparse_arguments(self, namespace, **kwargs):
         kwargs.setdefault('insecure', namespace.insecure)
         kwargs.setdefault('cacert', namespace.os_cacert)
         kwargs.setdefault('cert', namespace.os_cert)
         kwargs.setdefault('key', namespace.os_key)
         kwargs.setdefault('timeout', namespace.timeout)
+        kwargs.setdefault('collect_timing', namespace.collect_timing)
 
         return self.load_from_options(**kwargs)
 
@@ -139,6 +146,7 @@ class Session(base.BaseLoader):
             :keyfile: The key for the client certificate.
             :insecure: Whether to ignore SSL verification.
             :timeout: The max time to wait for HTTP connections.
+            :collect-timing: Whether to collect API timing information.
 
         :param dict deprecated_opts: Deprecated options that should be included
              in the definition of new options. This should be a dict from the
@@ -175,6 +183,11 @@ class Session(base.BaseLoader):
                 cfg.IntOpt('timeout',
                            deprecated_opts=deprecated_opts.get('timeout'),
                            help='Timeout value for http requests'),
+                cfg.BoolOpt('collect-timing',
+                            deprecated_opts=deprecated_opts.get(
+                                'collect-timing'),
+                            default=False,
+                            help='Collect per-API call timing information.'),
                 ]
 
     def register_conf_options(self, conf, group, deprecated_opts=None):
@@ -186,6 +199,7 @@ class Session(base.BaseLoader):
             :keyfile: The key for the client certificate.
             :insecure: Whether to ignore SSL verification.
             :timeout: The max time to wait for HTTP connections.
+            :collect-timing: Whether to collect API timing information.
 
         :param oslo_config.Cfg conf: config object to register with.
         :param string group: The ini group to register options in.
@@ -227,6 +241,7 @@ class Session(base.BaseLoader):
         kwargs.setdefault('cert', c.certfile)
         kwargs.setdefault('key', c.keyfile)
         kwargs.setdefault('timeout', c.timeout)
+        kwargs.setdefault('collect_timing', c.collect_timing)
 
         return self.load_from_options(**kwargs)
 
diff --git a/keystoneauth1/session.py b/keystoneauth1/session.py
index 6ab1e14..3d8752c 100644
--- a/keystoneauth1/session.py
+++ b/keystoneauth1/session.py
@@ -183,6 +183,24 @@ def _determine_user_agent():
     return name
 
 
+class RequestTiming(object):
+    """Contains timing information for an HTTP interaction."""
+
+    #: HTTP method used for the call (GET, POST, etc)
+    method = None
+
+    #: URL against which the call was made
+    url = None
+
+    #: Elapsed time information
+    elapsed = None  # type: datetime.timedelta
+
+    def __init__(self, method, url, elapsed):
+        self.method = method
+        self.url = url
+        self.elapsed = elapsed
+
+
 class Session(object):
     """Maintains client communication state and common functionality.
 
@@ -244,6 +262,9 @@ class Session(object):
                                  None which means automatically manage)
     :param bool split_loggers: Split the logging of requests across multiple
                                loggers instead of just one. Defaults to False.
+    :param bool collect_timing: Whether or not to collect per-method timing
+                                information for each API call. (optional,
+                                defaults to False)
     """
 
     user_agent = None
@@ -256,7 +277,8 @@ class Session(object):
                  cert=None, timeout=None, user_agent=None,
                  redirect=_DEFAULT_REDIRECT_LIMIT, additional_headers=None,
                  app_name=None, app_version=None, additional_user_agent=None,
-                 discovery_cache=None, split_loggers=None):
+                 discovery_cache=None, split_loggers=None,
+                 collect_timing=False):
 
         self.auth = auth
         self.session = _construct_session(session)
@@ -276,6 +298,8 @@ class Session(object):
         # NOTE(mordred) split_loggers kwarg default is None rather than False
         # so we can distinguish between the value being set or not.
         self._split_loggers = split_loggers
+        self._collect_timing = collect_timing
+        self._api_times = []
 
         if timeout is not None:
             self.timeout = float(timeout)
@@ -808,6 +832,19 @@ class Session(object):
                          resp.status_code)
             raise exceptions.from_response(resp, method, url)
 
+        if self._collect_timing:
+            for h in resp.history:
+                self._api_times.append(RequestTiming(
+                    method=h.request.method,
+                    url=h.request.url,
+                    elapsed=h.elapsed,
+                ))
+            self._api_times.append(RequestTiming(
+                method=resp.request.method,
+                url=resp.request.url,
+                elapsed=resp.elapsed,
+            ))
+
         return resp
 
     def _send_request(self, url, method, redirect, log, logger, split_loggers,
@@ -1172,6 +1209,18 @@ class Session(object):
         auth = self._auth_required(auth, 'get project_id')
         return auth.get_project_id(self)
 
+    def get_timings(self):
+        """Return collected API timing information.
+
+        :returns: List of `RequestTiming` objects.
+        """
+        return self._api_times
+
+    def reset_timings(self):
+        """Clear API timing information."""
+        self._api_times = []
+
+
 REQUESTS_VERSION = tuple(int(v) for v in requests.__version__.split('.'))
 
 
diff --git a/keystoneauth1/tests/unit/loading/test_session.py b/keystoneauth1/tests/unit/loading/test_session.py
index 253ec34..bc42a59 100644
--- a/keystoneauth1/tests/unit/loading/test_session.py
+++ b/keystoneauth1/tests/unit/loading/test_session.py
@@ -70,7 +70,14 @@ class ConfLoadingTests(utils.TestCase):
         def new_deprecated():
             return cfg.DeprecatedOpt(uuid.uuid4().hex, group=uuid.uuid4().hex)
 
-        opt_names = ['cafile', 'certfile', 'keyfile', 'insecure', 'timeout']
+        opt_names = [
+            'cafile',
+            'certfile',
+            'keyfile',
+            'insecure',
+            'timeout',
+            'collect-timing',
+        ]
         depr = dict([(n, [new_deprecated()]) for n in opt_names])
         opts = loading.get_session_conf_options(deprecated_opts=depr)
 
diff --git a/keystoneauth1/tests/unit/test_session.py b/keystoneauth1/tests/unit/test_session.py
index 94cc7d1..152a030 100644
--- a/keystoneauth1/tests/unit/test_session.py
+++ b/keystoneauth1/tests/unit/test_session.py
@@ -10,6 +10,7 @@
 # License for the specific language governing permissions and limitations
 # under the License.
 
+import datetime
 import itertools
 import json
 import logging
@@ -1010,6 +1011,26 @@ class SessionAuthTests(utils.TestCase):
                 key=response_key, val=response_val),
             body_output)
 
+    def test_collect_timing(self):
+        auth = AuthPlugin()
+        sess = client_session.Session(auth=auth, collect_timing=True)
+        response = {uuid.uuid4().hex: uuid.uuid4().hex}
+
+        self.stub_url('GET',
+                      json=response,
+                      headers={'Content-Type': 'application/json'})
+
+        resp = sess.get(self.TEST_URL)
+
+        self.assertEqual(response, resp.json())
+        timings = sess.get_timings()
+        self.assertEqual(timings[0].method, 'GET')
+        self.assertEqual(timings[0].url, self.TEST_URL)
+        self.assertIsInstance(timings[0].elapsed, datetime.timedelta)
+        sess.reset_timings()
+        timings = sess.get_timings()
+        self.assertEqual(len(timings), 0)
+
 
 class AdapterTest(utils.TestCase):
 
diff --git a/releasenotes/notes/collect-timing-85f007f0d86c8b26.yaml b/releasenotes/notes/collect-timing-85f007f0d86c8b26.yaml
new file mode 100644
index 0000000..0e09c9e
--- /dev/null
+++ b/releasenotes/notes/collect-timing-85f007f0d86c8b26.yaml
@@ -0,0 +1,8 @@
+---
+features:
+  - |
+    Added ``collect_timing`` option to ``keystoneauth1.session.Session``.
+    The option, which is off by default, causes the ``Session`` to collect
+    API timing information for every call it makes. Methods ``get_timings``
+    and ``reset_timings`` have been added to allow getting and clearing the
+    data.