Merge pull request #16393 from edx/noraiz/EDUCATOR-1652

EDUCATOR-1652 - add logs to time frame course listing

cms/djangoapps/contentstore/views/course.py

@@ -497,15 +497,26 @@ def course_listing(request):
     """
     List all courses available to the logged in user
     """
+    def _execute_method_and_log_time(func, *args):
+        """
+        Call func passed in method with logging the time it took to complete.
+        Logging is temporary, we will remove this once we get required information.
+        """
+        start_time = time.time()
+        output = func(*args)
+        log.info('[%s] completed in [%f]', func.__name__, (time.time() - start_time))
+        return output
+
     optimization_enabled = GlobalStaff().has_user(request.user) and \
         WaffleSwitchNamespace(name=WAFFLE_NAMESPACE).is_enabled(u'enable_global_staff_optimization')
 
     org = request.GET.get('org', '') if optimization_enabled else None
-    start_time = time.time()
-    courses_iter, in_process_course_actions = get_courses_accessible_to_user(request, org)
-    log.info('get_courses_accessible_to_user completed in [%f]', (time.time() - start_time))
+    courses_iter, in_process_course_actions = _execute_method_and_log_time(get_courses_accessible_to_user, request, org)
     user = request.user
-    libraries = _accessible_libraries_iter(request.user, org) if LIBRARIES_ENABLED else []
+
+    libraries = []
+    if LIBRARIES_ENABLED:
+        libraries = _execute_method_and_log_time(_accessible_libraries_iter, request.user, org)
 
     def format_in_process_course_view(uca):
         """
@@ -542,24 +553,35 @@ def course_listing(request):
         }
 
     split_archived = settings.FEATURES.get(u'ENABLE_SEPARATE_ARCHIVED_COURSES', False)
-    active_courses, archived_courses = _process_courses_list(courses_iter, in_process_course_actions, split_archived)
+    active_courses, archived_courses = _execute_method_and_log_time(
+        _process_courses_list,
+        courses_iter,
+        in_process_course_actions,
+        split_archived
+    )
     in_process_course_actions = [format_in_process_course_view(uca) for uca in in_process_course_actions]
 
-    return render_to_response(u'index.html', {
-        u'courses': active_courses,
-        u'archived_courses': archived_courses,
-        u'in_process_course_actions': in_process_course_actions,
-        u'libraries_enabled': LIBRARIES_ENABLED,
-        u'libraries': [format_library_for_view(lib) for lib in libraries],
-        u'show_new_library_button': get_library_creator_status(user),
-        u'user': user,
-        u'request_course_creator_url': reverse(u'contentstore.views.request_course_creator'),
-        u'course_creator_status': _get_course_creator_status(user),
-        u'rerun_creator_status': GlobalStaff().has_user(user),
-        u'allow_unicode_course_id': settings.FEATURES.get(u'ALLOW_UNICODE_COURSE_ID', False),
-        u'allow_course_reruns': settings.FEATURES.get(u'ALLOW_COURSE_RERUNS', True),
-        u'optimization_enabled': optimization_enabled
-    })
+    response = _execute_method_and_log_time(
+        render_to_response,
+        u'index.html',
+        {
+            u'courses': active_courses,
+            u'archived_courses': archived_courses,
+            u'in_process_course_actions': in_process_course_actions,
+            u'libraries_enabled': LIBRARIES_ENABLED,
+            u'libraries': [format_library_for_view(lib) for lib in libraries],
+            u'show_new_library_button': get_library_creator_status(user),
+            u'user': user,
+            u'request_course_creator_url': reverse(u'contentstore.views.request_course_creator'),
+            u'course_creator_status': _get_course_creator_status(user),
+            u'rerun_creator_status': GlobalStaff().has_user(user),
+            u'allow_unicode_course_id': settings.FEATURES.get(u'ALLOW_UNICODE_COURSE_ID', False),
+            u'allow_course_reruns': settings.FEATURES.get(u'ALLOW_COURSE_RERUNS', True),
+            u'optimization_enabled': optimization_enabled
+        }
+    )
+
+    return response
 
 
 def _get_rerun_link_for_item(course_key):
@@ -670,9 +692,7 @@ def get_courses_accessible_to_user(request, org=None):
         courses, in_process_course_actions = _accessible_courses_summary_iter(request, org)
     else:
         try:
-            start_time = time.time()
             courses, in_process_course_actions = _accessible_courses_list_from_groups(request)
-            log.info('_accessible_courses_list_from_groups completed in [%f]', (time.time() - start_time))
         except AccessListFallback:
             # user have some old groups or there was some error getting courses from django groups
             # so fallback to iterating through all courses

common/lib/xmodule/xmodule/modulestore/split_mongo/split.py

@@ -514,7 +514,6 @@ class SplitBulkWriteMixin(BulkOperationsMixin):
             org_target,
             course_keys=course_keys)
 
-        start_time = time.time()
         indexes = self._add_indexes_from_active_records(
             indexes,
             branch,
@@ -522,7 +521,6 @@ class SplitBulkWriteMixin(BulkOperationsMixin):
             org_target,
             course_keys=course_keys
         )
-        log.info('Active records traversed in [%f]', (time.time() - start_time))
 
         return indexes
 
@@ -947,14 +945,12 @@ class SplitMongoModuleStore(SplitBulkWriteMixin, ModuleStoreWriteBase):
         from the course_indexes.
 
         """
-        start_time = time.time()
         matching_indexes = self.find_matching_course_indexes(
             branch,
             search_targets=None,
             org_target=kwargs.get('org'),
             course_keys=kwargs.get('course_keys')
         )
-        log.info('Matching indexes fetched in [%f]', (time.time() - start_time))
 
         # collect ids and then query for those
         version_guids = []