Merge pull request #181 from Helene/internal_perf_measures

Refine internal time performance analytics

Author: Helene

source/analytics.py

@@ -23,5 +23,12 @@
 global inspect
 inspect = False
 
+global inspect_special
+inspect_special = False
+
 global urllib3_debug
 urllib3_debug = 0
+
+# measure requests Time-To-First-Byte (TTFB)
+global requests_elapsed_time
+requests_elapsed_time = False

source/collector.py

@@ -47,7 +47,7 @@ def __init__(self, columnInfo, dps, filtersMap):
 
         self.parse_tags(filtersMap)
 
-    @cond_execution_time(enabled=analytics.inspect)
+    @cond_execution_time(enabled=analytics.inspect_special)
     def parse_tags(self, filtersMap):
         tagsDict = defaultdict(set)
         logger = getBridgeLogger()
@@ -301,6 +301,7 @@ def start_collect(self):
                 '_Collector'
             self.thread = Thread(name=thread_name, target=self.collect)
             self.thread.start()
+            self.thread.name += '_' + str(self.thread.ident)
             self.logger.trace(
                 MSG['StartCustomThread'].format(self.thread.name))
 
@@ -378,13 +379,13 @@ def _collect(self):
                 self.metrics[columnInfo.keys[0].metric] = mt
         # self.logger.info(f'rows data {str(columnValues)}')
 
-    @cond_execution_time(enabled=analytics.inspect)
+    @cond_execution_time(enabled=analytics.inspect_special)
     def prepare_static_metrics_data(self):
         incl_metrics = list(self.request.metricsaggr.keys()
                             ) if self.request.metricsaggr else None
         self.setup_static_metrics_data(incl_metrics)
 
-    @cond_execution_time(enabled=analytics.inspect)
+    @cond_execution_time(enabled=analytics.inspect_special)
     def validate_query_filters(self):
         # check filterBy settings
         if self.request.filters:
@@ -433,7 +434,7 @@ def validate_query_filters(self):
                 raise cherrypy.HTTPError(
                     400, MSG['AttrNotValid'].format('filter'))
 
-    @cond_execution_time(enabled=analytics.inspect)
+    @cond_execution_time(enabled=analytics.inspect_special)
     def validate_group_tags(self):
         # check groupBy settings
         if self.request.grouptags:

source/opentsdb.py

@@ -50,7 +50,7 @@ def qh(self):
     def TOPO(self):
         return self.__md.metaData
 
-    @cond_execution_time(enabled=analytics.inspect)
+    @cond_execution_time(enabled=analytics.inspect_special)
     def format_response(self, data: dict, jreq: dict) -> List[dict]:
         respList = []
         metrics = set(data.values())

source/prometheus.py

@@ -57,7 +57,7 @@ def qh(self):
     def TOPO(self):
         return self.__md.metaData
 
-    @cond_execution_time(enabled=analytics.inspect)
+    @cond_execution_time(enabled=analytics.inspect_special)
     def format_response(self, data) -> [str]:
         resp = []
         for name, metric in data.items():

source/queryHandler/QueryHandler.py

@@ -523,6 +523,10 @@ def __do_RESTCall(self, endpoint, requestType='GET', params=None):
             _response = _request.doRequest()
 
             if _response.status_code == 200:
+                # the r.elapsed is the Time-To-First-Byte (TTFB) while the call to requests.get()
+                # only terminates after the whole message has been received (Time-To-Last-Byte, TTLB).
+                if analytics.requests_elapsed_time:
+                    self.logger.debug(f'response elapsed time: {_response.elapsed.total_seconds()} for request: {str(params)}')
                 return _response.content.decode('utf-8', "strict")
             elif _response.status_code == 401:
                 self.logger.trace('Request headers:{}'.format(_response.request.headers))
@@ -532,7 +536,7 @@ def __do_RESTCall(self, endpoint, requestType='GET', params=None):
                 raise PerfmonConnError("{} {}".format(_response.status_code, _response.reason))
             else:
                 msg = "Perfmon RESTcall error __ Server responded: {} {}".format(_response.status_code, _response.reason)
-                self.logger.trace(msg)
+                self.logger.details(msg)
                 if _response.content:
                     contentMsg = _response.content.decode('utf-8', "strict")
                     self.logger.trace(f'Response content:{contentMsg}')