🧪 Profile live statistics page (#5365)

Adds a sort of profiling to this page by placing some timers in some key function where I think the slowdown happens. Why is it so hacky? I tried for several hours to use werkzeug's `ProfilerMiddleware` but I think there's a bug with the implementation, as several people have reported in some other tools: django-commons/django-debug-toolbar#1875, jazzband/django-silk#682

I thought that since we didn't need the full-fledged tool and didn't want to spend more time on this, this approach would suffice.

website/statistics.py

@@ -14,11 +14,18 @@
 from website.flask_helpers import render_template
 from website import querylog
 from website.auth import is_admin, is_teacher, requires_admin, requires_login
-
+from timeit import default_timer as timer
 from .database import Database
 from .website_module import WebsiteModule, route
 from bs4 import BeautifulSoup
 
+import logging
+from logging_config import LOGGING_CONFIG
+from logging.config import dictConfig as logConfig
+
+logConfig(LOGGING_CONFIG)
+logger = logging.getLogger(__name__)
+
 """The Key tuple is used to aggregate the raw data by level, time or username."""
 Key = namedtuple("Key", ["name", "class_"])
 level_key = Key("level", int)
@@ -335,8 +342,11 @@ def __init__(self, db: Database):
         self.MAX_FEED_SIZE = 4
 
     def __selected_levels(self, class_id):
+        start = timer()
         class_customization = get_customizations(self.db, class_id)
         class_overview = class_customization.get('dashboard_customization')
+        end = timer()
+        logger.debug(f'Time taken by __selected_levels {end-start}')
         if class_overview:
             return class_overview.get('selected_levels', [1])
         return [1]
@@ -349,6 +359,7 @@ def __common_errors(self, class_id):
 
     def __all_students(self, class_):
         """Returns a list of all students in a class along with some info."""
+        start = timer()
         students = []
         for student_username in class_.get("students", []):
             programs = self.db.programs_for_user(student_username)
@@ -365,6 +376,8 @@ def __all_students(self, class_):
                     "current_level": programs[0]['level'] if programs else '0'
                 }
             )
+        end = timer()
+        logger.debug(f'Time taken by __all_students {end-start}')
         return students
 
     def __get_adventures_for_overview(self, user, class_id):
@@ -440,6 +453,7 @@ def render_live_stats(self, user, class_id):
         )
 
     def get_class_live_stats(self, user, class_):
+        start = timer()
         # Retrieve common errors and selected levels in class overview from the database for class
         selected_levels = self.__selected_levels(class_['id'])
         if selected_levels:
@@ -476,7 +490,8 @@ def get_class_live_stats(self, user, class_):
                     programs_for_student[_student] = adventures_for_student
             if programs_for_student != []:
                 attempted_adventures[level] = programs_for_student
-
+        end = timer()
+        logger.debug(f'Time taken by get_class_live_stats {end-start}')
         return students, common_errors, selected_levels, quiz_info, attempted_adventures, adventures
 
     @route("/live_stats/class/<class_id>/select_level", methods=["GET"])
@@ -810,6 +825,7 @@ def retrieve_exceptions_per_student(self, class_id):
         :param class_id: class id
         :return: exceptions_per_user
         """
+        start = timer()
         class_ = self.db.get_class(class_id)
         exceptions_per_user = {}
         students = sorted(class_.get("students", []))
@@ -820,7 +836,8 @@ def retrieve_exceptions_per_student(self, class_id):
                 program_stats = program_stats[-1]
                 exceptions = {k: v for k, v in program_stats.items() if k.lower().endswith("exception")}
                 exceptions_per_user[student_username] = exceptions
-
+        end = timer()
+        logger.debug(f'Tike taken by retrieve_exceptions_per_student {end-start}')
         return exceptions_per_user
 
     def new_id_calc(self, common_errors, class_id):
@@ -856,6 +873,7 @@ def common_exception_detection(self, class_id, user):
         """
         Detects misconceptions of students in the class based on errors they are making.
         """
+        start = timer()
         common_errors = self.__common_errors(class_id)
         # Group the error messages by session and count their occurrences
         exceptions_per_user = self.retrieve_exceptions_per_student(class_id)  # retrieves relevant data from db
@@ -913,7 +931,8 @@ def common_exception_detection(self, class_id, user):
                     'active': 1,
                     "students": users_only
                 })
-
+        end = timer()
+        logger.debug(f'Time taken by common_exception_detection {end-start}')
         return self.db.update_class_errors(common_errors)
 
     @route("/live_stats/class/<class_id>", methods=["POST"])