(don't merge) extensive time logs for EdraakCourseListView

common/djangoapps/enrollment/__init__.py

@@ -1,3 +1,19 @@
 """
 Enrollment API helpers and settings
 """
+import timeit
+import logging
+from contextlib import contextmanager
+
+log = logging.getLogger(__name__)
+
+
+@contextmanager
+def time_block(name, level):
+    start_time = timeit.default_timer()
+    log.info('%s edraak_time_block: %s [start]', level * ' >>', name)
+    try:
+        yield
+    finally:
+        diff = timeit.default_timer() - start_time
+        log.info('%s edraak_time_block: %s [end: %s ms]', level * ' >>', name, diff * 1000)

common/djangoapps/enrollment/data.py

@@ -45,34 +45,39 @@ def get_course_enrollments(user_id):
         A serializable list of dictionaries of all aggregated enrollment data for a user.
 
     """
-    qset = CourseEnrollment.objects.filter(
-        user__username=user_id,
-        is_active=True
-    ).order_by('created')
-
-    # Edraak: use EdraakCourseEnrollmentSerializer instead of CourseEnrollmentSerializer
-    enrollments = EdraakCourseEnrollmentSerializer(
-        qset,
-        many=True,
-        context={'request': get_request_or_stub()}
-    ).data
+    from . import time_block
+
+    with time_block('CourseEnrollment_query', 2):
+        qset = CourseEnrollment.objects.filter(
+            user__username=user_id,  # TODO: Omar user_id is not username
+            is_active=True
+        ).order_by('created')
+
+    with time_block('EdraakCourseEnrollmentSerializer', 2):
+        # Edraak: use EdraakCourseEnrollmentSerializer instead of CourseEnrollmentSerializer
+        enrollments = EdraakCourseEnrollmentSerializer(
+            qset,
+            many=True,
+            context={'request': get_request_or_stub()}
+        ).data
 
-    # Find deleted courses and filter them out of the results
-    deleted = []
-    valid = []
-    for enrollment in enrollments:
-        if enrollment.get("course_details") is not None:
-            valid.append(enrollment)
-        else:
-            deleted.append(enrollment)
-
-    if deleted:
-        log.warning(
-            (
-                u"Course enrollments for user %s reference "
-                u"courses that do not exist (this can occur if a course is deleted)."
-            ), user_id,
-        )
+    with time_block('append_enrollments', 2):
+        # Find deleted courses and filter them out of the results
+        deleted = []
+        valid = []
+        for enrollment in enrollments:
+            if enrollment.get("course_details") is not None:
+                valid.append(enrollment)
+            else:
+                deleted.append(enrollment)
+
+        if deleted:
+            log.warning(
+                (
+                    u"Course enrollments for user %s reference "
+                    u"courses that do not exist (this can occur if a course is deleted)."
+                ), user_id,
+            )
 
     return valid
 

common/djangoapps/enrollment/serializers.py

@@ -114,17 +114,26 @@ class EdraakCourseEnrollmentSerializer(CourseEnrollmentSerializer):
     is_completed = serializers.SerializerMethodField()
     is_certificate_available = serializers.SerializerMethodField()
 
+    def to_representation(self, *args, **kwargs):
+        from . import time_block
+        with time_block('to_representation', 3):
+            result = super(EdraakCourseEnrollmentSerializer, self).to_representation(*args, **kwargs)
+        return result
+
     def get_edraak_course_details(self, obj):
-        context = self.context.copy()
-        CourseDetailMarketingSerializer.update_marketing_context(
-            context=context,
-            course_key=obj.course_id
-        )
+        from . import time_block
+        with time_block('get_edraak_course_details', 4):
+            context = self.context.copy()
+            CourseDetailMarketingSerializer.update_marketing_context(
+                context=context,
+                course_key=obj.course_id
+            )
 
-        return CourseDetailMarketingSerializer(
-            obj.course_overview,
-            context=context
-        ).data
+            data = CourseDetailMarketingSerializer(
+                obj.course_overview,
+                context=context
+            ).data
+        return data
 
     def _get_user(self):
         request = self.context.get('request')
@@ -133,70 +142,81 @@ def _get_user(self):
         return None
 
     def get_is_certificate_allowed(self, obj):
-        # Keep this import local to hide LMS related stuff from pytest when testing CMS
-        from edraak_certificates.utils import is_certificate_allowed
-
-        user = self._get_user()
-        if user:
-            allowed = obj.course_overview and is_certificate_allowed(user, obj.course_overview)
-        else:
-            log.warning(
-                'EDRAAK: Certificate is not allowed because EdraakCourseEnrollmentSerializer cannot find user!'
-            )
-            allowed = False
-
+        from . import time_block
+        with time_block('get_is_certificate_allowed', 4):
+            # Keep this import local to hide LMS related stuff from pytest when testing CMS
+            from edraak_certificates.utils import is_certificate_allowed
+
+            user = self._get_user()
+            if user:
+                allowed = obj.course_overview and is_certificate_allowed(user, obj.course_overview)
+            else:
+                log.warning(
+                    'EDRAAK: Certificate is not allowed because EdraakCourseEnrollmentSerializer cannot find user!'
+                )
+                allowed = False
         return allowed
 
     def get_specialization_slug(self, obj):
-        try:
-            specialization_info = CourseSpecializationInfo.objects.get(course_id=obj.course_id)
-        except CourseSpecializationInfo.DoesNotExist:
-            return None
+        from . import time_block
+        with time_block('get_specialization_slug', 4):
+            try:
+                specialization_info = CourseSpecializationInfo.objects.get(course_id=obj.course_id)
+            except CourseSpecializationInfo.DoesNotExist:
+                return None
+
         return specialization_info.specialization_slug
 
     def get_subscribed_to_emails(self, obj):
-        user = self._get_user()
-        if not user or not user.is_authenticated:
-            return False
+        from . import time_block
+        with time_block('get_subscribed_to_emails', 4):
+            user = self._get_user()
+            if not user or not user.is_authenticated:
+                return False
 
-        return not Optout.objects.filter(user=user, course_id=obj.course_id).exists()
+            result = not Optout.objects.filter(user=user, course_id=obj.course_id).exists()
+        return result
 
     def get_is_completed(self, obj):
-        # Keep this import local to hide LMS related stuff from pytest when testing CMS
-        from lms.djangoapps.grades.models import PersistentCourseGrade
-
-        user = self._get_user()
-        completed = False
-        if user:
-            try:
-                grade = PersistentCourseGrade.objects.get(
-                    user_id=user.id,
-                    course_id=obj.course_id,
-                )
-            except PersistentCourseGrade.DoesNotExist:
-                pass
-            else:
-                if grade.percent_grade >= obj.course_overview.lowest_passing_grade:
-                    completed = True
+        from . import time_block
+        with time_block('get_is_completed', 4):
+            # Keep this import local to hide LMS related stuff from pytest when testing CMS
+            from lms.djangoapps.grades.models import PersistentCourseGrade
+
+            user = self._get_user()
+            completed = False
+            if user:
+                try:
+                    grade = PersistentCourseGrade.objects.get(
+                        user_id=user.id,
+                        course_id=obj.course_id,
+                    )
+                except PersistentCourseGrade.DoesNotExist:
+                    pass
+                else:
+                    if grade.percent_grade >= obj.course_overview.lowest_passing_grade:
+                        completed = True
         return completed
 
     def get_is_certificate_available(self, obj):
-        # Keep this import local to hide LMS related stuff from pytest when testing CMS
-        from lms.djangoapps.certificates.models import CertificateStatuses, GeneratedCertificate
-
-        user = self._get_user()
-        available = False
-        if user:
-            try:
-                _ = GeneratedCertificate.objects.get(
-                    user_id=user.id,
-                    course_id=obj.course_id,
-                    status__in=[CertificateStatuses.downloadable, CertificateStatuses.error],
-                )
-            except GeneratedCertificate.DoesNotExist:
-                pass
-            else:
-                available = True
+        from . import time_block
+        with time_block('get_is_certificate_available', 4):
+            # Keep this import local to hide LMS related stuff from pytest when testing CMS
+            from lms.djangoapps.certificates.models import CertificateStatuses, GeneratedCertificate
+
+            user = self._get_user()
+            available = False
+            if user:
+                try:
+                    _ = GeneratedCertificate.objects.get(
+                        user_id=user.id,
+                        course_id=obj.course_id,
+                        status__in=[CertificateStatuses.downloadable, CertificateStatuses.error],
+                    )
+                except GeneratedCertificate.DoesNotExist:
+                    pass
+                else:
+                    available = True
         return available
 
     class Meta(object):

common/djangoapps/enrollment/views.py

@@ -788,6 +788,8 @@ def post(self, request):
                 )
 
 
+
+
 @can_disable_rate_limit
 class EdraakCourseListView(APIView, ApiKeyPermissionMixIn):
     """
@@ -815,33 +817,35 @@ def get(self, request):
         Example: api/enrollment/v1/edraak_course_list?is_completed=true
             get all enrollments for current user, where courses are completed, regardless of certificate status
         """
-        try:
-            enrollment_data = get_course_enrollments(
-                request.user.username
-            )
-        except CourseEnrollmentError:
-            return Response(
-                status=status.HTTP_400_BAD_REQUEST,
-                data={
-                    "message": (
-                        u"An error occurred while retrieving enrollments for user '{username}'"
-                    ).format(username=request.user.username)
-                }
-            )
-
-        filters = {}
-        try:
-            for parameter_name in ('is_certificate_allowed', 'is_certificate_available', 'is_completed',):
-                self._add_filter(filters=filters, request=request, parameter_name=parameter_name)
-        except ValueError as error:
-            return Response(
-                status=status.HTTP_400_BAD_REQUEST,
-                data={"message": six.text_type(error)}
-            )
-
-        final_data = [enrollment for enrollment in enrollment_data if self._is_enrollment_match(filters, enrollment)]
-
-        return Response(final_data)
+        from . import time_block
+        with time_block('GET_EdraakCourseListView', 0):
+            with time_block('get_course_enrollments', 1):
+                try:
+                    enrollment_data = get_course_enrollments(
+                        request.user.username
+                    )
+                except CourseEnrollmentError:
+                    return Response(
+                        status=status.HTTP_400_BAD_REQUEST,
+                        data={
+                            "message": (
+                                u"An error occurred while retrieving enrollments for user '{username}'"
+                            ).format(username=request.user.username)
+                        }
+                    )
+            filters = {}
+            try:
+                for parameter_name in ('is_certificate_allowed', 'is_certificate_available', 'is_completed',):
+                    self._add_filter(filters=filters, request=request, parameter_name=parameter_name)
+            except ValueError as error:
+                return Response(
+                    status=status.HTTP_400_BAD_REQUEST,
+                    data={"message": six.text_type(error)}
+                )
+            with time_block('api_filtering', 1):
+                final_data = [enrollment for enrollment in enrollment_data if self._is_enrollment_match(filters, enrollment)]
+            response = Response(final_data)
+        return response
 
     def _add_filter(self, filters, request, parameter_name):
         parameter_value = self._get_boolean(request=request, param=parameter_name)

lms/djangoapps/course_api/helpers.py

@@ -51,19 +51,22 @@ def get_marketing_data(course_key, language):
     :returns a course details from the marketing API or None if
     no marketing details found.
     """
+    from enrollment import time_block
     CACHE_KEY = "MKTG_API_" + str(course_key) + str(language)
-    if cache.get(CACHE_KEY):
-        return cache.get(CACHE_KEY)
-    marketing_root_format = marketing_link('COURSE_DETAILS_API_FORMAT')
-    url = marketing_root_format.format(course_id=course_key)
-
-    response = requests.get(url=url, headers={
-        'Accept-Language': language,
-    })
-
-    if response.status_code != 200:
-        log.warning('Could not fetch the marketing details from the API. course_key=[%s], status_code=[%s], url=[%s].',
-                    course_key, response.status_code, url)
-        return {}
-    cache.set(CACHE_KEY, response.json(), 30 * 60)
-    return response.json()
+    with time_block(CACHE_KEY, 5):
+        if cache.get(CACHE_KEY):
+            return cache.get(CACHE_KEY)
+        marketing_root_format = marketing_link('COURSE_DETAILS_API_FORMAT')
+        url = marketing_root_format.format(course_id=course_key)
+
+        response = requests.get(url=url, headers={
+            'Accept-Language': language,
+        })
+
+        if response.status_code != 200:
+            log.warning('Could not fetch the marketing details from the API. course_key=[%s], status_code=[%s], url=[%s].',
+                        course_key, response.status_code, url)
+            return {}
+        cache.set(CACHE_KEY, response.json(), 30 * 60)
+        response_json = response.json() 
+    return response_json