Fix session timing

Subclass keystoneclient.session.Session to add the timing hooks to
record the elapsed time returned by requests.Response objects, including
the redirection history.  Redirects are included individually and not
rolled into the total time for the original request.

This works for all clients that use OSC's session.

Closes-Bug: #1402577
Change-Id: I9360c90c151579b89a37edb8c11c17feb15b3cb9

openstackclient/common/clientmanager.py

@@ -19,10 +19,10 @@ import logging
 import pkg_resources
 import sys
 
-from keystoneclient import session
 import requests
 
 from openstackclient.api import auth
+from openstackclient.common import session as osc_session
 from openstackclient.identity import client as identity_client
 
 
@@ -157,7 +157,7 @@ class ClientManager(object):
         self.auth = auth_plugin.load_from_options(**self._auth_params)
         # needed by SAML authentication
         request_session = requests.session()
-        self.session = session.Session(
+        self.session = osc_session.TimingSession(
             auth=self.auth,
             session=request_session,
             verify=self._verify,

openstackclient/common/session.py

@@ -0,0 +1,50 @@
+#   Licensed under the Apache License, Version 2.0 (the "License"); you may
+#   not use this file except in compliance with the License. You may obtain
+#   a copy of the License at
+#
+#        http://www.apache.org/licenses/LICENSE-2.0
+#
+#   Unless required by applicable law or agreed to in writing, software
+#   distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+#   WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+#   License for the specific language governing permissions and limitations
+#   under the License.
+#
+
+"""Subclass of keystoneclient.session"""
+
+from keystoneclient import session
+
+
+class TimingSession(session.Session):
+    """A Session that supports collection of timing data per Method URL"""
+
+    def __init__(
+            self,
+            **kwargs
+    ):
+        """Pass through all arguments except timing"""
+        super(TimingSession, self).__init__(**kwargs)
+
+        # times is a list of tuples: ("method url", elapsed_time)
+        self.times = []
+
+    def get_timings(self):
+        return self.times
+
+    def reset_timings(self):
+        self.times = []
+
+    def request(self, url, method, **kwargs):
+        """Wrap the usual request() method with the timers"""
+        resp = super(TimingSession, self).request(url, method, **kwargs)
+        for h in resp.history:
+            self.times.append((
+                "%s %s" % (h.request.method, h.request.url),
+                h.elapsed,
+            ))
+        self.times.append((
+            "%s %s" % (resp.request.method, resp.request.url),
+            resp.elapsed,
+        ))
+        return resp

openstackclient/common/timing.py

@@ -33,10 +33,12 @@ class Timing(lister.Lister):
 
         results = []
         total = 0.0
-        for url, start, end in self.app.timing_data:
+        for url, td in self.app.timing_data:
-            seconds = end - start
+            # NOTE(dtroyer): Take the long way here because total_seconds()
-            total += seconds
+            #                was added in py27.
-            results.append((url, seconds))
+            sec = (td.microseconds + (td.seconds + td.days*86400) * 1e6) / 1e6
+            total += sec
+            results.append((url, sec))
         results.append(('Total', total))
         return (
             column_headers,

openstackclient/shell.py

@@ -316,11 +316,10 @@ class OpenStackShell(app.App):
 
         # Process collected timing data
         if self.options.timing:
-            # Loop through extensions
+            # Get session data
-            for mod in self.ext_modules:
+            self.timing_data.extend(
-                client = getattr(self.client_manager, mod.API_NAME)
+                self.client_manager.session.get_timings(),
-                if hasattr(client, 'get_timings'):
+            )
-                    self.timing_data.extend(client.get_timings())
 
             # Use the Timing pseudo-command to generate the output
             tcmd = timing.Timing(self, self.options)

openstackclient/tests/common/test_timing.py

@@ -13,14 +13,15 @@
 
 """Test Timing pseudo-command"""
 
+import datetime
+
 from openstackclient.common import timing
 from openstackclient.tests import fakes
 from openstackclient.tests import utils
 
 
 timing_url = 'GET http://localhost:5000'
-timing_start = 1404802774.872809
+timing_elapsed = 0.872809
-timing_end = 1404802775.724802
 
 
 class FakeGenericClient(object):
@@ -66,9 +67,10 @@ class TestTiming(utils.TestCommand):
         self.assertEqual(datalist, data)
 
     def test_timing_list(self):
-        self.app.timing_data = [
+        self.app.timing_data = [(
-            (timing_url, timing_start, timing_end),
+            timing_url,
-        ]
+            datetime.timedelta(microseconds=timing_elapsed*1000000),
+        )]
 
         arglist = []
         verifylist = []
@@ -79,9 +81,8 @@ class TestTiming(utils.TestCommand):
 
         collist = ('URL', 'Seconds')
         self.assertEqual(collist, columns)
-        timing_sec = timing_end - timing_start
         datalist = [
-            (timing_url, timing_sec),
+            (timing_url, timing_elapsed),
-            ('Total', timing_sec)
+            ('Total', timing_elapsed),
         ]
         self.assertEqual(datalist, data)