add request timing
Time every request that we make from the base rest client so we
can see the API call time as part of normal tempest runs. This is
much more useful than this being done inside the servers, as this
will account for the entire call time from the outside.
Change-Id: I9c367a8fd05ae7996e5491a525d92c75d0275b2b
diff --git a/tempest/common/rest_client.py b/tempest/common/rest_client.py
index 4cc7338..934b861 100644
--- a/tempest/common/rest_client.py
+++ b/tempest/common/rest_client.py
@@ -281,14 +281,22 @@
return resp[i]
return ""
- def _log_request(self, method, req_url, resp):
+ def _log_request(self, method, req_url, resp, secs=""):
+ # if we have the request id, put it in the right part of the log
extra = dict(request_id=self._get_request_id(resp))
+ # NOTE(sdague): while we still have 6 callers to this function
+ # we're going to just provide work around on who is actually
+ # providing timings by gracefully adding no content if they don't.
+ # Once we're down to 1 caller, clean this up.
+ if secs:
+ secs = " %.3fs" % secs
self.LOG.info(
- 'Request (%s): %s %s %s' % (
+ 'Request (%s): %s %s %s%s' % (
self._find_caller(),
resp['status'],
method,
- req_url),
+ req_url,
+ secs),
extra=extra)
def _parse_resp(self, body):
@@ -369,10 +377,12 @@
req_url, req_headers, req_body = self.auth_provider.auth_request(
method, url, headers, body, self.filters)
- # Do the actual request
+ # Do the actual request, and time it
+ start = time.time()
resp, resp_body = self.http_obj.request(
req_url, method, headers=req_headers, body=req_body)
- self._log_request(method, req_url, resp)
+ end = time.time()
+ self._log_request(method, req_url, resp, secs=(end - start))
# Verify HTTP response codes
self.response_checker(method, url, req_headers, req_body, resp,
resp_body)