Adding more timing logs as course-rerun is slow for mitx-7.00x

cms/djangoapps/api/v1/serializers/course_runs.py

@@ -177,19 +177,6 @@ class CourseRunRerunSerializer(CourseRunSerializerCommonFieldsMixin, CourseRunTe
         return value
 
     def update(self, instance, validated_data):
-        def _execute_method_and_log_time(func, *args):
-            """
-            Call func passed in method with logging the time it took to complete.
-            Temporarily added for EDUCATOR-4013, we will remove this once we get the required information.
-            """
-            course_run_key = args[1]
-            if 'MITx+7.00x' not in unicode(course_run_key):
-                return func(*args)
-            start_time = time.time()
-            output = func(*args)
-            log.info(u'[%s] [%s] completed in [%f]', func.__name__, course_run_key, (time.time() - start_time))
-            return output
-
         course_run_key = instance.id
         _id = validated_data.pop('id')
         team = validated_data.pop('team', [])
@@ -198,15 +185,8 @@ class CourseRunRerunSerializer(CourseRunSerializerCommonFieldsMixin, CourseRunTe
             'display_name': instance.display_name
         }
         fields.update(validated_data)
-        new_course_run_key = _execute_method_and_log_time(
-            rerun_course,
-            user,
-            course_run_key,
-            course_run_key.org,
-            course_run_key.course,
-            _id['run'],
-            fields,
-            False
+        new_course_run_key = rerun_course(
+            user, course_run_key, course_run_key.org, course_run_key.course, _id['run'], fields, False
         )
 
         course_run = get_course_and_check_access(new_course_run_key, user)

cms/djangoapps/contentstore/tasks.py

@@ -38,7 +38,7 @@ from user_tasks.tasks import UserTask
 
 from contentstore.courseware_index import CoursewareSearchIndexer, LibrarySearchIndexer, SearchIndexingError
 from contentstore.storage import course_import_export_storage
-from contentstore.utils import initialize_permissions, reverse_usage_url
+from contentstore.utils import initialize_permissions, reverse_usage_url, execute_and_log_time
 from contentstore.video_utils import scrape_youtube_thumbnail
 from course_action_state.models import CourseRerunState
 from models.settings.course_metadata import CourseMetadata
@@ -458,16 +458,18 @@ def rerun_course(source_course_key_string, destination_course_key_string, user_i
         # as the Mongo modulestore doesn't support multiple runs of the same course.
         store = modulestore()
         with store.default_store('split'):
-            store.clone_course(source_course_key, destination_course_key, user_id, fields=fields)
+            execute_and_log_time(
+                store.clone_course, source_course_key, destination_course_key, user_id, fields=fields
+            )
 
         # set initial permissions for the user to access the course.
-        initialize_permissions(destination_course_key, User.objects.get(id=user_id))
+        execute_and_log_time(initialize_permissions, destination_course_key, User.objects.get(id=user_id))
 
         # update state: Succeeded
         CourseRerunState.objects.succeeded(course_key=destination_course_key)
 
         # call edxval to attach videos to the rerun
-        copy_course_videos(source_course_key, destination_course_key)
+        execute_and_log_time(copy_course_videos, source_course_key, destination_course_key)
 
         # Copy OrganizationCourse
         organization_course = OrganizationCourse.objects.filter(course_id=source_course_key_string).first()
@@ -475,14 +477,7 @@ def rerun_course(source_course_key_string, destination_course_key_string, user_i
         if organization_course:
             clone_instance(organization_course, {'course_id': destination_course_key_string})
 
-        # Copy RestrictedCourse
-        restricted_course = RestrictedCourse.objects.filter(course_key=source_course_key).first()
-
-        if restricted_course:
-            country_access_rules = CountryAccessRule.objects.filter(restricted_course=restricted_course)
-            new_restricted_course = clone_instance(restricted_course, {'course_key': destination_course_key})
-            for country_access_rule in country_access_rules:
-                clone_instance(country_access_rule, {'restricted_course': new_restricted_course})
+        execute_and_log_time(add_course_restrictions, source_course_key, destination_course_key)
 
         return "succeeded"
 
@@ -508,6 +503,17 @@ def rerun_course(source_course_key_string, destination_course_key_string, user_i
         return u"exception: " + text_type(exc)
 
 
+def add_course_restrictions(source_course_key, destination_course_key):
+    """Adds course restrictions"""
+    restricted_course = RestrictedCourse.objects.filter(course_key=source_course_key).first()
+
+    if restricted_course:
+        country_access_rules = CountryAccessRule.objects.filter(restricted_course=restricted_course)
+        new_restricted_course = clone_instance(restricted_course, {'course_key': destination_course_key})
+        for country_access_rule in country_access_rules:
+            clone_instance(country_access_rule, {'restricted_course': new_restricted_course})
+
+
 def deserialize_fields(json_fields):
     fields = json.loads(json_fields)
     for field_name, value in iteritems(fields):

cms/djangoapps/contentstore/utils.py

@@ -4,6 +4,7 @@ Common utility functions useful throughout the contentstore
 from __future__ import print_function
 
 import logging
+import time
 from datetime import datetime
 
 from django.conf import settings
@@ -517,3 +518,18 @@ def is_self_paced(course):
     Returns True if course is self-paced, False otherwise.
     """
     return course and course.self_paced
+
+
+def execute_and_log_time(func, *args, **kwargs):
+    """
+    Call func passed in method with logging the time it took to complete.
+    Temporarily added for EDUCATOR-4013, we will remove this once we get the required information.
+    """
+    course_key = args[1]
+    start_time = time.time()
+    output = func(*args, **kwargs)
+    if 'MITx+7.00x' in unicode(course_key):
+        log.info(
+            u'Execution time for [%s] [%s] completed in [%f]',
+            func.__name__, course_key, (time.time() - start_time))
+    return output