From 20187e4ad04f52d7576dd918a6ee5a98447d235e Mon Sep 17 00:00:00 2001 From: "Wladimir J. van der Laan" Date: Mon, 17 Apr 2017 10:50:00 +0200 Subject: [PATCH] test: Add elapsed time to RPC tracing Add elapsed time to output of `--tracerpc`. To find out why tests are slow. --- test/functional/test_framework/authproxy.py | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/test/functional/test_framework/authproxy.py b/test/functional/test_framework/authproxy.py index 9ab3094b0..dfcc52431 100644 --- a/test/functional/test_framework/authproxy.py +++ b/test/functional/test_framework/authproxy.py @@ -42,6 +42,7 @@ import decimal import json import logging import socket +import time try: import urllib.parse as urlparse except ImportError: @@ -163,6 +164,7 @@ class AuthServiceProxy(object): return self._request('POST', self.__url.path, postdata.encode('utf-8')) def _get_response(self): + req_start_time = time.time() try: http_response = self.__conn.getresponse() except socket.timeout as e: @@ -183,8 +185,9 @@ class AuthServiceProxy(object): responsedata = http_response.read().decode('utf8') response = json.loads(responsedata, parse_float=decimal.Decimal) + elapsed = time.time() - req_start_time if "error" in response and response["error"] is None: - log.debug("<-%s- %s"%(response["id"], json.dumps(response["result"], default=EncodeDecimal, ensure_ascii=self.ensure_ascii))) + log.debug("<-%s- [%.6f] %s"%(response["id"], elapsed, json.dumps(response["result"], default=EncodeDecimal, ensure_ascii=self.ensure_ascii))) else: - log.debug("<-- "+responsedata) + log.debug("<-- [%.6f] %s"%(elapsed,responsedata)) return response