[feature] Log execution time of monitoring checks #658

Closes #658

---------

Co-authored-by: Federico Capoano <f.capoano@openwisp.io>

Author: pandafy

openwisp_monitoring/check/base/models.py

@@ -102,7 +102,7 @@ def perform_check(self, store=True):
             and self.content_object.organization.is_active is False
         ):
             return
-        return self.check_instance.check(store=True)
+        return self.check_instance.timed_check(store=True)
 
     def perform_check_delayed(self, duration=0):
         from ..tasks import perform_check

openwisp_monitoring/check/classes/base.py

@@ -1,7 +1,12 @@
+import logging
+import time
+
 from django.contrib.contenttypes.models import ContentType
 from django.core.exceptions import ValidationError
 from swapper import load_model
 
+logger = logging.getLogger(__name__)
+
 Check = load_model('check', 'Check')
 Metric = load_model('monitoring', 'Metric')
 Device = load_model('config', 'Device')
@@ -55,6 +60,57 @@ def may_execute(cls):
     def check(self, store=True):
         raise NotImplementedError
 
+    def store(self, *args, **kwargs):
+        raise NotImplementedError
+
+    def timed_check(self, store=True):
+        """
+        Executes the check method and measures its execution time.
+
+        Optionally stores the result and logs the time taken for the check execution
+        and the time spent storing the result in the database(if available).
+
+        Args:
+            store (bool, optional): Whether to store the result of the check. Defaults to True.
+
+        Returns:
+            The result of the check method.
+
+        Logs:
+            The time taken to execute the check and store the result.
+        """
+        start_time = time.time()
+        result = self.check(store=store)
+        elapsed_time = time.time() - start_time
+        if hasattr(self, '_store_result_elapsed_time'):
+            elapsed_time -= self._store_result_elapsed_time
+        logger.info(
+            'Check "%s" executed in %.2fs, writing took %.2fs'
+            % (
+                self.check_instance,
+                elapsed_time,
+                getattr(self, '_store_result_elapsed_time', 0.0),
+            ),
+        )
+        return result
+
+    def timed_store(self, *args, **kwargs):
+        """
+        Calls the `store` method with the provided arguments and measures the time taken to execute it.
+
+        The elapsed time (in seconds) is stored in the `timed_store` attribute of the instance.
+
+        Args:
+            *args: Variable length argument list to pass to the `store` method.
+            **kwargs: Arbitrary keyword arguments to pass to the `store` method.
+
+        Side Effects:
+            Sets the `timed_store` attribute to the duration (in seconds) of the `store` method execution.
+        """
+        start_time = time.time()
+        self.store(*args, **kwargs)
+        self._store_result_elapsed_time = time.time() - start_time
+
     def _get_or_create_metric(self, configuration=None):
         """Gets or creates metric."""
         check = self.check_instance

openwisp_monitoring/check/classes/config_applied.py

@@ -33,11 +33,14 @@ def check(self, store=True):
         # but we need to ensure health status will be changed
         send_alert = self.related_object.config.status != 'error'
         if store:
-            self._get_metric().write(
-                result, retention_policy=SHORT_RP, send_alert=send_alert
-            )
+            self.timed_store(result, send_alert)
         return result
 
+    def store(self, result, send_alert, **kwargs):
+        self._get_metric().write(
+            result, retention_policy=SHORT_RP, send_alert=send_alert
+        )
+
     def _get_metric(self):
         metric, created = self._get_or_create_metric(configuration='config_applied')
         if created:

openwisp_monitoring/check/classes/data_collected.py

@@ -47,11 +47,14 @@ def check(self, store=True):
             result = 0
         send_alert = device_monitoring.status != 'critical'
         if store:
-            self._get_metric().write(
-                result, retention_policy=SHORT_RP, send_alert=send_alert
-            )
+            self.timed_store(result, send_alert)
         return {'data_collected': result}
 
+    def store(self, result, send_alert, *args, **kwargs):
+        self._get_metric().write(
+            result, retention_policy=SHORT_RP, send_alert=send_alert
+        )
+
     def _get_metric(self):
         metric, created = self._get_or_create_metric(configuration='data_collected')
         if created:

