diff --git a/search/api.py b/search/api.py index a8a331e7..fde7010d 100644 --- a/search/api.py +++ b/search/api.py @@ -1,15 +1,13 @@ """ search business logic implementations """ from datetime import datetime -import time - 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"] @@ -54,14 +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_time = { - "start": time.time() - } + 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_time['end'] = time.time() + filter_generation_timer.stop() searcher = SearchEngine.get_search_engine( getattr(settings, "COURSEWARE_CONTENT_INDEX_NAME", "courseware_content") @@ -70,9 +67,8 @@ 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_time = { - "start": time.time() - } + search_timer = Timer() + search_timer.start() results = searcher.search( query_string=search_term, @@ -84,9 +80,8 @@ def perform_search( log_search_params=log_search_params, ) - processing_time = { - "start": time.time() - } + processing_timer = Timer() + processing_timer.start() # post-process the result for result in results["results"]: @@ -95,20 +90,36 @@ def perform_search( 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_time['end'] = time.time() - search_time['end'] = time.time() + processing_timer.stop() + search_timer.stop() - processing_time_in_seconds = processing_time['end'] - processing_time['start'] - search_time_in_seconds = search_time['end'] - search_time['start'] - filter_generation_time_in_seconds = filter_generation_time['end'] - filter_generation_time['start'] + 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, - "processing_time_in_seconds": processing_time_in_seconds, - "search_time_in_seconds": search_time_in_seconds, - "filter_generation_time_in_seconds": filter_generation_time_in_seconds, + "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, + }, }) - return results def course_discovery_search(search_term=None, size=20, from_=0, field_dictionary=None): diff --git a/search/tests/test_api_timing_events.py b/search/tests/test_api_timing_events.py new file mode 100644 index 00000000..1c11347e --- /dev/null +++ b/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) diff --git a/search/utils.py b/search/utils.py index a5b4a424..ded4a759 100644 --- a/search/utils.py +++ b/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