feat: add timing for results filtering

search/api.py

@@ -1,13 +1,13 @@
 """ search business logic implementations """
 
 from datetime import datetime
-
 from django.conf import settings
 
+from eventtracking import tracker as track
 from .filter_generator import SearchFilterGenerator
 from .search_engine_base import SearchEngine
 from .result_processor import SearchResultProcessor
-from .utils import DateRange
+from .utils import DateRange, Timer
 
 # Default filters that we support, override using COURSE_DISCOVERY_FILTERS setting if desired
 DEFAULT_FILTER_FIELDS = ["org", "modes", "language"]
@@ -52,10 +52,13 @@ def perform_search(
     """
     # field_, filter_ and exclude_dictionary(s) can be overridden by calling application
     # field_dictionary includes course if course_id provided
+    filter_generation_timer = Timer()
+    filter_generation_timer.start()
     (field_dictionary, filter_dictionary, exclude_dictionary) = SearchFilterGenerator.generate_field_filters(
         user=user,
         course_id=course_id
     )
+    filter_generation_timer.stop()
 
     searcher = SearchEngine.get_search_engine(
         getattr(settings, "COURSEWARE_CONTENT_INDEX_NAME", "courseware_content")
@@ -64,6 +67,9 @@ def perform_search(
         raise NoSearchEngineError("No search engine specified in settings.SEARCH_ENGINE")
     log_search_params = getattr(settings, "SEARCH_COURSEWARE_CONTENT_LOG_PARAMS", False)
 
+    search_timer = Timer()
+    search_timer.start()
+
     results = searcher.search(
         query_string=search_term,
         field_dictionary=field_dictionary,
@@ -74,16 +80,48 @@ def perform_search(
         log_search_params=log_search_params,
     )
 
+    processing_timer = Timer()
+    processing_timer.start()
+
     # post-process the result
     for result in results["results"]:
         result["data"] = SearchResultProcessor.process_result(result["data"], search_term, user)
 
     results["access_denied_count"] = len([r for r in results["results"] if r["data"] is None])
     results["results"] = [r for r in results["results"] if r["data"] is not None]
 
+    processing_timer.stop()
+    search_timer.stop()
+
+    emit_api_timing_event(search_term, course_id, filter_generation_timer, processing_timer, search_timer)
     return results
 
 
+def emit_api_timing_event(search_term, course_id, filter_generation_timer, processing_timer, search_timer):
+    """
+    Emit the timing events for the search API
+    """
+    track.emit("edx.course.search.executed", {
+        "search_term": search_term,
+        "course_id": course_id,
+        "filter_generation_time": {
+            "start": filter_generation_timer.start_time,
+            "end": filter_generation_timer.end_time,
+            "elapsed": filter_generation_timer.elapsed_time,
+        },
+        "processing_time": {
+            "start": processing_timer.start_time_string,
+            "end": processing_timer.start_time_string,
+            "elapsed": processing_timer.elapsed_time,
+        },
+        "search_time": {
+            "start": search_timer.start_time_string,
+            "end": search_timer.start_time_string,
+            "elapsed": search_timer.elapsed_time,
+        },
+    })
+
+
 def course_discovery_search(search_term=None, size=20, from_=0, field_dictionary=None):
     """
     Course Discovery activities against the search engine index of course details

search/tests/test_api_timing_events.py

@@ -0,0 +1,107 @@
+""" Tests for timing functionality """
+
+import datetime
+from unittest.mock import patch, call
+
+from django.test import TestCase
+from django.test.utils import override_settings
+from search.tests.mock_search_engine import MockSearchEngine
+from search.utils import Timer
+from search.api import emit_api_timing_event
+
+
+@override_settings(SEARCH_ENGINE="search.tests.mock_search_engine.MockSearchEngine")
+class TimingEventsTest(TestCase):
+    """ Tests to see if timing events are emitted"""
+
+    def setUp(self):
+        super().setUp()
+        MockSearchEngine.destroy()
+        patcher = patch('search.api.track')
+        self.mock_track = patcher.start()
+        self.addCleanup(patcher.stop)
+
+    def tearDown(self):
+        MockSearchEngine.destroy()
+        super().tearDown()
+
+    def test_perform_search(self):
+        search_term = "testing search"
+        course_id = "mock.course.id"
+
+        filter_generation_timer = Timer()
+        filter_generation_timer.start()
+        filter_generation_timer.stop()
+
+        search_timer = Timer()
+        search_timer.start()
+        search_timer.stop()
+
+        processing_timer = Timer()
+        processing_timer.start()
+        processing_timer.stop()
+
+        emit_api_timing_event(search_term, course_id, filter_generation_timer, processing_timer, search_timer)
+        timing_event_call = self.mock_track.emit.mock_calls[0]
+        expected_call = call("edx.course.search.executed", {
+            "search_term": search_term,
+            "course_id": course_id,
+            "filter_generation_time": {
+                "start": filter_generation_timer.start_time,
+                "end": filter_generation_timer.end_time,
+                "elapsed": filter_generation_timer.elapsed_time,
+            },
+            "processing_time": {
+                "start": processing_timer.start_time_string,
+                "end": processing_timer.start_time_string,
+                "elapsed": processing_timer.elapsed_time,
+            },
+            "search_time": {
+                "start": search_timer.start_time_string,
+                "end": search_timer.start_time_string,
+                "elapsed": search_timer.elapsed_time,
+            },
+        })
+        self.assertEqual(timing_event_call, expected_call)
+
+
+class TimerTest(TestCase):
+    """
+    Timer Test Case
+    """
+
+    def test_start_timer(self):
+        timer = Timer()
+        timer.start()
+        timer.stop()
+        self.assertIsNotNone(timer.start_time)
+        self.assertIsNotNone(timer.end_time)
+
+    def test_elapsed_time(self):
+        # pylint: disable=protected-access
+
+        start = datetime.datetime(2024, 1, 1, 0, 0, 0, 0)
+        end = start + datetime.timedelta(seconds=5)
+
+        timer = Timer()
+        timer._start_time = start
+        timer._end_time = end
+
+        self.assertEqual(timer.elapsed_time, 5)
+        self.assertEqual(timer.start_time, start)
+        self.assertEqual(timer.end_time, end)
+
+    def test_elapsed_time_string(self):
+        # pylint: disable=protected-access
+
+        start = datetime.datetime(2024, 1, 1, 0, 0, 0, 0)
+        end = start + datetime.timedelta(seconds=5)
+
+        timer = Timer()
+        timer._start_time = start
+        timer._end_time = end
+
+        self.assertEqual(timer.elapsed_time, 5)
+        self.assertEqual(timer.start_time_string, "2024-01-01T00:00:00")
+        self.assertEqual(timer.end_time_string, "2024-01-01T00:00:05")
+        self.assertGreaterEqual(timer.end_time, timer.start_time)

search/utils.py

@@ -1,6 +1,7 @@
 """ Utility classes to support others """
 
 import importlib
+import datetime
 from collections.abc import Iterable
 
 
@@ -65,3 +66,44 @@ def upper_string(self):
     def lower_string(self):
         """ use isoformat for _lower date's string format """
         return self._lower.isoformat()
+
+
+class Timer:
+
+    """ Simple timer class to measure elapsed time """
+    def __init__(self):
+        self._start_time = None
+        self._end_time = None
+
+    def start(self):
+        """ Start the timer """
+        self._start_time = datetime.datetime.now()
+
+    def stop(self):
+        """ Stop the timer """
+        self._end_time = datetime.datetime.now()
+
+    @property
+    def start_time(self):
+        """ Return the start time """
+        return self._start_time
+
+    @property
+    def end_time(self):
+        """ Return the end time """
+        return self._end_time
+
+    @property
+    def start_time_string(self):
+        """ use isoformat for the start time """
+        return self._start_time.isoformat()
+
+    @property
+    def end_time_string(self):
+        """ use isoformat for the end time """
+        return self._end_time.isoformat()
+
+    @property
+    def elapsed_time(self):
+        """ Return the elapsed time """
+        return (self._end_time - self._start_time).seconds