openwisp_monitoring/check/classes/iperf3.py

@@ -279,7 +279,7 @@ def _run_iperf3_check(self, store, server, time):
             # Store iperf3_result field 1 if any mode passes, store 0 when both fails
             iperf3_result = result_tcp['iperf3_result'] | result_udp['iperf3_result']
             result.update({**result_tcp, **result_udp, 'iperf3_result': iperf3_result})
-            self.store_result(result)
+            self.timed_store(result)
         device_connection.disconnect()
         return result
 
@@ -489,7 +489,7 @@ def _get_iperf3_result(self, result, exit_code, mode):
                     'lost_percent': float(result['end']['sum']['lost_percent']),
                 }
 
-    def store_result(self, result):
+    def store(self, result, *args, **kwargs):
         """Store result in the DB."""
         metric = self._get_metric()
         copied = result.copy()

openwisp_monitoring/check/classes/ping.py

@@ -83,7 +83,7 @@ def check(self, store=True):
             # device is known, simulate down
             result = {'reachable': 0, 'loss': 100.0}
             if store:
-                self.store_result(result)
+                self.timed_store(result)
             return result
         command = [
             'fping',
@@ -116,10 +116,10 @@ def check(self, store=True):
                 {'rtt_min': float(min), 'rtt_avg': float(avg), 'rtt_max': float(max)}
             )
         if store:
-            self.store_result(result)
+            self.timed_store(result)
         return result
 
-    def store_result(self, result):
+    def store(self, result):
         """Stores result in the DB."""
         metric = self._get_metric()
         copied = result.copy()

openwisp_monitoring/check/tasks.py

@@ -1,5 +1,6 @@
 import json
 import logging
+import time
 
 from celery import shared_task
 from django.conf import settings
@@ -65,6 +66,8 @@ def perform_check(uuid):
     Retrieves check according to the passed UUID and calls the
     ``perform_check()`` method.
     """
+    start_time = time.time()
+
     try:
         check = get_check_model().objects.get(pk=uuid)
     except ObjectDoesNotExist:
@@ -74,6 +77,9 @@ def perform_check(uuid):
     if settings.DEBUG:  # pragma: nocover
         print(json.dumps(result, indent=4, sort_keys=True))
 
+    elapsed_time = time.time() - start_time
+    logger.info(f'Check "{check}" took {elapsed_time:.2f}s to complete.')
+
 
 @shared_task(base=OpenwispCeleryTask)
 def auto_create_check(

openwisp_monitoring/check/tests/test_ping.py

@@ -251,18 +251,27 @@ def test_schema_violation(self):
                 self.fail('ValidationError not raised')
 
     @patch.object(Ping, '_command', return_value=_FPING_REACHABLE)
-    def test_store_result(self, mocked_method):
+    @patch('openwisp_monitoring.check.classes.base.logger.info')
+    def test_store_result(self, mocked_logger, mocked_method):
         self.assertEqual(Check.objects.count(), 0)
         device = self._create_device(organization=self._create_org())
         device.management_ip = '10.40.0.1'
         device.save()
         # check created automatically by autoping
         self.assertEqual(Check.objects.count(), 4)
-        self.assertEqual(Metric.objects.count(), 0)
-        self.assertEqual(Chart.objects.count(), 0)
+        # self.assertEqual(Metric.objects.count(), 0)
+        # self.assertEqual(Chart.objects.count(), 0)
         self.assertEqual(AlertSettings.objects.count(), 0)
         check = Check.objects.filter(check_type=self._PING).first()
         result = check.perform_check()
+        self.assertIn(
+            f'Check "{check}" executed in',
+            mocked_logger.call_args_list[0][0][0],
+        )
+        self.assertIn(
+            'writing took ',
+            mocked_logger.call_args_list[0][0][0],
+        )
         self.assertEqual(Metric.objects.count(), 1)
         self.assertEqual(Chart.objects.count(), 3)
         self.assertEqual(AlertSettings.objects.count(), 1)