Merge pull request #13985 from edx/cdyer/grade-latency

Track grading task latency

lms/djangoapps/grades/signals/handlers.py

@@ -123,7 +123,7 @@ def enqueue_subsection_update(sender, **kwargs):  # pylint: disable=unused-argum
     """
     Handles the PROBLEM_SCORE_CHANGED signal by enqueueing a subsection update operation to occur asynchronously.
     """
-    recalculate_subsection_grade.apply_async(
+    result = recalculate_subsection_grade.apply_async(
         kwargs=dict(
             user_id=kwargs['user_id'],
             course_id=kwargs['course_id'],
@@ -134,6 +134,12 @@ def enqueue_subsection_update(sender, **kwargs):  # pylint: disable=unused-argum
             score_deleted=kwargs.get('score_deleted', False),
         )
     )
+    log.info(
+        u'Grades: Request async calculation of subsection grades with args: {}. Task [{}]'.format(
+            ', '.join('{}:{}'.format(arg, kwargs[arg]) for arg in sorted(kwargs)),
+            getattr(result, 'id', 'N/A'),
+        )
+    )
 
 
 @receiver(SUBSECTION_SCORE_CHANGED)

lms/djangoapps/grades/tests/test_signals.py

@@ -2,15 +2,19 @@
 Tests for the score change signals defined in the courseware models module.
 """
 
+import re
+
 import ddt
 from django.test import TestCase
 from mock import patch, MagicMock
 
 from ..signals.handlers import (
+    enqueue_subsection_update,
     submissions_score_set_handler,
     submissions_score_reset_handler,
 )
 
+UUID_REGEX = re.compile(ur'%(hex)s{8}-%(hex)s{4}-%(hex)s{4}-%(hex)s{4}-%(hex)s{12}' % {'hex': u'[0-9a-f]'})
 
 SUBMISSION_SET_KWARGS = {
     'points_possible': 10,
@@ -117,3 +121,22 @@ class SubmissionSignalRelayTest(TestCase):
         self.get_user_mock = self.setup_patch('lms.djangoapps.grades.signals.handlers.user_by_anonymous_id', None)
         handler(None, **kwargs)
         self.signal_mock.assert_not_called()
+
+    @patch('lms.djangoapps.grades.signals.handlers.log.info')
+    def test_problem_score_changed_logging(self, mocklog):
+        enqueue_subsection_update(
+            sender='test',
+            user_id=1,
+            course_id=u'course-v1:edX+Demo_Course+DemoX',
+            usage_id=u'block-v1:block-key',
+        )
+        log_statement = mocklog.call_args[0][0]
+        log_statement = UUID_REGEX.sub(u'*UUID*', log_statement)
+        self.assertEqual(
+            log_statement,
+            (
+                u'Grades: Request async calculation of subsection grades with args: '
+                u'course_id:course-v1:edX+Demo_Course+DemoX, usage_id:block-v1:block-key, '
+                u'user_id:1. Task [*UUID*]'
+            )
+        )