Standard Metrics - Incoming Requests Execution Time (#773)

* Incoming Requests Execution Time

* Fix test

* Remove blank line

* ADd line

* Update comments

* Include locks to prevent race case

* Fix lint

* address comments

Author: lzchen

contrib/opencensus-ext-azure/CHANGELOG.md

@@ -3,6 +3,8 @@
 ## Unreleased
 - Standard metrics incoming requests per second
   ([#758](https://github.com/census-instrumentation/opencensus-python/pull/758))
+- Standard metrics incoming requests average execution rate
+  ([#773](https://github.com/census-instrumentation/opencensus-python/pull/773))
 
 ## 0.7.0
 Released 2019-07-31

contrib/opencensus-ext-azure/README.rst

@@ -154,6 +154,7 @@ Below is a list of standard metrics that are currently available:
 - Available Memory (bytes)
 - CPU Processor Time (percentage)
 - Incoming Request Rate (per second)
+- Incoming Request Average Execution Time (milliseconds)
 - Outgoing Request Rate (per second)
 - Process CPU Usage (percentage)
 - Process Private Bytes (bytes)

contrib/opencensus-ext-azure/opencensus/ext/azure/metrics_exporter/standard_metrics/__init__.py

@@ -24,6 +24,8 @@
     import ProcessCPUMetric
 from opencensus.ext.azure.metrics_exporter.standard_metrics.process \
     import ProcessMemoryMetric
+from opencensus.ext.azure.metrics_exporter.standard_metrics.http_requests \
+    import RequestsAvgExecutionMetric
 from opencensus.ext.azure.metrics_exporter.standard_metrics.http_requests \
     import RequestsRateMetric
 
@@ -33,6 +35,7 @@
                     ProcessCPUMetric,
                     ProcessMemoryMetric,
                     ProcessorTimeMetric,
+                    RequestsAvgExecutionMetric,
                     RequestsRateMetric]
 
 

contrib/opencensus-ext-azure/opencensus/ext/azure/metrics_exporter/standard_metrics/http_dependency.py

@@ -13,21 +13,25 @@
 # limitations under the License.
 
 import requests
+import threading
 import time
 
 from opencensus.metrics.export.gauge import DerivedDoubleGauge
 from opencensus.trace import execution_context
 
 dependency_map = dict()
+_dependency_lock = threading.Lock()
 ORIGINAL_REQUEST = requests.Session.request
 
 
 def dependency_patch(*args, **kwargs):
     result = ORIGINAL_REQUEST(*args, **kwargs)
     # Only collect request metric if sent from non-exporter thread
     if not execution_context.is_exporter():
-        count = dependency_map.get('count', 0)
-        dependency_map['count'] = count + 1
+        # We don't want multiple threads updating this at once
+        with _dependency_lock:
+            count = dependency_map.get('count', 0)
+            dependency_map['count'] = count + 1
     return result
 
 

contrib/opencensus-ext-azure/opencensus/ext/azure/metrics_exporter/standard_metrics/http_requests.py

@@ -13,6 +13,7 @@
 # limitations under the License.
 
 import sys
+import threading
 import time
 
 from opencensus.metrics.export.gauge import DerivedDoubleGauge
@@ -21,16 +22,32 @@
 else:
     from http.server import HTTPServer
 
+_requests_lock = threading.Lock()
 requests_map = dict()
 ORIGINAL_CONSTRUCTOR = HTTPServer.__init__
 
 
 def request_patch(func):
     def wrapper(self=None):
+        start_time = time.time()
         func(self)
+        end_time = time.time()
+
+        update_request_state(start_time, end_time)
+
+    return wrapper
+
+
+def update_request_state(start_time, end_time):
+    # Update requests state information
+    # We don't want multiple threads updating this at once
+    with _requests_lock:
+        # Update Count
         count = requests_map.get('count', 0)
         requests_map['count'] = count + 1
-    return wrapper
+        # Update duration
+        duration = requests_map.get('duration', 0)
+        requests_map['duration'] = duration + (end_time - start_time)
 
 
 def server_patch(*args, **kwargs):
@@ -59,6 +76,76 @@ def setup():
     HTTPServer.__init__ = server_patch
 
 
+def get_average_execution_time():
+    last_average_duration = requests_map.get('last_average_duration', 0)
+    interval_duration = requests_map.get('duration', 0) \
+        - requests_map.get('last_duration', 0)
+    interval_count = requests_map.get('count', 0) \
+        - requests_map.get('last_count', 0)
+    try:
+        result = interval_duration / interval_count
+        requests_map['last_average_duration'] = result
+        requests_map['last_duration'] = requests_map.get('duration', 0)
+        # Convert to milliseconds
+        return result * 1000.0
+    except ZeroDivisionError:
+        # If interval_count is 0, exporter call made too close to previous
+        # Return the previous result if this is the case
+        return last_average_duration * 1000.0
+
+
+def get_requests_rate():
+    current_time = time.time()
+    last_rate = requests_map.get('last_rate', 0)
+    last_time = requests_map.get('last_time')
+
+    try:
+        # last_rate_time is None the first time this function is called
+        if last_time is not None:
+            interval_time = current_time - requests_map.get('last_time', 0)
+            interval_count = requests_map.get('count', 0) \
+                - requests_map.get('last_count', 0)
+            result = interval_count / interval_time
+        else:
+            result = 0
+        requests_map['last_time'] = current_time
+        requests_map['last_count'] = requests_map.get('count', 0)
+        requests_map['last_rate'] = result
+        return result
+    except ZeroDivisionError:
+        # If elapsed_seconds is 0, exporter call made too close to previous
+        # Return the previous result if this is the case
+        return last_rate
+
+
+class RequestsAvgExecutionMetric(object):
+    NAME = "\\ASP.NET Applications(??APP_W3SVC_PROC??)\\Request Execution Time"
+
+    def __init__(self):
+        setup()
+
+    @staticmethod
+    def get_value():
+        return get_average_execution_time()
+
+    def __call__(self):
+        """ Returns a derived gauge for incoming requests execution rate
+
+        Calculated by getting the time it takes to make an incoming request
+        and dividing over the amount of incoming requests over an elapsed time.
+
+        :rtype: :class:`opencensus.metrics.export.gauge.DerivedLongGauge`
+        :return: The gauge representing the incoming requests metric
+        """
+        gauge = DerivedDoubleGauge(
+            RequestsAvgExecutionMetric.NAME,
+            'Incoming Requests Average Execution Rate',
+            'milliseconds',
+            [])
+        gauge.create_default_time_series(RequestsAvgExecutionMetric.get_value)
+        return gauge
+
+
 class RequestsRateMetric(object):
     NAME = "\\ASP.NET Applications(??APP_W3SVC_PROC??)\\Requests/Sec"
 
@@ -67,28 +154,7 @@ def __init__(self):
 
     @staticmethod
     def get_value():
-        current_count = requests_map.get('count', 0)
-        current_time = time.time()
-        last_count = requests_map.get('last_count', 0)
-        last_time = requests_map.get('last_time')
-        last_result = requests_map.get('last_result', 0)
-
-        try:
-            # last_time is None the very first time this function is called
-            if last_time is not None:
-                elapsed_seconds = current_time - last_time
-                interval_count = current_count - last_count
-                result = interval_count / elapsed_seconds
-            else:
-                result = 0
-            requests_map['last_time'] = current_time
-            requests_map['last_count'] = current_count
-            requests_map['last_result'] = result
-            return result
-        except ZeroDivisionError:
-            # If elapsed_seconds is 0, exporter call made too close to previous
-            # Return the previous result if this is the case
-            return last_result
+        return get_requests_rate()
 
     def __call__(self):
         """ Returns a derived gauge for incoming requests per second

contrib/opencensus-ext-azure/tests/test_azure_standard_metrics.py

@@ -48,12 +48,12 @@ def test_producer_get_metrics(self):
         producer = standard_metrics.AzureStandardMetricsProducer()
         metrics = producer.get_metrics()
 
-        self.assertEqual(len(metrics), 6)
+        self.assertEqual(len(metrics), 7)
 
     def test_register_metrics(self):
         registry = standard_metrics.register_metrics()
 
-        self.assertEqual(len(registry.get_metrics()), 6)
+        self.assertEqual(len(registry.get_metrics()), 7)
 
     def test_get_available_memory_metric(self):
         metric = standard_metrics.AvailableMemoryMetric()
@@ -201,6 +201,7 @@ def test_request_patch(self):
         new_func()
 
         self.assertEqual(map['count'], 1)
+        self.assertIsNotNone(map['duration'])
         self.assertEqual(len(func.call_args_list), 1)
 
     def test_server_patch(self):
@@ -267,34 +268,60 @@ def test_server_patch_no_handler(self):
 
         self.assertEqual(r, None)
 
-    def test_get_request_rate_metric(self):
+    def test_get_requests_rate_metric(self):
         metric = standard_metrics.RequestsRateMetric()
         gauge = metric()
 
         name = '\\ASP.NET Applications(??APP_W3SVC_PROC??)\\Requests/Sec'
         self.assertEqual(gauge.descriptor.name, name)
 
-    def test_get_request_rate_first_time(self):
-        rate = standard_metrics.RequestsRateMetric.get_value()
+    def test_get_requests_rate_first_time(self):
+        rate = standard_metrics.http_requests.get_requests_rate()
 
         self.assertEqual(rate, 0)
 
     @mock.patch('opencensus.ext.azure.metrics_exporter'
                 '.standard_metrics.http_requests.time')
-    def test_get_request_rate(self, time_mock):
+    def test_get_requests_rate(self, time_mock):
         time_mock.time.return_value = 100
         standard_metrics.http_requests.requests_map['last_time'] = 98
         standard_metrics.http_requests.requests_map['count'] = 4
-        rate = standard_metrics.RequestsRateMetric.get_value()
+        rate = standard_metrics.http_requests.get_requests_rate()
 
         self.assertEqual(rate, 2)
 
     @mock.patch('opencensus.ext.azure.metrics_exporter'
                 '.standard_metrics.http_requests.time')
-    def test_get_request_rate_error(self, time_mock):
+    def test_get_requests_rate_error(self, time_mock):
         time_mock.time.return_value = 100
-        standard_metrics.http_requests.requests_map['last_result'] = 5
+        standard_metrics.http_requests.requests_map['last_rate'] = 5
         standard_metrics.http_requests.requests_map['last_time'] = 100
-        result = standard_metrics.RequestsRateMetric.get_value()
+        result = standard_metrics.http_requests.get_requests_rate()
 
         self.assertEqual(result, 5)
+
+    def test_get_requests_execution_metric(self):
+        metric = standard_metrics.RequestsAvgExecutionMetric()
+        gauge = metric()
+
+        name = '\\ASP.NET Applications(??APP_W3SVC_PROC??)' \
+               '\\Request Execution Time'
+        self.assertEqual(gauge.descriptor.name, name)
+
+    def test_get_requests_execution(self):
+        map = standard_metrics.http_requests.requests_map
+        map['duration'] = 0.1
+        map['count'] = 10
+        map['last_count'] = 5
+        result = standard_metrics.http_requests.get_average_execution_time()
+
+        self.assertEqual(result, 20)
+
+    def test_get_requests_execution_error(self):
+        map = standard_metrics.http_requests.requests_map
+        map['duration'] = 0.1
+        map['count'] = 10
+        map['last_count'] = 10
+        result = standard_metrics.http_requests.get_average_execution_time()
+
+        self.assertEqual(result, 0)